Bug 212338 – [WPE] Avoid possible WTR event timing going back in time and fix conversion from s to ms

• Status: RESOLVED
• Resolution: FIXED
• Component: WPE WebKit

[Lauro Moura]

WPE's EventSenderProxy stores the event time (double m_time) as the elapsed number of seconds like other ports, but the native wpe_input_*_event uses uint32_t. EventSenderProxy casts the former to the latter without adjusting neither to a "real" time (more below) nor from seconds to milliseconds (wpe_input_*_event's timing unit).

Also, when the event arrives in Source/WebKit/Shared/libwpe/WebEventFactory.cpp, WPE's implementation of wallTimeForEventTime will fallback to WallTime::now() if the timestamp is zero, using raw seconds otherwise. This can cause the WebEvents that started from zero having a WallTime in front of subsequent events that would come after a leapForward (for example, the event timestamps in fast/events/click-count.html)

[Lauro Moura]

Created attachment 400185 [details]
Patch

[Lauro Moura]

Cc'ing mcatanzaro and cdumez (from the original discussion from bug 177449).

[Carlos Garcia Campos]

Other ports don't use m_time for the events, it's only used to calculate the click count.

[Michael Catanzaro]

Comment on attachment 400185 [details]
Patch

View in context: https://bugs.webkit.org/attachment.cgi?id=400185&action=review

> Source/WebKit/Shared/libwpe/WebEventFactory.cpp:66
> +    // From wayland docs:
> +    //  Input events also carry timestamps with millisecond granularity. Their base
> +    //  is undefined, so they can't be compared against system time (as obtained
> +    //  with clock_gettime or gettimeofday). They can be compared with each other
> +    //  though, and for instance be used to identify sequences of button presses
> +    //  as double or triple clicks.

Same for X event timestamps. Anyway, I like your solution since it drops the assumption that the WPE backend (or, for GTK, the display server) is going to be using CLOCK_MONOTONIC. This is true for X11, and it's true for GNOME, and it's probably true for other Wayland compositors that exist today as well, so it's a "safe" assumption, but it's never really been correct.

I was almost going to suggest changing the GTK implementation (duplicated in GtkUtilities.h and GtkUtilities.cpp) as well, but now I see that your real problem here is the handling of 0. In GTK, 0 always represents the current time (GDK_CURRENT_TIME) and it's normal to see events using it whenever. I understand from your comment that this handling is causing trouble for WPE, but I'm not sure I entirely understand how exactly....

Probably adding a comment on Wayland is not good to do here, btw, because WPE might not be using Wayland at all. Suffice to say that the WPE timestamp is always monotonically increasing and unrelated to wall time (like X or Wayland timestamps).

> Source/WebKit/Shared/libwpe/WebEventFactory.cpp:72
> +    std::unique_lock<std::mutex> lock(m);

I would use std::call_once for this, it's nice and idiomatic. (We also have GOnce, but std::call_once is nicer in C++.)

> LayoutTests/ChangeLog:12
> +        Added new test to check if WPE input events timestamps are actually
> +        monotonically increasing since the start.
> +
> +        * platform/wpe/fast/events/monotonic-event-time-expected.txt: Added.
> +        * platform/wpe/fast/events/monotonic-event-time.html: Added.

Good test! I assume the test failed before your patch?

This test should pass on all ports though, right? I don't think it should be WPE-specific. Try putting it under toplevel fast/events and see if it passes EWS. :) We've got a problem if timestamps are jumping around on any port! (If GTK or another port fails the test, you can add an appropriate TestExpectations line in order to land it without fixing that port. But hopefully no other port will fail the test.)

[Lauro Moura]

(In reply to Michael Catanzaro from comment #4)
> Comment on attachment 400185 [details]
> Patch
> 
<snip>

> I understand from your comment that this handling is causing trouble for WPE,
> but I'm not sure I entirely understand how exactly....

The initial events (before a leapForward, for example), come with an event timestamp of 0. This caused the conversion to WallTime to return WallTime::now(). Once you leap forward, the event time becomes non-zero and would be a duration since the epoch (usually waaaaaay smaller than Now()).

For example, I hit this issue in fast/events/click-count.html after rebasing the patch from bug174674 for WPE click counting.

> Probably adding a comment on Wayland is not good to do here, btw, because
> WPE might not be using Wayland at all. Suffice to say that the WPE timestamp
> is always monotonically increasing and unrelated to wall time (like X or
> Wayland timestamps).

Right.

> 
> > Source/WebKit/Shared/libwpe/WebEventFactory.cpp:72
> > +    std::unique_lock<std::mutex> lock(m);
> 
> I would use std::call_once for this, it's nice and idiomatic. (We also have
> GOnce, but std::call_once is nicer in C++.)

TIL std::call_once :D

> 
> > LayoutTests/ChangeLog:12
> > +        Added new test to check if WPE input events timestamps are actually
> > +        monotonically increasing since the start.
> > +
> > +        * platform/wpe/fast/events/monotonic-event-time-expected.txt: Added.
> > +        * platform/wpe/fast/events/monotonic-event-time.html: Added.
> 
> Good test! I assume the test failed before your patch?

Yes, it failed before.

> 
> This test should pass on all ports though, right? I don't think it should be
> WPE-specific. Try putting it under top level fast/events and see if it passes
> EWS. :) We've got a problem if timestamps are jumping around on any port!
> (If GTK or another port fails the test, you can add an appropriate
> TestExpectations line in order to land it without fixing that port. But
> hopefully no other port will fail the test.)

That sounds good. I tested GTK here (after adding missing mouseUps to complete the click) and it worked fine. I'll submit the updated patch through CQ to test other ports.

[Lauro Moura]

Comment on attachment 400185 [details]
Patch

Found an issue with this reference timing implementation when running multiple tests. Will investigate.

[Michael Catanzaro]

(In reply to Lauro Moura from comment #5)
> The initial events (before a leapForward, for example), come with an event
> timestamp of 0. This caused the conversion to WallTime to return
> WallTime::now().

So... in WPE, we want to treat 0 as the initial time rather than the current time, and therefore we need a different conversion function that we use for GTK. Yes? Since that is the fundamental problem, it would be good to mention in your comment.

[Michael Catanzaro]

(In reply to Lauro Moura from comment #5)
> Once you leap forward, the event time becomes non-zero and
> would be a duration since the epoch (usually waaaaaay smaller than Now()).

Wait, none of the timestamps here are duration since epoch. The WPE time should be a monotonic time (or, oddly, 0... why are events using timestamp 0?) and the WebKit times are all wall times (elapsed real time).

What is "leap forward?" Changing system time should have no impact on monotonic time or wall time, right?

[Adrian Perez]

(In reply to Michael Catanzaro from comment #8)
> (In reply to Lauro Moura from comment #5)
> > Once you leap forward, the event time becomes non-zero and
> > would be a duration since the epoch (usually waaaaaay smaller than Now()).
> 
> Wait, none of the timestamps here are duration since epoch. The WPE time
> should be a monotonic time (or, oddly, 0... why are events using timestamp
> 0?) and the WebKit times are all wall times (elapsed real time).
> 
> What is "leap forward?" Changing system time should have no impact on
> monotonic time or wall time, right?

Changing the system time does NOT affect monotonic time, but DOES affect
wall time, even when it's expressed as seconds from the Epoch, because
contrary to what one may think, obtaining such a value is not just asking
the kernel “give me how many seconds have passed since the Epoch”: you
need to know the current date and time, and *then* subtract the date and
time of the Epoch from it. If the current date and time change… well, the
result of that calculation will change as well, and the “now” timestamp
for Epoch-based wall time will leap back and forth as the system clock
changes.

Now in the context of WebKit: WallTime::now() calls g_get_real_time(),
which in turn uses gettimeofday(), which is indeed affected by clock
changes—it should be using clock_gettime() but that has basically the
same problem. By the way, it's called “wall” time because if you had
a wall clock, you could look at it and write down the same timestamp.
And anybody can sneak in and change the handles of your beautiful wall
clock in between the first time and the next you look at it ¯\_(ツ)_/¯ 

TL;DR: Never ever use wall time to measure time intervals reliably,
which includes about 93.67% of the use cases of time in computing: wall
time is to *display* things to the user.

Now, after this long comment you may be left wondering: Why does the
DOM events API use wall time, then? Dunno, but clearly whoever designed
that API did not know better and now after it has been used in the wild
cannot be changed, so we are stuck with it ¬_¬

[Michael Catanzaro]

Yeah so I misunderstood what wall time was, I thought it was equivalent of 'uptime'. Of course there would be no need to have such a class, that's effectively monotonic time....

[Lauro Moura]

(In reply to Michael Catanzaro from comment #8)
> (In reply to Lauro Moura from comment #5)
> > Once you leap forward, the event time becomes non-zero and
> > would be a duration since the epoch (usually waaaaaay smaller than Now()).
> 
> Wait, none of the timestamps here are duration since epoch. The WPE time
> should be a monotonic time (or, oddly, 0... why are events using timestamp
> 0?) and the WebKit times are all wall times (elapsed real time).
> 
> What is "leap forward?" Changing system time should have no impact on
> monotonic time or wall time, right?

Sorry, leap forward in the sense of eventSender.leapForward (changing the subsequent event timestamps). Not changing the system time.

GTK's event sender proxy actually waits some time (to keep up with GDK_CURRENT_TIME usage), while Mac just stores this value, adding to the current time when converting from event timestamp to NSEvent.

[Lauro Moura]

(In reply to Adrian Perez from comment #9)
> 
> Now, after this long comment you may be left wondering: Why does the
> DOM events API use wall time, then? Dunno, but clearly whoever designed
> that API did not know better and now after it has been used in the wild
> cannot be changed, so we are stuck with it ¬_¬

DOM (in JS sense) events do not use wall time. They are DOMHighResTimeStamp [1], counted from some time origin[2].

But WebEvents in WebKit code indeed uses WallTime for the event timestamps, converting back to MonotonicTime later when creating their DOM (C) objects.

[1] https://dom.spec.whatwg.org/#ref-for-dom-event-timestamp%E2%91%A3
[2] https://w3c.github.io/hr-time/#dfn-time-origin

[Lauro Moura]

(In reply to Lauro Moura from comment #6)
> Comment on attachment 400185 [details]
> Patch
> 
> Found an issue with this reference timing implementation when running
> multiple tests. Will investigate.

So, the issue with the current iteration of the patch (just changing to call_once) happens when the same worker is used for multiple tests (Well, all the time).

In these cases, the "timeOrigin" (LoadTiming::markStartTime()) is adjusted for each navigation, advancing the "frame of reference" used by the WebProcess when converting from the internal events WallTime to the DOM Monotonic time.

Meanwhile, the event sender would start sending back events with 0 timestamp by default. In essence, the event timestamps given to wallTimeForEventTime were not monotonic.

That said, instead of initializing EventSenderProxy::m_time (not used in absolute values, but relative, like cgarcia said in #c3) with 0, initializing it with the current MonotonicTime makes the test work fine (By guaranteeing that subsequent instantiations of the EventSender by the test controller will give monotonically increasing event timestamps). Would this be reasonable or raises some flags?

[Lauro Moura]

Created attachment 400303 [details]
Updated patch initializing m_time to MonotonicTime::now

[Carlos Garcia Campos]

(In reply to Lauro Moura from comment #11)
> (In reply to Michael Catanzaro from comment #8)
> > (In reply to Lauro Moura from comment #5)
> > > Once you leap forward, the event time becomes non-zero and
> > > would be a duration since the epoch (usually waaaaaay smaller than Now()).
> > 
> > Wait, none of the timestamps here are duration since epoch. The WPE time
> > should be a monotonic time (or, oddly, 0... why are events using timestamp
> > 0?) and the WebKit times are all wall times (elapsed real time).
> > 
> > What is "leap forward?" Changing system time should have no impact on
> > monotonic time or wall time, right?
> 
> Sorry, leap forward in the sense of eventSender.leapForward (changing the
> subsequent event timestamps). Not changing the system time.
> 
> GTK's event sender proxy actually waits some time (to keep up with
> GDK_CURRENT_TIME usage), while Mac just stores this value, adding to the
> current time when converting from event timestamp to NSEvent.

Not anymore, since r262184 it behaves like other ports and the time is only used to calculate the click count.

[Michael Catanzaro]

Comment on attachment 400303 [details]
Updated patch initializing m_time to MonotonicTime::now

You'll need to add a failure expectation for iOS-wk2:

--- /Volumes/Data/worker/iOS-13-Simulator-WK2-Tests-EWS/build/layout-test-results/fast/events/monotonic-event-time-expected.txt
+++ /Volumes/Data/worker/iOS-13-Simulator-WK2-Tests-EWS/build/layout-test-results/fast/events/monotonic-event-time-actual.txt
@@ -3,10 +3,6 @@
 On success, you will see a series of "PASS" messages, followed by "TEST COMPLETE".
 
 
-PASS lastTimeStamp < event.timeStamp is true
-PASS lastTimeStamp < event.timeStamp is true
-PASS lastTimeStamp < event.timeStamp is true
-PASS lastTimeStamp < event.timeStamp is true
 PASS successfullyParsed is true
 
 TEST COMPLETE

[Lauro Moura]

Created attachment 400363 [details]
Patch for landing

Skipped in iOS altogether as it does not have mouse events.

[EWS]

Committed r262214: <https://trac.webkit.org/changeset/262214>

All reviewed patches have been landed. Closing bug and clearing flags on attachment 400363 [details].

[Lauro Moura]

There were two missing conversions making fast/events/touch/tap-highlight-color.html fail.

Committed them unreviewed in r262225.