If you think a bug might affect users in the 57 release, please set the correct tracking and status flags for Release Management.

July 28 2016 Regression in Performance Measure FX_REFRESH_DRIVER_SYNC_SCROLL_FRAME_DELAY_MS

RESOLVED FIXED

Status

()

Core
Panning and Zooming
P3
normal
RESOLVED FIXED
a year ago
a year ago

People

(Reporter: chutten, Unassigned)

Tracking

({regression})

50 Branch
Unspecified
Windows
regression
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox49 unaffected, firefox50 fixed, firefox51 fixed)

Details

(Whiteboard: [gfx-noted])

(Reporter)

Description

a year ago
From July 28 to July 29 there was a sudden [1] increase in the aggregate measures of FX_REFRESH_DRIVER_SYNC_SCROLL_FRAME_DELAY_MS. The mean jumped from 0 to 1, the 75th percentile from 1 to 11.

Submission volumes in terms of clients and pings are roughly the same (compare metric/sample count in [2] vs [3]) which is consistent with a change in the measured code, not change in what is being measured. (IOW: we're not suddenly measuring more/fewer things which is skewing the distribution. The actual things we're measuring have changed to be larger)

This was detected by medusa [4] which came up with a pushlog for the regression range [5]. Unfortunately, I can't tell what change in that list may have caused this, and whether the change is intentional.

The relevant files according to dxr [6] are layout/base/nsRefreshDriver.cpp and layout/generic/nsGfxScrollFrame.cpp. The only change in the pushlog for either of those files [7] was for bug 1282408 and appears to just add some annotations for static analysis. Just in case, I've +Cc'd the two people visible from that commit.

Questions:
  Is this change in the measure expected/intentional?
  Is this change in the measure acceptable?
  Is this evidence that the measure is incorrect/not useful? 

[1]: https://mzl.la/2anRdkY
[2]: https://mzl.la/2anRAfl
[3]: https://mzl.la/2anRXGJ
[4]: http://alerts.telemetry.mozilla.org/index.html#/detectors/1/metrics/1683/alerts/?from=2016-07-29&to=2016-07-29
[5]: https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=db3ed1fdbbeaf5ab1e8fe454780146e7499be3db&tochange=2ea3d51ba1bb9f5c3b6921c43ea63f70b4fdf5d2
[6]: https://dxr.mozilla.org/mozilla-central/search?q=FX_REFRESH_DRIVER_SYNC_SCROLL_FRAME_DELAY_MS&case=true&=mozilla-central
[7]: https://hg.mozilla.org/mozilla-central/rev/d8b267ae7f69
(Reporter)

Comment 1

a year ago
I don't suppose the simultaneous change [1] in COMPOSITE_FRAME_ROUNDTRIP time might be related? 

[1]: https://mzl.la/2anSXdV
   : http://alerts.telemetry.mozilla.org/index.html#/detectors/1/metrics/1645/alerts/?from=2016-07-29&to=2016-07-29
What release channel(s) did this happen on?

Did things change across platforms or only on one?
Flags: needinfo?(chutten)
(Reporter)

Comment 3

a year ago
This appears to be Windows-only ( Mac+Linux [1] remain flat ) and it was detected on Nightly.

[1]: https://mzl.la/2ao5Uoq
Flags: needinfo?(chutten)
(Reporter)

Comment 4

a year ago
Due to timing, it may have crept into Aurora as well, but submission volumes are too low to say for sure just yet.
It looks like FX_REFRESH_DRIVER_CHROME_FRAME_DELAY_MS went up but FX_REFRESH_DRIVER_CONTENT_FRAME_DELAY_MS did not. This suggests that it may have been a change to the Firefox frontend and not a graphics change that caused the difference.
I didn't see anything obvious in the regression-window. Here's the best I was able to come up with:
https://hg.mozilla.org/mozilla-central/rev/2b3f0b8a6318
I don't think that the patch that was mentioned here has something to do with the issue.
Whiteboard: [gfx-noted]
status-firefox49: --- → unaffected
status-firefox50: --- → affected
status-firefox51: --- → affected
Component: Graphics → Panning and Zooming
Keywords: regression, regressionwindow-wanted
OS: Unspecified → Windows
Version: unspecified → 50 Branch
I also don't see anything in the regression range that stands out as a probable culprit.

(In reply to Chris H-C :chutten from comment #0)
> Questions:
>   Is this change in the measure expected/intentional?

No.

>   Is this change in the measure acceptable?

No.

>   Is this evidence that the measure is incorrect/not useful? 

No.

(In reply to Chris H-C :chutten from comment #1)
> I don't suppose the simultaneous change [1] in COMPOSITE_FRAME_ROUNDTRIP
> time might be related? 

Seems that way, yeah.
(Reporter)

Comment 9

a year ago
If it's any help, it appears to be concentrated on Windows[1]. Linux[2] and Mac[3] show no corresponding increases at that day.

[1]: https://mzl.la/2bJH5EF
[2]: https://mzl.la/2bJGfbh
[3]: https://mzl.la/2bJGlPO
I've been puzzling over this a bit. I sort of agree with Jeff's conclusion in comment 5 that since this only affects the parent process it's unlikely to be a gfx change, and is likely something that changed in the browser front-end. Given that the regression is in the sync smooth-scrolling code (ScrollFrameHelper::AsyncScroll and ScrollFrameHelper::AsyncSmoothMSDScroll are the two classes that enable recording of the FX_REFRESH_DRIVER_SYNC_SCROLL_FRAME_DELAY_MS histogram), and given that APZ should be enabled by default, it seems that the regression is limited to some part of the browser chrome that is somehow doing smooth-scrolling without APZ. Really there shouldn't be anything that does this at all. I'll try setting a breakpoint in that code in a local build and see what trips it, that might provide some clues.
One example of an action that triggers this behaviour is scrolling down a page using the spacebar on about:addons or about:preferences.

Another is wheel-scrolling inside select element popups (which basically spawn non-APZ popup windows), and thus wheel scrolling inside them with smooth scrolling enabled does sync scrolling on the main thread.
Looking over the regression pushlog again I also noticed bug 1278408, which actually might be the cause. If the vsync timestamps are shifted around then the refresh driver will tick at different times, and so any sync-scroll animations will be affected. It may not be an actual performance regression, but just a shift in timestamps being used for the probes. I'm not entirely sure why the content process escaped unscathed but maybe the IPC overhead negated some of this? Mason, any thoughts?

It'll be interesting to see if bug 1295214 fixes this regression as well.
Flags: needinfo?(mchang)
(In reply to Kartikaya Gupta (email:kats@mozilla.com) from comment #12)
> Looking over the regression pushlog again I also noticed bug 1278408, which
> actually might be the cause. If the vsync timestamps are shifted around then
> the refresh driver will tick at different times, and so any sync-scroll
> animations will be affected. It may not be an actual performance regression,
> but just a shift in timestamps being used for the probes. I'm not entirely
> sure why the content process escaped unscathed but maybe the IPC overhead
> negated some of this? Mason, any thoughts?
> 
> It'll be interesting to see if bug 1295214 fixes this regression as well.

From [1], we track the latency between the vsync timestamp and when the parent process runs the refresh drivers. For the child process, we track the latency since the last tick.

Like Kats said this is kind of a regression, but not a real one. It's noisy because we had bugs in reporting the vsync timestamp with intel drivers that we forgot to correct for, which bug 1295214 should fix.

[1] http://searchfox.org/mozilla-central/source/layout/base/nsRefreshDriver.cpp#452
Flags: needinfo?(mchang)
Blocks: 1278408
Depends on: 1295214
Keywords: regressionwindow-wanted
Priority: -- → P3
The telemetry data appears to back down as of the Aug 27 build, which corresponds to the first build that has the fix from bug 1295214. However I want a few more days data before I call it.
Ok, calling this fixed by bug 1295214, on both nightly and aurora.
Status: NEW → RESOLVED
Last Resolved: a year ago
status-firefox50: affected → fixed
status-firefox51: affected → fixed
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.