[2.9] Weird scrolling in, for example Firefox

[AlanGriffiths]

1. Start firefox/Wayland on a webpage large enough to scroll
2. Use the scroll wheel to scroll up or down

Expect: can scroll to the top and bottom
Actual: scrolling stops before reaching the top/bottom

Observation: on the first scroll event in the opposite direction the scrolling does reach the top/bottom. This was obvious when tracking the events in a terminal window with:

WAYLAND_DEBUG=client firefox 2>&1 | grep axis_discrete

This is intermittent, but seems consistent within a run of a Mir server. Restarting the server "rolls the dice" again with around a 65% chance of seeing problems.

[AlanGriffiths]

Comparing with Mutter, there's a slight difference in the order of wl_pointer events within the frame, but empirically changing the order has no effect. (Which is obviously how it should be.)

[wmww]

I had to do some work on wayland-debug, but eventually I was able to get a nice clean event stream.

My observations:

• I've analyzed diffs of protcol messages between the good and bad runs. Nothing stands out
• I often see it on Mir-on-X, but never with libinput. Saviq reports seeing it in a Miriway session, presumably on libinput
• Looking at how FF is acting, it appears that events are arriving late. This would explain both the wrong direction scrolls, and the lack of smooth scrolling (if FF notices it's processing events late, maybe it doesn't let them animate?)
• One possibility is something is wrong with the timestamps? Just speculation

[wmww]

Oh, I should upload the logs I got in case that's helpful. They're from a patched libwayland so if you wanted to use wayland-debug to analyze these you'd have to use this branch.

ff-bad-scroll.log
ff-good-scroll.log

[AlanGriffiths]

Sorry for the lack of clarity, this was first observed on gbm-kms/libwayland. That you also see it on the X11 backend is interesting as that doesn't do the discrete/valeu120 stuff (yet).

I don't think the events are arriving significantly late, watching them logged on the client side (as described above) it seem more that the client is responding to the previous event, not that the previous event arrive late.

Anyway, thanks for the observations they all help towards identifying the problem!

[AlanGriffiths]

Actually, obviously it isn't as simple as "respond to the previous event" as there can be multiple idempotent "down" events before an "up" causes the fully scrolled content to paint.

[AlanGriffiths]

Some further observations:

1. This problem also exists in Mir 2.8 (tested with egmde/stable)
2. It isn't "consistent within a run of a Mir server", it comes and goes even within a run of Firefox
3. Scrolling from the touchpad works fine

[wmww]

It appears it does seem to be related to timestamps. Specifically, I can trigger it reliably on all platforms by adding 100ms to the timestamp returned by mir_input_event_get_wayland_timestamp(). Returning the current std::chrono::steady_clock time fixes the problem (though probably isn't what we want to do).

Subtracting 100ms fixes the jank, but also makes smooth scrolling jump a little bit. Subtracting 500ms entirely disables smooth scrolling. From this data I conclude that Firefox is (probably accidentally) assuming the timestamps it's getting match it's internal clock in the smooth scrolling animation code.

[wmww]

Oh, the reason you might not be seeing this on the X11 platform but I have been is that I've been testing with #2579. Without that, all X11 scroll events are seen as non-discrete.

[wmww]

I think I have a pretty clear idea what's going on now. Platforms send events with timestamps. Mir also sends timestamps (for example in the frame done event). Mir wants to pass on the timestamps from the platform because, for example, a client might want to calculate how long a click was, even if one of the events got slowed down before Mir saw it. Mir doesn't want to trust the the platform (and presumably underlying library like libinput and XCB) are using the same timestamp base as Mir itself.

To solve this problem, the first time a DefaultEventBuilder sees a timestamp it records it's offset from Mir's current time. It then applies that offset to all future events.

The problem is that often the first few events are delayed in transit, but after that they arrive in a timely manor. This causes Mir to register the first few events as the correct time, and subsequent events as coming from the future. We forward these future events to Firefox, Firefox tries to use future times as a basis for it's animation code, weird results ensue.

There's a few possibilities as to how to fix it. In practice, everything seems to the same timestamp base so entirely removing the calibration would fix it. We could also continually adjust the calibration every time a higher-than expected timestamp comes in, guaranteeing that no future timestamps are ever sent. We could do a hybrid approach where if the timestamps are close enough to the system's default time they're assumed to have the same base, but otherwise an offset is added. I need to do more research before having an opinion on which option is best.

[AlanGriffiths]

Thanks @wmww for tracking that down. That explanation sounds both convoluted and plausible.

If the events have timestamps why is Mir messing with them at all? Isn't the simplest thing that might work to just pass them on?

[wmww]

That is the simplest thing and it does seem to work. The problem is that since we mix in timestamps generated by Mir (and even clients in the case of the virtual pointer and keyboard protocols), we need all the timestamps to match. In practice everyone seems to be getting the same timestamps, but the problem is no one is guaranteeing they use a particular source. In the case of the virtual input device wayland protocols the base is explicitly undefined.