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

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

New occurrence:

New occurrence:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=282189935&repo=mozilla-central&lineNumber=1926

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup
For more information, please visit auto_nag documentation.

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

Justin, failure rate for this issue has increased, also affecting the beta simulations:
https://treeherder.mozilla.org/#/jobs?repo=try&revision=8f5f67d8f7c51ed505dff429ef3e34d1e7ffec9d&searchStr=windows%2C7%2Cdevedition%2Copt%2Cmochitests%2Ctest-windows7-32-devedition%2Fopt-mochitest-browser-chrome-e10s-4%2Cm%28bc4%29&selectedTaskRun=Qh4rkD1ERjGBj_WIH8u7EQ-0

Could you please redirect this to someone who can take a look?

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?

[Tracking Requested - why for this release]:

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

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

(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.

Depends on D75102

Backed out 4 changesets (bug 1580390, bug 1637603, bug 1629824) for Browser-chrome failures in performance/browser_startup_images.js. CLOSED TREE

Log:
https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=302310802&repo=autoland&lineNumber=16761

Push with failures:
https://treeherder.mozilla.org/#/jobs?repo=autoland&group_state=expanded&revision=7a0696cf87a3256f13dbeddb620ed783f4dbeb90

Backout:
https://hg.mozilla.org/integration/autoland/rev/8714cc14400550c3ef4f69b8b6ef8d844e830a93

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

https://hg.mozilla.org/releases/mozilla-beta/rev/232f10b09b19

Intermittent Failures chart verifies it's gone.