Intermittent browser/base/content/test/performance/browser_appmenu.js | reflow at adjustArrowPosition@chrome://global/content/bindings/popup.xml was encountered 5 times,

RESOLVED FIXED in Firefox 67

Status

()

defect
P5
normal
RESOLVED FIXED
11 months ago
Last month

People

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

Tracking

(Blocks 1 bug, {intermittent-failure})

unspecified
Firefox 67
Points:
---
Dependency tree / graph

Firefox Tracking Flags

(firefox67 fixed)

Details

(Whiteboard: [retriggered])

Attachments

(1 attachment, 3 obsolete attachments)

Filed by: shindli [at] mozilla.com

https://treeherder.mozilla.org/logviewer.html#?job_id=197848766&repo=mozilla-inbound

https://queue.taskcluster.net/v1/task/arlYyP-eSQ-rsORRdhK93A/runs/0/artifacts/public/logs/live_backing.log

08:10:27     INFO -   
08:10:27     INFO - Buffered messages finished
08:10:27     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_appmenu.js | reflow at adjustArrowPosition@chrome://global/content/bindings/popup.xml was encountered 5 times,
08:10:27     INFO - it was expected to happen up to 3 times. - false == true - JS frame :: chrome://mochitests/content/browser/browser/base/content/test/performance/head.js :: reportUnexpectedReflows :: line 172
08:10:27     INFO - Stack trace:
08:10:27     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/head.js:reportUnexpectedReflows:172
08:10:27     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/head.js:withPerfObserver:629
08:10:27     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_appmenu.js:null:67
08:10:27     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1102
08:10:27     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1093
08:10:27     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:995
08:10:27     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:795
08:10:27     INFO - Full stack (hit 5 times):
08:10:27     INFO -   adjustArrowPosition@chrome://global/content/bindings/popup.xml:163:13
08:10:27     INFO -   onxblpopuppositioned@chrome://global/content/bindings/popup.xml:262:9
08:10:27     INFO -
https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
Status: NEW → RESOLVED
Closed: 8 months ago
Resolution: --- → INCOMPLETE
Status: REOPENED → RESOLVED
Closed: 8 months ago6 months ago
Resolution: --- → INCOMPLETE

I don't think it is my code change. The only code change is currently in code that's preffed off by default, the CSS changes should also not be affecting anything since they're only a one-off anyway.

Cristina, I just noticed, my revision - 9f90c6e59169 - has browser_appmenu.js as bc3, however revision fb4f75995571 (the one with all green bc3) doesn't have browser_appmenu.js listed in bc3 - it is in bc5. So at some stage between those, the split of tests got re-arranged.

Therefore I think the current range is wrong. Looking a few changesets further back in the list, I think 2e27f3f1ebc6 (bug 1520607) would be a likely candidate.

Flags: needinfo?(standard8) → needinfo?(ccoroiu)

:standard8 thank you for looking.

:Gijs could you please take a look at comment 17?

Flags: needinfo?(ccoroiu) → needinfo?(gijskruitbosch+bugs)

(In reply to Cristina Coroiu [:ccoroiu] from comment #19)

:standard8 thank you for looking.

:Gijs could you please take a look at comment 17?

I can't reproduce locally, unfortunately.

The log has:

16:07:56     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_appmenu.js | reflow at adjustArrowPosition@chrome://global/content/bindings/popup.xml was encountered 17 times,
16:07:56     INFO - it was expected to happen up to 3 times. - false == true - JS frame :: chrome://mochitests/content/browser/browser/base/content/test/performance/head.js :: reportUnexpectedReflows :: line 180
16:07:56     INFO - Stack trace:
16:07:56     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/head.js:reportUnexpectedReflows:180
16:07:56     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/head.js:withPerfObserver:637
16:07:56     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_appmenu.js:null:67
16:07:56     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1109
16:07:56     INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1100
16:07:56     INFO - chrome://mochikit/content/browser-test.js:nextTest/<:998
16:07:56     INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:803
16:07:56     INFO - Full stack (hit 17 times):
16:07:56     INFO -   adjustArrowPosition@chrome://global/content/bindings/popup.xml:290:13
16:07:56     INFO -   onxblpopuppositioned@chrome://global/content/bindings/popup.xml:389:9
16:07:56     INFO -   


So we're trying to show the popup in https://searchfox.org/mozilla-central/source/browser/base/content/test/performance/browser_appmenu.js#66-70 and we see https://searchfox.org/mozilla-central/source/toolkit/content/widgets/popup.xml#290 being hit loads, which means we're getting loads of popuppositioned events somehow. I don't understand why that'd be the case. Neil, can you help?

Flags: needinfo?(gijskruitbosch+bugs) → needinfo?(enndeakin)

Over the last 7 days there are 39 failures on this bug. All of the failures happen on osx-10-10.

Here is the latest log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=226419778&repo=autoland&lineNumber=985

22:28:27 INFO - Entering test bound
22:28:27 INFO - TEST-PASS | browser/base/content/test/performance/browser_appmenu.js | The panel is closed to begin with. - "closed" == "closed" -
22:28:27 INFO - Buffered messages logged at 22:28:27
22:28:27 INFO - TEST-FAIL | browser/base/content/test/performance/browser_appmenu.js | known reflow at openPopup/this._openPopupPromise<@resource:///modules/PanelMultiView.jsm was encountered 1 times -
22:28:27 INFO - Full stack:
22:28:27 INFO - openPopup/this._openPopupPromise<@resource:///modules/PanelMultiView.jsm:520:9
22:28:27 INFO -
22:28:27 INFO - Buffered messages finished
22:28:27 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_appmenu.js | reflow at adjustArrowPosition@chrome://global/content/bindings/popup.xml was encountered 14 times,
22:28:27 INFO - it was expected to happen up to 3 times. - false == true - JS frame :: chrome://mochitests/content/browser/browser/base/content/test/performance/head.js :: reportUnexpectedReflows :: line 180
22:28:27 INFO - Stack trace:
22:28:27 INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/head.js:reportUnexpectedReflows:180
22:28:27 INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/head.js:withPerfObserver:637
22:28:27 INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_appmenu.js:null:67
22:28:27 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1106
22:28:27 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1097
22:28:27 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:995
22:28:27 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:803
22:28:27 INFO - Full stack (hit 14 times):
22:28:27 INFO - adjustArrowPosition@chrome://global/content/bindings/popup.xml:290:13
22:28:27 INFO - onxblpopuppositioned@chrome://global/content/bindings/popup.xml:389:9
22:28:27 INFO -
22:28:27 INFO - TEST-FAIL | browser/base/content/test/performance/browser_appmenu.js | known reflow at _calculateMaxHeight@resource:///modules/PanelMultiView.jsm was encountered 7 times -
22:28:27 INFO - Full stack:
22:28:27 INFO - _calculateMaxHeight@resource:///modules/PanelMultiView.jsm:1061:9
22:28:27 INFO - handleEvent@resource:///modules/PanelMultiView.jsm:1122:27
22:28:27 INFO - EventListener.handleEventconnect@resource:///modules/PanelMultiView.jsm:391:5
22:28:27 INFO - openPopup/this._openPopupPromise<@resource:///modules/PanelMultiView.jsm:500:11
22:28:27 INFO - promise callback
openPopup@resource:///modules/PanelMultiView.jsm:486:37
22:28:27 INFO - asyncopenPopup@resource:///modules/PanelMultiView.jsm:272:47
22:28:27 INFO - async
show/<@chrome://browser/content/customizableui/panelUI.js:211:13
22:28:27 INFO - asyncshow@chrome://browser/content/customizableui/panelUI.js:197:6
22:28:27 INFO - openMainMenu/<@resource://testing-common/CustomizableUITestUtils.jsm:80:41
22:28:27 INFO - openPanelMultiView@resource://testing-common/CustomizableUITestUtils.jsm:59:11
22:28:27 INFO - async
openMainMenu@resource://testing-common/CustomizableUITestUtils.jsm:79:11
22:28:27 INFO - async*@chrome://mochitests/content/browser/browser/base/content/test/performance/browser_appmenu.js:67:32
22:28:27 INFO - withPerfObserver@chrome://mochitests/content/browser/browser/base/content/test/performance/head.js:633:3
22:28:27 INFO - async*@chrome://mochitests/content/browser/browser/base/content/test/performance/browser_appmenu.js:67:9
22:28:27 INFO - AsyncTester_execTest/<@chrome://mochikit/content/browser-test.js:1106:34
22:28:27 INFO - async
Tester_execTest@chrome://mochikit/content/browser-test.js:1097:16
22:28:27 INFO - nextTest/<@chrome://mochikit/content/browser-test.js:995:9
22:28:27 INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:803:59

Flags: needinfo?(jaws)

(In reply to Stefan Hindli [:stefan_hindli] from comment #22)

Over the last 7 days there are 39 failures on this bug. All of the failures happen on osx-10-10.

I already diagnosed why that is, and I'm waiting on an answer from Neil to comment #20. Needinfo'ing extra people won't help.

Flags: needinfo?(jaws)

I'm having hard time to see how the test can work with popuppositioned, which is dispatched as a result of a reflow, and then, when the event is dispatched, the whole frame tree is marked dirty again.
And since bug 1506376 let's us trigger RefreshDriver more often, causing interruptible reflow, but also triggering popuppositioned firing (which dirties frame tree, causing reflow...)

https://searchfox.org/mozilla-central/rev/03ebbdab952409640c6857d835d3040bf6f9e2db/browser/base/content/test/performance/head.js#63-68

Posted patch less_frame_dirtying.diff (obsolete) — Splinter Review

https://treeherder.mozilla.org/#/jobs?repo=try&revision=d05b03fbed68d43d0fd9b9992cb1f4d5b0d59cb7

It is not super clear to me why we want addListenerForAllEvents usage here at
all, since that forces reflows even in cases where there wouldn't be such normally.
Especially any event which is dispatched because of a reflow won't work too well with that setup, if the event has listeners.
But this patch just filters out popuppositioned. Let's see what tryserver thinks about it. Locally tested only on Linux.

Assignee: nobody → bugs
Posted patch less_frame_dirtying_2.diff (obsolete) — Splinter Review
Attachment #9042651 - Attachment is obsolete: true
Posted patch less_frame_dirtying_3.diff (obsolete) — Splinter Review
Attachment #9042675 - Attachment is obsolete: true
Comment on attachment 9042701 [details] [diff] [review]
less_frame_dirtying_3.diff

Same as v2 but nicer minCount handling. Explicit minCount can be used to avoid the assertion about unused reflow.
Locally I get 0 reflows, but tryserver gives at least one.
Attachment #9042701 - Flags: review?(mconley)
Blocks: 1506376
Comment on attachment 9042701 [details] [diff] [review]
less_frame_dirtying_3.diff

Review of attachment 9042701 [details] [diff] [review]:
-----------------------------------------------------------------

Hey smaug,

I think I'm going to recommend that we just bump up the amount of expected popuppositioned reflows we get in browser_appmenu.js. It's annoying, but I think it gives us less room to accidentally introduce new layout flushes in the front-end in the future.

::: browser/base/content/test/performance/head.js
@@ +63,5 @@
>    let dirtyFrameFn = event => {
> +    // MozAfterPaint is triggered after RefreshDriver tick and
> +    // popuppositioned right after a reflow.
> +    if (event.type != "MozAfterPaint" &&
> +        event.type != "popuppositioned") {

I know that https://searchfox.org/mozilla-central/source/browser/base/content/test/performance/browser_appmenu.js#29 says that number should only ever go down, and never up...

However, I'd much prefer that we maintain as strict a list of allowed places where front-end can cause layout flushes as possible. I worry that having popuppositioned whitelisted means that we're adding a blind-spot for ourselves down the line (one can make the same argument for MozAfterPaint too, but that one was whitelisted for memory concerns with our flicker tests).

I think I'd much rather set https://searchfox.org/mozilla-central/source/browser/base/content/test/performance/browser_appmenu.js#29 at a higher value that is better represented of how many flushes might occur with the higher composite rate. Then we really need to get popup.xml off of alignmentPosition... (bug 1296442).

@@ +135,1 @@
>              actualStacks: new Map()};

We should probably default minCount to match maxCount if it isn't defined.
Attachment #9042701 - Flags: review?(mconley) → review-

17 seems to be the magic number.

Attachment #9042701 - Attachment is obsolete: true
Attachment #9043384 - Flags: review?(mconley)
Comment on attachment 9043384 [details] [diff] [review]
reflows_in_browser_appmenu.js.diff

Review of attachment 9043384 [details] [diff] [review]:
-----------------------------------------------------------------

Thanks! That scary "This number should only ever go down - never up." message is really more for front-end people to discourage adding more places that do layout flushes. I think this is a righteous increase.
Attachment #9043384 - Flags: review?(mconley) → review+
Pushed by opettay@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/aca48f57fb21
let more reflows happen while running browser_appmenu.js, r=mconley
Status: REOPENED → RESOLVED
Closed: 6 months ago5 months ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 67
See Also: → 1527550

oh, more reflows. Given the setup, it can be really anything. If something else is slow (for whatever reasons) but vsync is not, then we may get quite a few reflows.

Flags: needinfo?(bugs)

I'll increase the reflow number and discuss with mconley.

Pushed by opettay@mozilla.com:
https://hg.mozilla.org/integration/mozilla-inbound/rev/03c808feaf89
let more reflows happen while running browser_appmenu.js, r=testfailure

This is still happening: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=231628867&repo=mozilla-beta&lineNumber=978

05:45:01 INFO - TEST-PASS | browser/base/content/test/performance/browser_appmenu.js | The panel is closed to begin with. - "closed" == "closed" -
05:45:01 INFO - Buffered messages logged at 05:45:01
05:45:01 INFO - TEST-FAIL | browser/base/content/test/performance/browser_appmenu.js | known reflow at openPopup/this._openPopupPromise<@resource:///modules/PanelMultiView.jsm was encountered 1 times -
05:45:01 INFO - Full stack:
05:45:01 INFO - openPopup/this._openPopupPromise<@resource:///modules/PanelMultiView.jsm:520:9
05:45:01 INFO -
05:45:01 INFO - Buffered messages finished
05:45:01 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_appmenu.js | reflow at adjustArrowPosition@chrome://global/content/bindings/popup.xml was encountered 17 times,
05:45:01 INFO - it was expected to happen up to 3 times. - false == true - JS frame :: chrome://mochitests/content/browser/browser/base/content/test/performance/head.js :: reportUnexpectedReflows :: line 180
05:45:01 INFO - Stack trace:
05:45:01 INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/head.js:reportUnexpectedReflows:180
05:45:01 INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/head.js:withPerfObserver:637
05:45:01 INFO - Full stack (hit 17 times):
05:45:01 INFO - adjustArrowPosition@chrome://global/content/bindings/popup.xml:290:13
05:45:01 INFO - onxblpopuppositioned@chrome://global/content/bindings/popup.xml:389:9
05:45:01 INFO -
05:45:01 INFO - TEST-FAIL | browser/base/content/test/performance/browser_appmenu.js | known reflow at _calculateMaxHeight@resource:///modules/PanelMultiView.jsm was encountered 7 times -
05:45:01 INFO - Full stack:
05:45:01 INFO - _calculateMaxHeight@resource:///modules/PanelMultiView.jsm:1061:9
05:45:01 INFO - handleEvent@resource:///modules/PanelMultiView.jsm:1122:27
05:45:01 INFO -
05:45:01 INFO - Full stack:
05:45:01 INFO - _calculateMaxHeight@resource:///modules/PanelMultiView.jsm:1062:1
05:45:01 INFO - handleEvent@resource:///modules/PanelMultiView.jsm:1122:27
05:45:01 INFO -
05:45:01 INFO - Full stack:
05:45:01 INFO - _calculateMaxHeight@resource:///modules/PanelMultiView.jsm:1063:1
05:45:01 INFO - handleEvent@resource:///modules/PanelMultiView.jsm:1122:27
05:45:01 INFO -
05:45:01 INFO - Full stack:
05:45:01 INFO - _calculateMaxHeight@resource:///modules/PanelMultiView.jsm:1064:1
05:45:01 INFO - handleEvent@resource:///modules/PanelMultiView.jsm:1122:27
05:45:01 INFO -
05:45:01 INFO - Full stack:
05:45:01 INFO - _calculateMaxHeight@resource:///modules/PanelMultiView.jsm:1072:5
05:45:01 INFO - handleEvent@resource:///modules/PanelMultiView.jsm:1122:27
05:45:01 INFO -
05:45:01 INFO - Full stack (hit 2 times):
05:45:01 INFO - _calculateMaxHeight@resource:///modules/PanelMultiView.jsm:1075:11
05:45:01 INFO - handleEvent@resource:///modules/PanelMultiView.jsm:1122:27

Flags: needinfo?(bugs)

ok, then it is about something else than the behavior change which bug 1506376 would cause, since that got backed out.

Flags: needinfo?(bugs)
Flags: needinfo?(enndeakin)
You need to log in before you can comment on or make changes to this bug.