1773127 - 8.62 - 5.95% tumblr LastVisualChange / tumblr fcp (Linux) regression on Mon June 6 2022

Status: RESOLVED FIXED

(Testing :: Raptor, defect, P2)

Description

[Alexandru Ionescu (needinfo me) [:alexandrui]]

Perfherder has detected a browsertime performance regression from push 5718cf939e0d24b8e7324515f8ff9fc1867aeb7b. As author of one of the patches included in that push, we need your help to address this regression.

Regressions:

Ratio	Test	Platform	Options	Absolute values (old vs new)
200%	tumblr FirstVisualChange	linux1804-64-shippable-qr	fission warm webrender	56.67 -> 170.00
53%	tumblr SpeedIndex	linux1804-64-shippable-qr	fission warm webrender	180.88 -> 277.00
36%	tumblr PerceptualSpeedIndex	linux1804-64-shippable-qr	fission warm webrender	246.33 -> 335.67
21%	tumblr ContentfulSpeedIndex	linux1804-64-shippable-qr	fission warm webrender	345.25 -> 417.67
9%	tumblr LastVisualChange	linux1804-64-shippable-qr	fission warm webrender	773.33 -> 840.00
6%	tumblr fcp	linux1804-64-shippable-qr	fission warm webrender	183.10 -> 194.00

Details of the alert can be found in the alert summary, including links to graphs and comparisons for each of the affected tests. Please follow our guide to handling regression bugs and let us know your plans within 3 business days, or the offending patch(es) will be backed out in accordance with our regression policy.

If you need the profiling jobs you can trigger them yourself from treeherder job view or ask a sheriff to do that for you.

For more information on performance sheriffing please see our FAQ.

Comment 1

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1655554

Comment 2

[Greg Mierzwinski [:sparky]]

Looking through the commits here: https://github.com/sitespeedio/browsertime/commits/main?before=d319b00e965e16d559abf7ce1f7c99dd989929d5+35&branch=main&qualified_name=refs%2Fheads%2Fmain

From there to May 4th, the one that sticks out most is this one: https://github.com/sitespeedio/browsertime/commit/e610bfb4f6f7231f73228e993bbebac8a5911f22

If this is the only regression we have though then I suggest closing it as wontfix (harness change).

Comment 3

[Greg Mierzwinski [:sparky]]

Regression still exists on the commit I mentioned above: https://treeherder.mozilla.org/perfherder/compare?originalProject=autoland&originalRevision=533ad0ead2345d753cfee67be9d044c10ecce710&newProject=try&newRevision=cea378a724041a3d38d9d9350ba0bb0cbd859b49&framework=13&page=3&showOnlyComparable=1

I'm testing a little further back now: https://treeherder.mozilla.org/jobs?repo=try&revision=b0044fc49f19efa3e5e72b065d3771f3a38d510e

Comment 4

[Greg Mierzwinski [:sparky]]

Found the commit which caused this regression: https://github.com/sitespeedio/browsertime/commit/2441eb53a386d0f0d28dfedae6f62b1f91b1da10

The previous commit was fine (https://github.com/sitespeedio/browsertime/commit/781921475ff9eab3b34cdd86ffe4a72e1ad19194): https://treeherder.mozilla.org/perfherder/compare?originalProject=autoland&originalRevision=533ad0ead2345d753cfee67be9d044c10ecce710&newProject=try&newRevision=a85299cda3d67a2a3b4dad295f585b623a822845&framework=13&page=2&showOnlyComparable=1&filter=tumbl

Peter, do you think we could hide the new metric behind a flag? It seems like the calculation/gathering is delaying or interfering with the pageload.

Comment 5

[Peter Hedenskog]

I think this indicates that something isn't working as it should: The correct flow should be that the video is turned off before we start to collect JavaScript metrics, meaning independently of what metrics we collect, the video should be the same.

I wonder if we need to add an extra wait? I'll go through the code first thing tomorrow.

Comment 6

[Peter Hedenskog]

Is that test using Firefox window recorder? We have different code depending on which recorder that is used.

Comment 7

[Greg Mierzwinski [:sparky]]

Yes, it uses the Firefox window recorder, here's the full command we are running if it helps: /home/cltbld/tasks/task_165480080508932/fetches/node/bin/node /home/cltbld/tasks/task_165480080508932/fetches/browsertime/node_modules/browsertime/bin/browsertime.js --firefox.geckodriverPath /home/cltbld/tasks/task_165480080508932/fetches/geckodriver /home/cltbld/tasks/task_165480080508932/build/tests/raptor/raptor/browsertime/../../browsertime/browsertime_pageload.js --firefox.noDefaultPrefs --browsertime.page_cycle_delay 1000 --skipHar --pageLoadStrategy none --webdriverPageload true --firefox.disableBrowsertimeExtension true --pageCompleteCheckStartWait 5000 --pageCompleteCheckPollTimeout 1000 --timeouts.pageLoad 60000 --timeouts.script 120000 --browsertime.page_cycles 2 --pageCompleteWaitTime 5000 --browsertime.url https://www.tumblr.com/dashboard --browsertime.post_startup_delay 1000 --iterations 25 --browsertime.secondary_url https://www.tumblr.com/tagged/funny+cats?sort=top --browsertime.commands --viewPort 1280x1024 --browser firefox --firefox.binaryPath /home/cltbld/tasks/task_165480080508932/build/application/firefox/firefox --firefox.profileTemplate /tmp/tmp8wly_akf/profile --resultDir /home/cltbld/tasks/task_165480080508932/build/blobber_upload_dir/browsertime-results/tumblr --video true --visualMetrics true --visualMetricsContentful true --visualMetricsPerceptual true --visualMetricsPortable true --videoParams.keepOriginalVideo true --firefox.windowRecorder true

Comment 8

[Peter Hedenskog]

I think the code then somehow is broken in the recorder? I've added https://github.com/sitespeedio/browsertime/pull/1805 where you can configure a delay to wait so that the video really stops before moving on (but if the async code would work in the recorder that should happen automatically?). The code work like this:

1. The page complete check has finished
2. Stop the video
3. Start collect JavaScript metrics (as the one you noticed causing the regression).

Or at least should work like that :)

Comment 9

[Greg Mierzwinski [:sparky]]

Ok, thanks for investigating Peter! I made a couple try runs here to see if there's still a regression on tumblr when we use FFMPEG instead: https://treeherder.mozilla.org/perfherder/compare?originalProject=try&originalRevision=1cbf93477ee6fbe599ff343088ac6c2e877a9568&newProject=try&newRevision=55369df6954b1297d7e0dc500d9ff4c291f02f56&framework=13&page=1

I'll post again when results are available.

Comment 10

[Greg Mierzwinski [:sparky]]

So with FFMPEG there are no regressions on that commit, but when we use the Firefox window recorder there is.

Here's the compare view link using the window recorder which shows a regression: https://treeherder.mozilla.org/perfherder/compare?originalProject=try&originalRevision=a85299cda3d67a2a3b4dad295f585b623a822845&newProject=try&newRevision=aaccb49876b1461b66995ce4fc1705a9f82d6635&framework=13&page=1&showOnlyComparable=1&showOnlyImportant=1

And this is the one which uses FFMPEG which shows no regressions: https://treeherder.mozilla.org/perfherder/compare?originalProject=try&originalRevision=1cbf93477ee6fbe599ff343088ac6c2e877a9568&newProject=try&newRevision=55369df6954b1297d7e0dc500d9ff4c291f02f56&framework=13&page=1&showOnlyComparable=1

Comment 11

[Greg Mierzwinski [:sparky]]

:sefeng, would you be able to look into this issue with the window recorder?

Comment 12

[Sean Feng [:sefeng211]]

Sorry I don't think I am the best person to look into this as I am not familiar with window recorder..

Thanks!

Comment 13

[Frank Doty [:fdoty]]

:bas are you able to review?

Comment 14

[BugBot [:suhaib / :marco/ :calixte]]

Redirect a needinfo that is pending on an inactive user to the triage owner.
:sparky, could you please find another way to get the information or close the bug as INCOMPLETE if it is not actionable?

For more information, please visit auto_nag documentation.

Comment 15

[BugBot [:suhaib / :marco/ :calixte]]

Set release status flags based on info from the regressing bug 1655554

Comment 16

[Dave Hunt [:davehunt] [he/him] ⌚BST]

@sparky Is there anything more to do here? Are we currently using the Firefox window recorder or FFMPEG? As this is not a regression that impacts users, I suggest closing this bug as WONTFIX and opening a bug against the Firefox window recorder. Perhaps also opening a meta bug to track switching to the Firefox window recorder if there are multiple blockers. Perhaps we even already have such a bug?

Comment 17

[Greg Mierzwinski [:sparky]]

Yes, no progress has been made on this bug and we're waiting on a ni? from :bas. We're currently using the window recorder, and that's what's broken here (or the reason why this regression occurred). For context, this regression doesn't exist when we use FFMPEG.

I disagree with closing this as WONTFIX unless we decide not to fix the issue (or unless we're changing our approach to handling these).

Comment 18

[Bas Schouten (:bas.schouten)]

Hmpf. So based on the comments on this bug it suggests that there can be JS code running before the Window Recorder has actually recorded its last frame. My theory here is that these websites have something that's visually changing continuously, and that because the Window Recorder operates asynchronously, we end up grabbing another frame that is delayed by that work before we actually stop it. Ideally we could just make sure the Window Recorder's promise here https://searchfox.org/mozilla-central/source/dom/base/nsDOMWindowUtils.cpp#4580 has resolved before we start collecting metrics.

Comment 19

[Timothy Nikkel (:tnikkel)]

Not sure if it's relevant, but sounds like it might be, in bug 1779953 we fixed a bug where the window recorder was actually recording the previous frame. So the time stamps of the frames would be off, but this also meant we would never get ahold of the very last snapshot of the window. The fix landed after this bug was filed.

Comment 20

[Greg Mierzwinski [:sparky]]

Resolving as fixed based on :tnikkel's comment. We can open a new bug for this if it happens again.