Closed Bug 1489259 Opened 6 years ago Closed 6 years ago

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

Categories

(Firefox :: Menus, defect, P5)

Product:
Firefox
Component:
Menus
Type:
defect

Tracking

()

Status:
RESOLVED FIXED
Milestone:
Firefox 67
Tracking Flags:
Tracking Status
firefox67 --- fixed

People

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

References

Details

(Keywords: intermittent-failure, Whiteboard: [retriggered])

Attachments

(1 file, 4 obsolete files)

reflows_in_browser_appmenu.js.diff
807 bytes, patch
mconley
: review+
Details | Diff | Splinter Review
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: 6 years ago
Resolution: --- → INCOMPLETE

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup

Status: REOPENED → RESOLVED
Closed: 6 years ago → 6 years 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 callbackopenPopup@resource:///modules/PanelMultiView.jsm:486:37
22:28:27 INFO - asyncopenPopup@resource:///modules/PanelMultiView.jsm:272:47
22:28:27 INFO - asyncshow/<@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 - asyncopenMainMenu@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 - asyncTester_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

Attached 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
Attached 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

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

Status: REOPENED → RESOLVED
Closed: 6 years ago → 6 years ago
status-firefox67: --- → fixed
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)

Before my patch we were skipping some popuppositioned events, so it's
not unexpected that this count can go up as a result.

Pushed by emilio@crisal.io: https://hg.mozilla.org/integration/autoland/rev/aa49cdc20ff4 Increase the number of allowed reflows in browser_appmenu.js.

Comment on attachment 9179616 [details]
Bug 1489259 - Increase the number of allowed reflows in browser_appmenu.js. r=mconley,gijs

Revision D92444 was moved to bug 1666497. Setting attachment 9179616 [details] to obsolete.

Attachment #9179616 - Attachment is obsolete: true

Err, wrong bug :(

Backed out for conflicting with the backout of Bug 1666497

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

Attachment

General

Creator:
Created:
Updated:
Size: