Closed Bug 1580390 Opened 1 year ago Closed 4 months ago

Intermittent browser/base/content/test/performance/browser_startup_syncIPC.js | unused whitelist entry before handling user events: PLayerTransaction::Msg_GetTextureFactoryIdentifier -

Categories

(Firefox :: General, defect, P2)

defect

Tracking

()

VERIFIED FIXED
Firefox 78
Tracking Status
firefox-esr68 --- unaffected
firefox75 --- unaffected
firefox76 --- unaffected
firefox77 --- fixed
firefox78 + verified

People

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

References

Details

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

Attachments

(1 file)

Filed by: opoprus [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=266009477&repo=mozilla-central
Full log: https://queue.taskcluster.net/v1/task/JkSOSz7KQXCpBQG8VLBAFQ/runs/0/artifacts/public/logs/live_backing.log


[task 2019-09-10T22:53:56.959Z] 22:53:56 INFO - TEST-START | browser/base/content/test/performance/browser_startup_syncIPC.js
[task 2019-09-10T22:53:56.974Z] 22:53:56 INFO - TEST-INFO | started process screenshot
[task 2019-09-10T22:53:57.034Z] 22:53:57 INFO - TEST-INFO | screenshot: exit 0
[task 2019-09-10T22:53:57.034Z] 22:53:57 INFO - Buffered messages logged at 22:53:56
[task 2019-09-10T22:53:57.036Z] 22:53:57 INFO - Entering test bound
[task 2019-09-10T22:53:57.036Z] 22:53:57 INFO - whitelisted sync IPC before first paint:
[task 2019-09-10T22:53:57.036Z] 22:53:57 INFO - PLayerTransaction::Msg_GetTextureFactoryIdentifier - at most 3 times
[task 2019-09-10T22:53:57.037Z] 22:53:57 INFO - PCompositorBridge::Msg_NotifyChildCreated - at most 2 times
[task 2019-09-10T22:53:57.037Z] 22:53:57 INFO - PCompositorBridge::Msg_MapAndNotifyChildCreated - at most 2 times
[task 2019-09-10T22:53:57.037Z] 22:53:57 INFO - PCompositorBridge::Msg_FlushRendering - at most 1 times
[task 2019-09-10T22:53:57.037Z] 22:53:57 INFO - PCompositorBridge::Msg_Initialize - at most 3 times
[task 2019-09-10T22:53:57.037Z] 22:53:57 INFO - PGPU::Msg_AddLayerTreeIdMapping - at most 5 times
[task 2019-09-10T22:53:57.037Z] 22:53:57 INFO - PCompositorBridge::Msg_MakeSnapshot - at most 1 times
[task 2019-09-10T22:53:57.037Z] 22:53:57 INFO - PCompositorBridge::Msg_WillClose - at most 2 times
[task 2019-09-10T22:53:57.037Z] 22:53:57 INFO - PAPZInputBridge::Msg_ProcessUnhandledEvent - at most 1 times
[task 2019-09-10T22:53:57.037Z] 22:53:57 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PLayerTransaction::Msg_GetTextureFactoryIdentifier allowed 1 more times before first paint -
[task 2019-09-10T22:53:57.038Z] 22:53:57 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_NotifyChildCreated happened as many times as expected before first paint -
[task 2019-09-10T22:53:57.038Z] 22:53:57 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_MapAndNotifyChildCreated allowed 2 more times before first paint -
[task 2019-09-10T22:53:57.038Z] 22:53:57 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_FlushRendering happened as many times as expected before first paint -
[task 2019-09-10T22:53:57.038Z] 22:53:57 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_Initialize allowed 3 more times before first paint -
[task 2019-09-10T22:53:57.039Z] 22:53:57 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PGPU::Msg_AddLayerTreeIdMapping allowed 5 more times before first paint -
[task 2019-09-10T22:53:57.039Z] 22:53:57 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_MakeSnapshot happened as many times as expected before first paint -
[task 2019-09-10T22:53:57.040Z] 22:53:57 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_WillClose allowed 1 more times before first paint -
[task 2019-09-10T22:53:57.040Z] 22:53:57 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PAPZInputBridge::Msg_ProcessUnhandledEvent allowed 1 more times before first paint -
[task 2019-09-10T22:53:57.040Z] 22:53:57 INFO - whitelisted sync IPC before handling user events:
[task 2019-09-10T22:53:57.041Z] 22:53:57 INFO - PLayerTransaction::Msg_GetTextureFactoryIdentifier - at most 1 times
[task 2019-09-10T22:53:57.041Z] 22:53:57 INFO - PCompositorBridge::Msg_Initialize - at most 1 times
[task 2019-09-10T22:53:57.041Z] 22:53:57 INFO - PCompositorBridge::Msg_WillClose - at most 2 times
[task 2019-09-10T22:53:57.041Z] 22:53:57 INFO - PCompositorBridge::Msg_MakeSnapshot - at most 1 times
[task 2019-09-10T22:53:57.041Z] 22:53:57 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PLayerTransaction::Msg_GetTextureFactoryIdentifier allowed 1 more times before handling user events -
[task 2019-09-10T22:53:57.041Z] 22:53:57 INFO - Buffered messages finished
[task 2019-09-10T22:53:57.041Z] 22:53:57 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_syncIPC.js | unused whitelist entry before handling user events: PLayerTransaction::Msg_GetTextureFactoryIdentifier -
[task 2019-09-10T22:53:57.041Z] 22:53:57 INFO - Stack trace:
[task 2019-09-10T22:53:57.041Z] 22:53:57 INFO - chrome://mochikit/content/browser-test.js:test_ok:1580
[task 2019-09-10T22:53:57.041Z] 22:53:57 INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_syncIPC.js:null:344
[task 2019-09-10T22:53:57.041Z] 22:53:57 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1350
[task 2019-09-10T22:53:57.041Z] 22:53:57 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1385
[task 2019-09-10T22:53:57.041Z] 22:53:57 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1213
[task 2019-09-10T22:53:57.041Z] 22:53:57 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:805
[task 2019-09-10T22:53:57.042Z] 22:53:57 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_Initialize allowed 1 more times before handling user events -
[task 2019-09-10T22:53:57.042Z] 22:53:57 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_WillClose allowed 2 more times before handling user events -
[task 2019-09-10T22:53:57.042Z] 22:53:57 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_MakeSnapshot allowed 1 more times before handling user events -
[task 2019-09-10T22:53:57.042Z] 22:53:57 INFO - whitelisted sync IPC before becoming idle:
[task 2019-09-10T22:53:57.042Z] 22:53:57 INFO - PCompositorBridge::Msg_NotifyChildCreated - at most 1 times
[task 2019-09-10T22:53:57.042Z] 22:53:57 INFO - PAPZInputBridge::Msg_ProcessUnhandledEvent - at most 1 times
[task 2019-09-10T22:53:57.042Z] 22:53:57 INFO - PAPZInputBridge::Msg_ReceiveMouseInputEvent - at most 1 times
[task 2019-09-10T22:53:57.042Z] 22:53:57 INFO - PCompositorBridge::Msg_MapAndNotifyChildCreated - at most 1 times
[task 2019-09-10T22:53:57.042Z] 22:53:57 INFO - PCompositorBridge::Msg_WillClose - at most 2 times
[task 2019-09-10T22:53:57.042Z] 22:53:57 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-09-10T22:53:57.043Z] 22:53:57 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_syncIPC.js | unexpected PLayerTransaction::Msg_GetTextureFactoryIdentifier sync IPC before becoming idle -
[task 2019-09-10T22:53:57.043Z] 22:53:57 INFO - Stack trace:
[task 2019-09-10T22:53:57.043Z] 22:53:57 INFO - chrome://mochikit/content/browser-test.js:test_ok:1580
[task 2019-09-10T22:53:57.043Z] 22:53:57 INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_syncIPC.js:null:326
[task 2019-09-10T22:53:57.043Z] 22:53:57 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1350
[task 2019-09-10T22:53:57.043Z] 22:53:57 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1385
[task 2019-09-10T22:53:57.043Z] 22:53:57 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1213
[task 2019-09-10T22:53:57.043Z] 22:53:57 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:805
[task 2019-09-10T22:53:57.043Z] 22:53:57 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_NotifyChildCreated happened as many times as expected before becoming idle -
[task 2019-09-10T22:53:57.043Z] 22:53:57 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PAPZInputBridge::Msg_ProcessUnhandledEvent allowed 1 more times before becoming idle -
[task 2019-09-10T22:53:57.043Z] 22:53:57 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PAPZInputBridge::Msg_ReceiveMouseInputEvent allowed 1 more times before becoming idle -
[task 2019-09-10T22:53:57.043Z] 22:53:57 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_MapAndNotifyChildCreated allowed 1 more times before becoming idle -
[task 2019-09-10T22:53:57.044Z] 22:53:57 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_WillClose allowed 2 more times before becoming idle -
[task 2019-09-10T22:53:57.051Z] 22:53:57 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-09-10T22:53:57.051Z] 22:53:57 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_syncIPC.js | Unexpected sync IPC behavior during startup; open the profile_startup_syncIPC.json artifact in the Firefox Profiler to see what happened -
[task 2019-09-10T22:53:57.051Z] 22:53:57 INFO - Stack trace:
[task 2019-09-10T22:53:57.051Z] 22:53:57 INFO - chrome://mochikit/content/browser-test.js:test_ok:1580
[task 2019-09-10T22:53:57.051Z] 22:53:57 INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_syncIPC.js:null:363
[task 2019-09-10T22:53:57.051Z] 22:53:57 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1350
[task 2019-09-10T22:53:57.051Z] 22:53:57 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1385
[task 2019-09-10T22:53:57.051Z] 22:53:57 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1213
[task 2019-09-10T22:53:57.051Z] 22:53:57 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:805
[task 2019-09-10T22:53:57.051Z] 22:53:57 INFO - Leaving test bound
[task 2019-09-10T22:53:57.058Z] 22:53:57 INFO - GECKO(2968) | JavaScript error: resource://testing-common/PromiseTestUtils.jsm, line 112: uncaught exception: Object
[task 2019-09-10T22:53:57.058Z] 22:53:57 INFO - Console message: [JavaScript Error: "uncaught exception: Object" {file: "resource://testing-common/PromiseTestUtils.jsm" line: 112}]
[task 2019-09-10T22:53:57.073Z] 22:53:57 INFO - GECKO(2968) | MEMORY STAT | vsize 803MB | vsizeMaxContiguous 540MB | residentFast 272MB | heapAllocated 145MB
[task 2019-09-10T22:53:57.073Z] 22:53:57 INFO - TEST-OK | browser/base/content/test/performance/browser_startup_syncIPC.js | took 109ms
[task 2019-09-10T22:53:57.108Z] 22:53:57 INFO - checking window state
[task 2019-09-10T22:53:58.529Z] 22:53:58 INFO - GECKO(2968) | Completed ShutdownLeaks collections in process 5052
[task 2019-09-10T22:53:58.532Z] 22:53:58 INFO - GECKO(2968) | Completed ShutdownLeaks collections in process 4828
[task 2019-09-10T22:53:58.539Z] 22:53:58 INFO - GECKO(2968) | Completed ShutdownLeaks collections in process 1012
[task 2019-09-10T22:53:58.554Z] 22:53:58 INFO - GECKO(2968) | Completed ShutdownLeaks collections in process 5180
[task 2019-09-10T22:53:58.554Z] 22:53:58 INFO - GECKO(2968) | Completed ShutdownLeaks collections in process 4916
[task 2019-09-10T22:53:58.569Z] 22:53:58 INFO - GECKO(2968) | Completed ShutdownLeaks collections in process 4416
[task 2019-09-10T22:53:59.264Z] 22:53:59 INFO - GECKO(2968) | Completed ShutdownLeaks collections in process 1720
[task 2019-09-10T22:53:59.264Z] 22:53:59 INFO - TEST-START | Shutdown

Status: NEW → RESOLVED
Closed: 1 year ago
Resolution: --- → INCOMPLETE

New occurrence:

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Status: REOPENED → RESOLVED
Closed: 1 year ago9 months ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Whiteboard: [stockwell needswork:owner]

This fails permanently on Windows DevEdition on beta and started to fail in daily beta simulations on May 1st but got classified against this bug. Changelog April 30th to May 1st: https://hg.mozilla.org/mozilla-central/pushloghtml?fromchange=83beb87d9f6945ccddefe62341b5536398eb72a0&tochange=29e888a9270c6d38ffaa30efd0d297f5163613f1

Test source: https://searchfox.org/mozilla-central/source/browser/base/content/test/performance/browser_startup_syncIPC.js

Florian, any idea what change is causing this?

Flags: needinfo?(florian)
Summary: Intermittent browser/base/content/test/performance/browser_startup_syncIPC.js | unused whitelist entry before handling user events: PLayerTransaction::Msg_GetTextureFactoryIdentifier - → Perma beta Windows DevEdition browser/base/content/test/performance/browser_startup_syncIPC.js | unused whitelist entry before handling user events: PLayerTransaction::Msg_GetTextureFactoryIdentifier -

It's not exactly permanently - failed 1/2 Windows DevEdition runs today.

Summary: Perma beta Windows DevEdition browser/base/content/test/performance/browser_startup_syncIPC.js | unused whitelist entry before handling user events: PLayerTransaction::Msg_GetTextureFactoryIdentifier - → Very frequent beta Windows DevEdition browser/base/content/test/performance/browser_startup_syncIPC.js | unused whitelist entry before handling user events: PLayerTransaction::Msg_GetTextureFactoryIdentifier -

Changing the priority to p2 as the bug is tracked by a release manager for the current nightly.
See What Do You Triage for more information

Priority: P5 → P2

(In reply to Sebastian Hengst [:aryx] (needinfo on intermittent or backout) from comment #20)

This fails permanently on Windows DevEdition on beta and started to fail in daily beta simulations on May 1st but got classified against this bug.

This test doesn't actually run on beta (except dev edition builds) : https://searchfox.org/mozilla-central/rev/446160560bf32ebf4cb7c4e25d7386ee22667255/browser/base/content/test/performance/browser_startup_syncIPC.js#277-288

Florian, any idea what change is causing this?

Likely a change in timing, there's a race between the 10 idle callbacks at https://searchfox.org/mozilla-central/rev/446160560bf32ebf4cb7c4e25d7386ee22667255/browser/components/tests/startupRecorder.js#178,180 and whatever is happening during actual browser startup. We keep adding more stuff to _scheduleStartupIdleTasks in BrowserGlue.jsm, so 10 idle callbacks might not be enough anymore to capture all of the startup idle tasks.

I would like to make this recording more reliable, here's an attempt to replace the racy code that's surprisingly green on try: https://treeherder.mozilla.org/#/jobs?repo=try&revision=8e791131d19abf618cbb56122ba88a45606f165f

We'll still need to adjust the whitelist in the test to make it pass for the case in this bug.

Duplicate of this bug: 1633686
Summary: Very frequent beta Windows DevEdition browser/base/content/test/performance/browser_startup_syncIPC.js | unused whitelist entry before handling user events: PLayerTransaction::Msg_GetTextureFactoryIdentifier - → Intermittent browser/base/content/test/performance/browser_startup_syncIPC.js | unused whitelist entry before handling user events: PLayerTransaction::Msg_GetTextureFactoryIdentifier -
Depends on: 1637603
Assignee: nobody → florian
Pushed by fqueze@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/a836a04739ec
fix sync IPC whitelist entries for PLayerTransaction::Msg_GetTextureFactoryIdentifier, PCompositorBridge::Msg_Initialize and PCompositorWidget::Msg_Initialize, r=emalysz.
Pushed by fqueze@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/cb3d6fc3c2fa
fix sync IPC whitelist entries for PLayerTransaction::Msg_GetTextureFactoryIdentifier, PCompositorBridge::Msg_Initialize and PCompositorWidget::Msg_Initialize, r=emalysz.
Status: REOPENED → RESOLVED
Closed: 9 months ago4 months ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 78
Flags: needinfo?(florian)
Flags: needinfo?(dolske)
Whiteboard: [stockwell disable-recommended] → [stockwell fixed]

Intermittent Failures chart verifies it's gone.

Status: RESOLVED → VERIFIED
You need to log in before you can comment on or make changes to this bug.