Closed Bug 1744354 Opened 2 years ago Closed 2 years ago

Almost perma gfx/layers/apz/test/mochitest/test_group_keyboard.html | scroll offset should be strictly monotonically increasing previous offset: 3.683349609375, offset: 3.683349609375

Categories

(Core :: Panning and Zooming, defect, P5)

defect

Tracking

()

RESOLVED FIXED
102 Branch
Tracking Status
firefox-esr91 --- unaffected
firefox100 --- unaffected
firefox101 --- unaffected
firefox102 --- fixed

People

(Reporter: intermittent-bug-filer, Assigned: dlrobertson)

References

(Regression)

Details

(Keywords: intermittent-failure, regression, Whiteboard: [stockwell disable-recommended])

Attachments

(1 file)

Filed by: ccozmuta [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=360124204&repo=mozilla-central
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/CC1pY3dlR2aIAzvf9I_yVw/runs/0/artifacts/public/logs/live_backing.log


[task 2021-12-03T22:29:34.600Z] 22:29:34     INFO - TEST-START | gfx/layers/apz/test/mochitest/test_group_keyboard.html
[task 2021-12-03T22:29:34.842Z] 22:29:34     INFO - GECKO(4190) | WaitUntilApzStable: flushed APZ repaints in parent proc, waiting for callback...
[task 2021-12-03T22:29:34.846Z] 22:29:34     INFO - GECKO(4190) | WaitUntilApzStable: APZ flush done in parent proc
[task 2021-12-03T22:29:34.846Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | WaitUntilApzStable: got apz-flush-done in child proc
[task 2021-12-03T22:29:34.848Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | WaitUntilApzStable: done promiseFocus
[task 2021-12-03T22:29:34.849Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | waiting for paint...
[task 2021-12-03T22:29:34.857Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | got MozAfterPaint: 0,0,0,0
[task 2021-12-03T22:29:34.858Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | Dispatching 1 onpaint listeners
[task 2021-12-03T22:29:34.859Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | waiting for paint...
[task 2021-12-03T22:29:34.875Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | got MozAfterPaint: 0,0,0,0
[task 2021-12-03T22:29:34.875Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | Dispatching 1 onpaint listeners
[task 2021-12-03T22:29:34.876Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | done...
[task 2021-12-03T22:29:34.876Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | WaitUntilApzStable: done promiseAllPaintsDone
[task 2021-12-03T22:29:34.878Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | PromiseApzRepaintsFlushed: Flushed APZ repaints, waiting for callback...
[task 2021-12-03T22:29:34.888Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | PromiseApzRepaintsFlushed: APZ flush done
[task 2021-12-03T22:29:34.889Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | WaitUntilApzStable: all done
[task 2021-12-03T22:29:34.899Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | waiting for paint...
[task 2021-12-03T22:29:34.900Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | got MozAfterPaint: 0,0,0,0
[task 2021-12-03T22:29:34.900Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | Dispatching 1 onpaint listeners
[task 2021-12-03T22:29:34.900Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | waiting for paint...
[task 2021-12-03T22:29:34.923Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | got MozAfterPaint: 0,0,0,0
[task 2021-12-03T22:29:34.923Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | Dispatching 1 onpaint listeners
[task 2021-12-03T22:29:34.924Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | done...
[task 2021-12-03T22:29:34.925Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | PromiseApzRepaintsFlushed: Flushed APZ repaints, waiting for callback...
[task 2021-12-03T22:29:34.939Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | PromiseApzRepaintsFlushed: APZ flush done
[task 2021-12-03T22:29:34.966Z] 22:29:34     INFO - GECKO(4190) | [Parent 4190, Main Thread] WARNING: '!IsSelectionValid()', file /builds/worker/checkouts/gecko/widget/ContentCache.cpp:667
[task 2021-12-03T22:29:34.966Z] 22:29:34     INFO - GECKO(4190) | [Parent 4190, Main Thread] WARNING: '!mContentCache.HandleQueryContentEvent( aEvent, textInputHandlingWidget)', file /builds/worker/checkouts/gecko/dom/ipc/BrowserParent.cpp:3050
[task 2021-12-03T22:29:34.971Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | got MozAfterPaint: 0,0,0,0
[task 2021-12-03T22:29:34.972Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | Dispatching 0 onpaint listeners
[task 2021-12-03T22:29:34.972Z] 22:29:34     INFO - GECKO(4190) | [Child 4204, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp:348
[task 2021-12-03T22:29:34.973Z] 22:29:34     INFO - GECKO(4190) | [Child 4204, Main Thread] WARNING: NS_ENSURE_TRUE(info) failed: file /builds/worker/checkouts/gecko/extensions/permissions/PermissionDelegateHandler.cpp:348
[task 2021-12-03T22:29:34.991Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | got MozAfterPaint: 0,0,0,0
[task 2021-12-03T22:29:34.991Z] 22:29:34     INFO - GECKO(4190) | helper_key_scroll.html | Dispatching 0 onpaint listeners
<...>
[task 2021-12-03T22:29:42.235Z] 22:29:42     INFO - Buffered messages logged at 22:29:42
[task 2021-12-03T22:29:42.236Z] 22:29:42     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | scroll offset should be strictly monotonically increasing previous offset: 0, offset: 0.066650390625 
[task 2021-12-03T22:29:42.236Z] 22:29:42     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | sampled time stamp should be strictly monotonically increasing previous timestamp: 0, timestamp: 103843970.625 
[task 2021-12-03T22:29:42.237Z] 22:29:42     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | scroll offset should be strictly monotonically increasing previous offset: 0.066650390625, offset: 0.2166748046875 
[task 2021-12-03T22:29:42.237Z] 22:29:42     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | sampled time stamp should be strictly monotonically increasing previous timestamp: 103843970.625, timestamp: 103860668.11099999 
[task 2021-12-03T22:29:42.238Z] 22:29:42     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | scroll offset should be strictly monotonically increasing previous offset: 0.2166748046875, offset: 0.5 
[task 2021-12-03T22:29:42.238Z] 22:29:42     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | sampled time stamp should be strictly monotonically increasing previous timestamp: 103860668.11099999, timestamp: 103877078.067 
[task 2021-12-03T22:29:42.239Z] 22:29:42     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | scroll offset should be strictly monotonically increasing previous offset: 0.5, offset: 0.8499755859375 
[task 2021-12-03T22:29:42.239Z] 22:29:42     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | sampled time stamp should be strictly monotonically increasing previous timestamp: 103877078.067, timestamp: 103893016.00100002 
[task 2021-12-03T22:29:42.240Z] 22:29:42     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | scroll offset should be strictly monotonically increasing previous offset: 0.8499755859375, offset: 1.26666259765625 
[task 2021-12-03T22:29:42.240Z] 22:29:42     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | sampled time stamp should be strictly monotonically increasing previous timestamp: 103893016.00100002, timestamp: 103908639.90100001 
[task 2021-12-03T22:29:42.241Z] 22:29:42     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | scroll offset should be strictly monotonically increasing previous offset: 1.26666259765625, offset: 1.75 
[task 2021-12-03T22:29:42.241Z] 22:29:42     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | sampled time stamp should be strictly monotonically increasing previous timestamp: 103908639.90100001, timestamp: 103925416.44 
[task 2021-12-03T22:29:42.242Z] 22:29:42     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | scroll offset should be strictly monotonically increasing previous offset: 1.75, offset: 2.26666259765625 
[task 2021-12-03T22:29:42.242Z] 22:29:42     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | sampled time stamp should be strictly monotonically increasing previous timestamp: 103925416.44, timestamp: 103943979.332 
[task 2021-12-03T22:29:42.243Z] 22:29:42     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | scroll offset should be strictly monotonically increasing previous offset: 2.26666259765625, offset: 2.9000244140625 
[task 2021-12-03T22:29:42.243Z] 22:29:42     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | sampled time stamp should be strictly monotonically increasing previous timestamp: 103943979.332, timestamp: 103958682.353 
[task 2021-12-03T22:29:42.243Z] 22:29:42     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | scroll offset should be strictly monotonically increasing previous offset: 2.9000244140625, offset: 3.683349609375 
[task 2021-12-03T22:29:42.244Z] 22:29:42     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | sampled time stamp should be strictly monotonically increasing previous timestamp: 103958682.353, timestamp: 103975328.06700002 
[task 2021-12-03T22:29:42.244Z] 22:29:42     INFO - Buffered messages finished
[task 2021-12-03T22:29:42.245Z] 22:29:42     INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_group_keyboard.html | scroll offset should be strictly monotonically increasing previous offset: 3.683349609375, offset: 3.683349609375 
[task 2021-12-03T22:29:42.245Z] 22:29:42     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
[task 2021-12-03T22:29:42.245Z] 22:29:42     INFO -     test@gfx/layers/apz/test/mochitest/helper_relative_scroll_smoothness.html?input-type=native-key&scroll-method=scrollTo:121:7
<...>
[task 2021-12-03T22:29:42.317Z] 22:29:42     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | scroll offset should be strictly monotonically increasing previous offset: 2822.083251953125, offset: 2876.7666015625 
[task 2021-12-03T22:29:42.318Z] 22:29:42     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | sampled time stamp should be strictly monotonically increasing previous timestamp: 105276200.157, timestamp: 105291643.585 
[task 2021-12-03T22:29:42.318Z] 22:29:42     INFO - GECKO(4190) | helper_relative_scroll_smoothness.html?input-type=native-key&scroll-method=scrollTo | got MozAfterPaint: 0,0,0,0
[task 2021-12-03T22:29:42.319Z] 22:29:42     INFO - GECKO(4190) | helper_relative_scroll_smoothness.html?input-type=native-key&scroll-method=scrollTo | Dispatching 0 onpaint listeners
[task 2021-12-03T22:29:42.319Z] 22:29:42     INFO - must wait for focus
[task 2021-12-03T22:29:42.319Z] 22:29:42     INFO - GECKO(4190) | helper_relative_scroll_smoothness.html?input-type=native-key&scroll-method=scrollTo | got MozAfterPaint: 0,0,0,0
[task 2021-12-03T22:29:42.320Z] 22:29:42     INFO - GECKO(4190) | helper_relative_scroll_smoothness.html?input-type=native-key&scroll-method=scrollTo | Dispatching 0 onpaint listeners
[task 2021-12-03T22:29:42.320Z] 22:29:42     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | Starting subtest helper_relative_scroll_smoothness.html?input-type=native-key&scroll-method=scrollTop 
[task 2021-12-03T22:29:42.435Z] 22:29:42     INFO - GECKO(4190) | WaitUntilApzStable: flushed APZ repaints in parent proc, waiting for callback...
[task 2021-12-03T22:29:42.435Z] 22:29:42     INFO - GECKO(4190) | WaitUntilApzStable: APZ flush done in parent proc
[task 2021-12-03T22:29:42.438Z] 22:29:42     INFO - GECKO(4190) | helper_relative_scroll_smoothness.html?input-type=native-key&scroll-method=scrollTop | WaitUntilApzStable: got apz-flush-done in child proc
[task 2021-12-03T22:29:42.439Z] 22:29:42     INFO - must wait for load
[task 2021-12-03T22:29:42.443Z] 22:29:42     INFO - GECKO(4190) | helper_relative_scroll_smoothness.html?input-type=native-key&scroll-method=scrollTop | WaitUntilApzStable: done promiseFocus
[task 2021-12-03T22:29:42.444Z] 22:29:42     INFO - GECKO(4190) | helper_relative_scroll_smoothness.html?input-type=native-key&scroll-method=scrollTop | waiting for paint...
[task 2021-12-03T22:29:42.473Z] 22:29:42     INFO - GECKO(4190) | helper_relative_scroll_smoothness.html?input-type=native-key&scroll-method=scrollTop | got MozAfterPaint: 0,0,0,0
[task 2021-12-03T22:29:42.474Z] 22:29:42     INFO - GECKO(4190) | helper_relative_scroll_smoothness.html?input-type=native-key&scroll-method=scrollTop | Dispatching 1 onpaint listeners
[task 2021-12-03T22:29:42.474Z] 22:29:42     INFO - GECKO(4190) | helper_relative_scroll_smoothness.html?input-type=native-key&scroll-method=scrollTop | got MozAfterPaint: 0,0,0,0
[task 2021-12-03T22:29:42.475Z] 22:29:42     INFO - GECKO(4190) | helper_relative_scroll_smoothness.html?input-type=native-key&scroll-method=scrollTop | Dispatching 0 onpaint listeners
[task 2021-12-03T22:29:42.475Z] 22:29:42     INFO - GECKO(4190) | helper_relative_scroll_smoothness.html?input-type=native-key&scroll-method=scrollTop | done...
[task 2021-12-03T22:29:42.476Z] 22:29:42     INFO - GECKO(4190) | helper_relative_scroll_smoothness.html?input-type=native-key&scroll-method=scrollTop | WaitUntilApzStable: done promiseAllPaintsDone
[task 2021-12-03T22:29:42.477Z] 22:29:42     INFO - GECKO(4190) | helper_relative_scroll_smoothness.html?input-type=native-key&scroll-method=scrollTop | PromiseApzRepaintsFlushed: Flushed APZ repaints, waiting for callback...
[task 2021-12-03T22:29:42.485Z] 22:29:42     INFO - GECKO(4190) | helper_relative_scroll_smoothness.html?input-type=native-key&scroll-method=scrollTop | PromiseApzRepaintsFlushed: APZ flush done
[task 2021-12-03T22:29:42.486Z] 22:29:42     INFO - GECKO(4190) | helper_relative_scroll_smoothness.html?input-type=native-key&scroll-method=scrollTop | WaitUntilApzStable: all done
[task 2021-12-03T22:29:42.488Z] 22:29:42     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | Dispatched an down arrow key event 
Summary: Intermittent [Tier 2] gfx/layers/apz/test/mochitest/test_group_keyboard.html | scroll offset should be strictly monotonically increasing previous offset: 3.683349609375, offset: 3.683349609375 → Intermittent gfx/layers/apz/test/mochitest/test_group_keyboard.html | scroll offset should be strictly monotonically increasing previous offset: 3.683349609375, offset: 3.683349609375
Status: NEW → RESOLVED
Closed: 2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

Update:
There have been 37 failures within the last 7 days, all on Windows 10 x64 2004 asan WebRender opt.
Recent failure log: https://treeherder.mozilla.org/logviewer?job_id=379402776&repo=mozilla-central&lineNumber=13824

[task 2022-05-26T23:03:56.825Z] 23:03:56     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | sampled time stamp should be strictly monotonically increasing previous timestamp: 46313394.9, timestamp: 46329019.9 
[task 2022-05-26T23:03:56.826Z] 23:03:56     INFO - Buffered messages finished
[task 2022-05-26T23:03:56.826Z] 23:03:56     INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_group_keyboard.html | scroll offset should be strictly monotonically increasing previous offset: 272.449951171875, offset: 143 
[task 2022-05-26T23:03:56.826Z] 23:03:56     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
[task 2022-05-26T23:03:56.827Z] 23:03:56     INFO -     test@gfx/layers/apz/test/mochitest/helper_relative_scroll_smoothness.html?input-type=native-key&scroll-method=scrollTo:108:7
[task 2022-05-26T23:03:56.827Z] 23:03:56     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | sampled time stamp should be strictly monotonically increasing previous timestamp: 46329019.9, timestamp: 46360325.2 
[task 2022-05-26T23:03:56.828Z] 23:03:56     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-05-26T23:03:56.829Z] 23:03:56     INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_group_keyboard.html | scroll offset should be strictly monotonically increasing previous offset: 143, offset: 143 
[task 2022-05-26T23:03:56.829Z] 23:03:56     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
[task 2022-05-26T23:03:56.829Z] 23:03:56     INFO -     test@gfx/layers/apz/test/mochitest/helper_relative_scroll_smoothness.html?input-type=native-key&scroll-method=scrollTo:108:7
[task 2022-05-26T23:03:56.830Z] 23:03:56     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | sampled time stamp should be strictly monotonically increasing previous timestamp: 46360325.2, timestamp: 46376391.7 
[task 2022-05-26T23:03:56.830Z] 23:03:56     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-05-26T23:03:56.831Z] 23:03:56     INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_group_keyboard.html | scroll offset should be strictly monotonically increasing previous offset: 143, offset: 143 
[task 2022-05-26T23:03:56.831Z] 23:03:56     INFO -     SimpleTest.ok@SimpleTest/SimpleTest.js:417:16
[task 2022-05-26T23:03:56.831Z] 23:03:56     INFO -     test@gfx/layers/apz/test/mochitest/helper_relative_scroll_smoothness.html?input-type=native-key&scroll-method=scrollTo:108:7
[task 2022-05-26T23:03:56.832Z] 23:03:56     INFO - TEST-PASS | gfx/layers/apz/test/mochitest/test_group_keyboard.html | sampled time stamp should be strictly monotonically increasing previous timestamp: 46376391.7, timestamp: 46397977 
Whiteboard: [stockwell needswork:owner]

Hi Botond! Can you please take a look at this?
Thank you!

Flags: needinfo?(botond)

The failing subtest is helper_relative_scroll_smoothness.html -- Hiro, perhaps you could take a look?

Flags: needinfo?(botond) → needinfo?(hikezoe.birchill)

From the log in comment 14;

[task 2022-05-26T23:03:56.826Z] 23:03:56     INFO - TEST-UNEXPECTED-FAIL | gfx/layers/apz/test/mochitest/test_group_keyboard.html | scroll offset should be strictly monotonically increasing previous offset: 272.449951171875, offset: 143 

This is not what this bug is supposed to. The scroll position jumped back upwards. It looks to me we regressed at some point.

According to recent backfills/retriggers (bk range), it seems to be almost a perma fail.

Summary: Intermittent gfx/layers/apz/test/mochitest/test_group_keyboard.html | scroll offset should be strictly monotonically increasing previous offset: 3.683349609375, offset: 3.683349609375 → Almost perma gfx/layers/apz/test/mochitest/test_group_keyboard.html | scroll offset should be strictly monotonically increasing previous offset: 3.683349609375, offset: 3.683349609375

I pushed a try run with two logging places; one is just before a transmogrification from ScrollToCSSPixels to ScrollByCSSPxels, another one is just after the transmogrification if branch.

 ScrollToCSSPixels scrollTo((0,201)) current: (0,191)
 ScrollToCSSPixels scrollTo((0,211)) current: (0,201)
 Transmogrify scrollTo((0,234)) -> scrollBy((0,10)) current: (0,224)

The first two lines show us it failed to do the transmogrification. I guess if the main-thread was very heavy load even our Priority=control repaint requests had't been able to be processed, but after a while window.scrollTo in a setInterval callback is processed just before processing pending repaint requests, thus we are not sure whether there's an on-going APZ animations or not. That's my hypothesis.

I will push another try run to see mCurrentAPZScrollAnimationType and isScrollAnimating values in the function.

Hiro, if it helps, the failure seem to have started to almost perma fail with the landing of Bug 1759627
R&B range

Regressed by: 1754308
Regressed by: 1759627
No longer regressed by: 1754308

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

Looks like bug 1759627 caused us to do more work than necessary in scenarios was apz.printtree was false (we would prepare the output we would have dumped if the pref was set and then throw it away), which likely threw off some timings / made things slower in this test.

Dan has a patch on Try which looks like it fixes this: https://treeherder.mozilla.org/jobs?repo=try&revision=9ecc46122b331c4c9f44b7679e7d4701024d3927

Assignee: nobody → drobertson
Flags: needinfo?(hikezoe.birchill)
Attachment #9278593 - Attachment description: Bug 1744354 - Do not build print string unless we are going to print. r=botond → Bug 1744354 - Do not build print string for apz.printree logging unless the pref is enabled. r=botond
Pushed by bballo@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/7b6293ef312a
Do not build print string for apz.printree logging unless the pref is enabled. r=botond
Status: REOPENED → RESOLVED
Closed: 2 years ago2 years ago
Resolution: --- → FIXED
Target Milestone: --- → 102 Branch

Thank you, Dan and Botond!

For references I am noting what I learned from logs. A place in a log where we fail to transmogrify scrollTo is;

21:46:09.452Z  repaint request: { scrollId=14, scrollOffset=(0,186.233), zoom=1, viewport=(x=0, y=186.233, w=1263, h=938), scrollUpdateType=0, scrollGeneration=143, scrollGenerationOnApz=269, dpMargins=(t=586.25, r=78.9375, b=586.25, l=78.9375)}
21:46:09.457Z  queuing repaint request: { scrollId=14, scrollOffset=(0,211.75), zoom=1, viewport=(x=0, y=211.75, w=1263, h=938), scrollUpdateType=1, scrollGeneration=143, scrollGenerationOnApz=270, dpMargins=(t=586.25, r=78.9375, b=586.25, l=78.9375)}
21:46:09.460Z  queuing repaint request: { scrollId=14, scrollOffset=(0,211.75), zoom=1, viewport=(x=0, y=211.75, w=1263, h=938), scrollUpdateType=0, scrollGeneration=144, scrollGenerationOnApz=270, dpMargins=(t=586.25, r=78.9375, b=586.25, l=78.9375)}
21:46:09.469Z  ScrollToCSSPixels scrollTo((0,196)) current: (0,186), animation-type: 2, scrollAnimationState: 14

At the first line we reflected a repaint request having 186.233 scroll offset on the main-thread, thus the offset, 186 was used as current at the last line.
Two queuing repaint requests at the second/third lines hadn't been processed when we failed the transmogrification at the forth line.

This is a possible scenario where we fail, that is;

  1. a refresh driver tick started
  2. queued repaint requests are processed
  3. a refresh driver tick ended
  4. new repaint requests queued
  5. some scripts run in setTimeout/setInterval callbacks
  6. next refresh driver tick

That said, in these days I suppose web developers use requestAnimationFrame rather then setTimeout/setInterval so it won't be a big problem (I'd hope).

== Change summary for alert #34257 (as of Tue, 31 May 2022 22:01:36 GMT) ==

Improvements:

Ratio Test Platform Options Absolute values (old vs new)
14% tresize windows10-64-shippable-qr e10s fission stylo webrender 6.89 -> 5.96
7% tresize linux1804-64-shippable-qr e10s fission stylo webrender-sw 20.00 -> 18.57
6% tscrollx linux1804-64-shippable-qr e10s fission stylo webrender 1.46 -> 1.37
5% tscrollx linux1804-64-shippable-qr e10s fission stylo webrender-sw 1.16 -> 1.10

For up to date results, see: https://treeherder.mozilla.org/perfherder/alerts?id=34257

(In reply to Andrej (:andrej) from comment #29)

== Change summary for alert #34257 (as of Tue, 31 May 2022 22:01:36 GMT) ==
...

This is likely due to this bug fixing bug 1771906 as discussed in this comment.

You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: