1207412 - Mouse wheel smooth-scroll "jumps forward" every ~250ms with APZ enabled - regression from 2015-08-24

Status: RESOLVED FIXED

(Core :: DOM: Core & HTML, defect)

Description

[Avi Halachmi (:avih)]

Before this date, mouse wheel scroll was very smooth after either a single mouse wheel roll "notch" or in consecutive rolls which keep the page moving. After this date, it seems that the page "jumps" forward in the direction of scrolling every ~250ms.

This doesn't happen when scrolling with the keyboard arrows.

This is unrelated to the rate at which the mouse wheel is rolled and is noticeable either in normal configuration (where I noticed it) when rolling the mouse wheel steadily such that the page keeps moving, or in a configuration where the scroll duration is much longer such that after several quick mouse wheel roll notches the page keeps scrolling for few seconds (the video demonstrates the latter*).

Video: first scroll is after few quick mouse wheel rolls, second scroll is after few quick down-arrow presses, on both cases the input lasts ~500ms and then the page keeps scrolling on its own:
https://people.mozilla.org/~ahalachmi/share/bugs/wheel-jumps_arrows-smooth.mp4

I single-stepped the recording and found out that every 15 or 16 frames the scroll step appears bigger than what it should be.

I bisected it and came up with the following range:

> 9:36.51 LOG: MainThread Bisector INFO Last good revision: f8b3d9a3d5771e23cd99f899315831b97c774a92
> 9:36.51 LOG: MainThread Bisector INFO First bad revision: e13c23f424f664651417fffe914efa7348106249
> 9:36.51 LOG: MainThread Bisector INFO Pushlog:
> https://hg.mozilla.org/integration/mozilla-inbound/pushloghtml?fromchange=f8b3d9a3d5771e23cd99f899315831b97c774a92&tochange=e13c23f424f664651417fffe914efa7348106249

Brian, the entire range appears to be bug 1026803.


* Firefox settings in In order to let it scroll for few seconds after few quick mouse wheel roll notches or arrow-down presses:
> general.smoothScroll.lines.durationMaxMS      = 5000
> general.smoothScroll.lines.durationMinMS      = 5000
> general.smoothScroll.mouseWheel.durationMaxMS = 5000
> general.smoothScroll.mouseWheel.durationMinMS = 5000

Comment 1

[Avi Halachmi (:avih)]

(In reply to Avi Halachmi (:avih) from comment #0)
> Brian, the entire range appears to be bug 1026803.

Which is a bit weird, since I noticed this on Windows (8.1 64, Firefox 32 bits), but this bug seems to address Linux...

Comment 2

[Avi Halachmi (:avih)]

(In reply to Avi Halachmi (:avih) from comment #1)
> (In reply to Avi Halachmi (:avih) from comment #0)
> > Brian, the entire range appears to be bug 1026803.
> 
> Which is a bit weird, since I noticed this on Windows (8.1 64, Firefox 32
> bits), but this bug seems to address Linux...

I redid the bisection to verify and got the same range.

Comment 3

[Karl Tomlinson (:karlt)]

The testcase in Bug 1202119 may be helpful.

Comment 4

[Kartikaya Gupta (email:[e-mail])]

Per discussion with Avi on IRC

Comment 5

[Avi Halachmi (:avih)]

Brian, any idea what might be going on here? Any reason to suspect it might not be bug 1026803 afteral?

Comment 6

[Brian Birtles (:birtles)]

(In reply to Avi Halachmi (:avih) from comment #1)
> (In reply to Avi Halachmi (:avih) from comment #0)
> > Brian, the entire range appears to be bug 1026803.
> 
> Which is a bit weird, since I noticed this on Windows (8.1 64, Firefox 32
> bits), but this bug seems to address Linux...

That bug refactored the code used on Windows so it could be shared with Linux. It made some changes to the behavior on Windows too.

Comment 7

[Brian Birtles (:birtles)]

(In reply to Avi Halachmi (:avih) from comment #5)
> Brian, any idea what might be going on here? Any reason to suspect it might
> not be bug 1026803 afteral?

It's highly likely to be bug 1026803. Are you able to bisect that range to the actual changeset?

Comment 8

[Brian Birtles (:birtles)]

I guess it's either:
* part 3,
* part 6 (most likely), or
* part 8b (unlikely)

I really hope it's not part 6.

Comment 9

[Avi Halachmi (:avih)]

I used mozregression and this is the highest resolution it got with pre-built binaries of nightlies and inbound.

My build machine is slow so it would be a hassle to build all those revisions (even incrementally), but I can do try pushes of all of them and use the binaries.

However, I'm not able to push to try right now, so if you'd do that for me and create win32 builds, I'll test them tomorrow, otherwise I'll push to try tomorrow.

Comment 10

[Brian Birtles (:birtles)]

Sure:

part 1: https://ftp-ssl.mozilla.org/pub/mozilla.org/firefox/try-builds/[e-mail]-00a0bf4154e1
part 3: https://ftp-ssl.mozilla.org/pub/mozilla.org/firefox/try-builds/[e-mail]-ffb32b9331c7
part 6: https://ftp-ssl.mozilla.org/pub/mozilla.org/firefox/try-builds/[e-mail]-1d60ec84e002
part 8b: https://ftp-ssl.mozilla.org/pub/mozilla.org/firefox/try-builds/[e-mail]-68b16e8f35d3

Comment 11

[Avi Halachmi (:avih)]

(In reply to Brian Birtles (:birtles) from comment #8)
> I guess it's either:
> * part 3,
> * part 6 (most likely), or
> * part 8b (unlikely)

(In reply to Brian Birtles (:birtles) from comment #10)
> part 1:
> https://ftp-ssl.mozilla.org/pub/mozilla.org/firefox/try-builds/
> [e-mail]-00a0bf4154e1
> ...

Thanks.

Parts 1 and 3 are OK, parts 6 and 8b have the bug. So it seems 6 indeed.

Comment 12

[Karl Tomlinson (:karlt)]

It may be worth testing with NowLoRes() replaced with Now() to remove some possible effects of bug 1026765.

Comment 13

[Avi Halachmi (:avih)]

FWIW, I reproduced the issue (i.e. it always happens) on different Windows systems, so it's probably fair to say that many users are affected by this. Tested on:

1. win 8.1 64 - i7-4500U
2. win 10  64 - i3-5010U
3. win 10  32 - Atom z3740

All systems using the integrated GPU.

Comment 14

[MrOtherGuy]

I too experince this behavior. And just as well, parts 1&3 are unaffected while part 6 has the bug.

Specs for reference:

Win7 64 - i7-2630qm
nvidia gtx560m - no integrated gpu

Comment 15

[Avi Halachmi (:avih)]

[Tracking Requested - why for this release]:

APZ is planned to ride the trains with Firefox 44 (according to jrmuizel), and so this bug will be there as well.

The bug also affected Firefox 43 nightly, but AFAIK 43 will not ship with APZ and so will not have release users affected by it. I didn't check if it affects 43 Aurora and I don't know if it will affect 43 beta.

It's visible to users and considerably degrades the behavior of smooth scroll using the mouse wheel - which is probably one of the most common methods to scroll the page.

Comment 13 and comment 14 suggest that many users might be affected by it. I don't know if it affects OSs other than Windows.

Comment 16

[Kartikaya Gupta (email:[e-mail])]

(In reply to Avi Halachmi (:avih) from comment #15)
> APZ is planned to ride the trains with Firefox 44 (according to jrmuizel),
> and so this bug will be there as well.

That's what we're aiming for, but I don't intend to let APZ ride the trains unless all the bugs blocking 1178298 are dealt with one way or another. Adding this one to that pile.

Comment 17

[Karl Tomlinson (:karlt)]

Bug 1026803 should not have any effect on beta or release builds unless bug 1026804 is fixed.

Given APZ behaviour seems to depend on event timestamps, it should be retested with dom.event.highrestimestamp.enabled false before jumping to the beta train.

Comment 18

[Avi Halachmi (:avih)]

(In reply to Karl Tomlinson (ni?:karlt) from comment #17)
> Given APZ behaviour seems to depend on event timestamps, it should be
> retested with dom.event.highrestimestamp.enabled false before jumping to the
> beta train.

I tested with dom.event.highrestimestamp.enabled = false (had it as true by default), and it does _not_ fix the bug.

FWIW, Not sure if interesting or not, but I _think_ I don't see the bug at http://dbaron.org/log/20150916-compositor-animations-smoothness-demo i.e. as far as I can tell the animation is 100% smooth, and regardless if dom.event.highrestimestamp.enabled is true/false.

Comment 19

[Brian Birtles (:birtles)]

(In reply to Karl Tomlinson (ni?:karlt) from comment #17)
> Bug 1026803 should not have any effect on beta or release builds unless bug
> 1026804 is fixed.

Unless APZ is using the internal TimeStamp member, which seems possible. We currently store the timestamp in two formats but the pref determines which one we actually report back to the DOM (as well as the format we use for reporting it).

(In reply to Avi Halachmi (:avih) from comment #18)
> FWIW, Not sure if interesting or not, but I _think_ I don't see the bug at
> http://dbaron.org/log/20150916-compositor-animations-smoothness-demo i.e. as
> far as I can tell the animation is 100% smooth, and regardless if
> dom.event.highrestimestamp.enabled is true/false.

Compositor animations should have no relationship to event timestamps.

Comment 20

[Avi Halachmi (:avih)]

(In reply to Brian Birtles (:birtles) from comment #19)
> Compositor animations should have no relationship to event timestamps.

As far as I can tell, it happens with the animation itself, and while I can't tell about events in general, I do think it's not directly related to the wheel scroll events.

As comment 0 states (the video shows this too), when setting the animation duration to last few seconds, and rolling the mouse wheel few quick notches, it keeps animating for several seconds without any further inputs, and still exhibits this "jump" every ~250ms.

Comment 21

[Markus Stange [:mstange]]

(In reply to Brian Birtles (:birtles) from comment #19)
> (In reply to Karl Tomlinson (ni?:karlt) from comment #17)
> > Bug 1026803 should not have any effect on beta or release builds unless bug
> > 1026804 is fixed.
> 
> Unless APZ is using the internal TimeStamp member

It does: https://dxr.mozilla.org/mozilla-central/rev/6256ec9113c115141aab089c45ee69438884b680/gfx/layers/apz/src/AsyncPanZoomController.cpp#1615

Comment 22

[Kate Glazko]

As per comment 15, marking status affected for FF 44 and setting tracking flags for 44 because it has potential user impact especially for Windows.

Comment 23

[Brian Birtles (:birtles)]

I started looking into it and here's what I've found so far.

Narrowing down what part of https://hg.mozilla.org/mozilla-central/rev/1bf77ab3474c caused this it basically comes down to changing the following calculation:

    Time timeSinceReference = aTime - mReferenceTime;
    return mReferenceTimeStamp + TimeDuration::FromMilliseconds(timeSinceReference);
    
to:
    
    Time timeToNowByTimeStamp =
      static_cast<int64_t>((roughlyNow - mReferenceTimeStamp).ToMilliseconds());
    Time deltaFromNow = timeToNowByTimeStamp - timeSinceReference;
    return roughlyNow - TimeDuration::FromMilliseconds(deltaFromNow);

Now, ignoring imprecisions introduced in conversion routines, these would seem to be equivalent:

i.e. call the old behaviour A, and the new B

    A = mReferenceTimeStamp + timeSinceReference

    B = roughlyNow - deltaFromNow
      = roughlyNow - (timeToNowByTimeStamp - timeSinceReference)
      = roughlyNow - ((roughlyNow - mReferenceTimeStamp) - timeSinceReference)
      = roughlyNow - (roughlyNow - mReferenceTimeStamp - timeSinceReference)
      = mReferenceTimeStamp + timeSinceReference
      = A

One inaccuracy is that when we calculate deltaFromNow, Time is a uint32_t so if timeToNowByTimeStamp > timeSinceReference it wraps and we end up with a large number. This is easily fixed (and possibly already is) but doesn't appear to affect the result.

However, if I use TimeStamp::Now() instead of TimeStamp::NowLowRes() to calculate roughlyNow, the issue goes away. Based on the calculation above I wouldn't expect that to matter but it does appear to.

Comment 24

[Karl Tomlinson (:karlt)]

(In reply to Brian Birtles (:birtles) from comment #23)
> However, if I use TimeStamp::Now() instead of TimeStamp::NowLowRes() to
> calculate roughlyNow, the issue goes away. Based on the calculation above I
> wouldn't expect that to matter but it does appear to.

Bug 1026765 means it does.

Comment 25

[Brian Birtles (:birtles)]

(In reply to Karl Tomlinson (ni?:karlt) from comment #24)
> (In reply to Brian Birtles (:birtles) from comment #23)
> > However, if I use TimeStamp::Now() instead of TimeStamp::NowLowRes() to
> > calculate roughlyNow, the issue goes away. Based on the calculation above I
> > wouldn't expect that to matter but it does appear to.
> 
> Bug 1026765 means it does.

I'm not sure really. We don't call NowLoRes twice. In the very-much reduced code I'm debugging we call it once, store the result, and then perform a calculation that should eliminate its value, whatever it is.

What I can see is that sometimes methods A and B from comment 23 differ slightly, probably due to further int-float-int conversions, but it's always within 1ms. What's interesting is that we only appear to be hitting the timestamp conversion code at the beginning of the scroll. After that the scroll runs by itself and yet it still seems to show the jumping behavior.

It might be possible that we're getting a slightly inaccurate time for one of the events that sets up the scroll and that sets up a pattern for the animation that causes it to jump. Basically a bad input to the velocity calculation for the scroll animation.

Comment 26

[Brian Birtles (:birtles)]

If I return the timestamp from A everything works fine.
If I return the timestamp from B, it jumps.
If I do:

  if (a != b) {
    b = a;
  }
  return b;

then it jumps.

I guess it's something in the Windows implementation of TimeStampValue which might come back to bug 1026765 after all.

Comment 27

[Brian Birtles (:birtles)]

(In reply to Brian Birtles (:birtles) from comment #26)
>   if (a != b) {
>     b = a;
>   }
>   return b;

This is failing because a != b returns false because the equality operator is actually "roughly equal" operator. It is based on using operator- which given two operands with identical GTC values but one with a QPC value and one without, will return zero. As a result operator== will return true even when the two objects are not actually equal.

In this case, the timestamp calculated using the 'B' code path will have no QPC value because it is based on a value calculated from TimeStamp::NowLoRes().

Comment 28

[Brian Birtles (:birtles)]

I think the basic problem here is that we're mixing timestamps that use GTC values only, and timestamps that also have a QPC value. mReferenceTimeStamp is based on TimeStamp::Now() and hence stores a QPC value. However, we subtract it from roughlyNow which is based on TimeStamp::NoLowRes(). Although I still haven't pin-pointed the exact nature of the inaccuracy it's clear that doing arithmetic with these two types of values is introducing error which is triggering the jumpy behavior.

I originally chose to use TimeStamp::NoLowRes() because I anticipated a flood of events where the cost of TimeStamp::Now() might be significant. That's not based on any data however, just a hunch, and I'm now inclined to think we should just use TimeStamp::Now() here. I'll keep trying to dig into this but for now, Karl, what do you think about switching to calling TimeStamp::Now()?

Comment 29

[Karl Tomlinson (:karlt)]

(In reply to Brian Birtles (:birtles) from comment #28)
> Karl, what do you think about switching to calling
> TimeStamp::Now()?

I think that is the fastest way to a solution here.
durations from Now only can't be mixed with those involving NowLoRes, so if the TimeStamp returned here may be compared to one from Now, then it must not involve arithmetic with a TimeStamp from NowLoRes().

That's a r+ on a patch to change the NowLoRes() call to Now().
Some comments will need updating I expect.

Comment 30

[Brian Birtles (:birtles)]

Thanks Karl. I've thrown a patch at try for now. If all look ok, I'll fix up comments and land next week:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=38b04db643dd

Comment 31

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/c9af4f7acba9

Comment 32

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/c9af4f7acba9