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

[task 2020-04-28T06:21:52.973Z] 06:21:52 INFO - TEST-START | browser/base/content/test/performance/browser_startup_syncIPC.js
[task 2020-04-28T06:21:52.998Z] 06:21:52 INFO - TEST-INFO | started process screenshot
[task 2020-04-28T06:21:53.078Z] 06:21:53 INFO - TEST-INFO | screenshot: exit 0
[task 2020-04-28T06:21:53.078Z] 06:21:53 INFO - Buffered messages logged at 06:21:52
[task 2020-04-28T06:21:53.078Z] 06:21:53 INFO - Entering test bound
[task 2020-04-28T06:21:53.078Z] 06:21:53 INFO - whitelisted sync IPC before first paint:
[task 2020-04-28T06:21:53.078Z] 06:21:53 INFO - PLayerTransaction::Msg_GetTextureFactoryIdentifier - at most 3 times
[task 2020-04-28T06:21:53.078Z] 06:21:53 INFO - PCompositorBridge::Msg_NotifyChildCreated - at most 2 times
[task 2020-04-28T06:21:53.078Z] 06:21:53 INFO - PCompositorBridge::Msg_MapAndNotifyChildCreated - at most 2 times
[task 2020-04-28T06:21:53.078Z] 06:21:53 INFO - PCompositorBridge::Msg_FlushRendering - at most 1 times
[task 2020-04-28T06:21:53.078Z] 06:21:53 INFO - PCompositorBridge::Msg_Initialize - at most 3 times
[task 2020-04-28T06:21:53.079Z] 06:21:53 INFO - PCompositorWidget::Msg_Initialize - at most 3 times
[task 2020-04-28T06:21:53.079Z] 06:21:53 INFO - PGPU::Msg_AddLayerTreeIdMapping - at most 5 times
[task 2020-04-28T06:21:53.079Z] 06:21:53 INFO - PCompositorBridge::Msg_MakeSnapshot - at most 1 times
[task 2020-04-28T06:21:53.079Z] 06:21:53 INFO - PCompositorBridge::Msg_WillClose - at most 2 times
[task 2020-04-28T06:21:53.079Z] 06:21:53 INFO - PAPZInputBridge::Msg_ProcessUnhandledEvent - at most 1 times
[task 2020-04-28T06:21:53.079Z] 06:21:53 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 2020-04-28T06:21:53.079Z] 06:21:53 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_NotifyChildCreated allowed 2 more times before first paint -
[task 2020-04-28T06:21:53.080Z] 06:21:53 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_MapAndNotifyChildCreated happened as many times as expected before first paint -
[task 2020-04-28T06:21:53.080Z] 06:21:53 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 2020-04-28T06:21:53.080Z] 06:21:53 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_Initialize allowed 1 more times before first paint -
[task 2020-04-28T06:21:53.080Z] 06:21:53 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorWidget::Msg_Initialize allowed 1 more times before first paint -
[task 2020-04-28T06:21:53.080Z] 06:21:53 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PGPU::Msg_AddLayerTreeIdMapping happened as many times as expected before first paint -
[task 2020-04-28T06:21:53.080Z] 06:21:53 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_MakeSnapshot allowed 1 more times before first paint -
[task 2020-04-28T06:21:53.080Z] 06:21:53 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_WillClose allowed 2 more times before first paint -
[task 2020-04-28T06:21:53.081Z] 06:21:53 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PAPZInputBridge::Msg_ProcessUnhandledEvent happened as many times as expected before first paint -
[task 2020-04-28T06:21:53.081Z] 06:21:53 INFO - whitelisted sync IPC before handling user events:
[task 2020-04-28T06:21:53.081Z] 06:21:53 INFO - PLayerTransaction::Msg_GetTextureFactoryIdentifier - at most 1 times
[task 2020-04-28T06:21:53.081Z] 06:21:53 INFO - PCompositorBridge::Msg_Initialize - at most 1 times
[task 2020-04-28T06:21:53.081Z] 06:21:53 INFO - PCompositorWidget::Msg_Initialize - at most 1 times
[task 2020-04-28T06:21:53.081Z] 06:21:53 INFO - PCompositorBridge::Msg_WillClose - at most 2 times
[task 2020-04-28T06:21:53.081Z] 06:21:53 INFO - PCompositorBridge::Msg_MakeSnapshot - at most 1 times
[task 2020-04-28T06:21:53.081Z] 06:21:53 INFO - PAPZInputBridge::Msg_ProcessUnhandledEvent - at most 1 times
[task 2020-04-28T06:21:53.081Z] 06:21:53 INFO - PAPZInputBridge::Msg_ReceiveMouseInputEvent - at most 1 times
[task 2020-04-28T06:21:53.081Z] 06:21:53 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PLayerTransaction::Msg_GetTextureFactoryIdentifier happened as many times as expected before handling user events -
[task 2020-04-28T06:21:53.082Z] 06:21:53 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_Initialize happened as many times as expected before handling user events -
[task 2020-04-28T06:21:53.082Z] 06:21:53 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorWidget::Msg_Initialize happened as many times as expected before handling user events -
[task 2020-04-28T06:21:53.082Z] 06:21:53 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_WillClose happened as many times as expected before handling user events -
[task 2020-04-28T06:21:53.082Z] 06:21:53 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_MakeSnapshot happened as many times as expected before handling user events -
[task 2020-04-28T06:21:53.082Z] 06:21:53 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PAPZInputBridge::Msg_ProcessUnhandledEvent happened as many times as expected before handling user events -
[task 2020-04-28T06:21:53.082Z] 06:21:53 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PAPZInputBridge::Msg_ReceiveMouseInputEvent happened as many times as expected before handling user events -
[task 2020-04-28T06:21:53.083Z] 06:21:53 INFO - whitelisted sync IPC before becoming idle:
[task 2020-04-28T06:21:53.083Z] 06:21:53 INFO - PCompositorBridge::Msg_NotifyChildCreated - at most 1 times
[task 2020-04-28T06:21:53.083Z] 06:21:53 INFO - PAPZInputBridge::Msg_ProcessUnhandledEvent - at most 1 times
[task 2020-04-28T06:21:53.083Z] 06:21:53 INFO - PAPZInputBridge::Msg_ReceiveMouseInputEvent - at most 1 times
[task 2020-04-28T06:21:53.083Z] 06:21:53 INFO - PCompositorBridge::Msg_MapAndNotifyChildCreated - at most 1 times
[task 2020-04-28T06:21:53.083Z] 06:21:53 INFO - PCompositorBridge::Msg_WillClose - at most 2 times
[task 2020-04-28T06:21:53.083Z] 06:21:53 INFO - Buffered messages finished
[task 2020-04-28T06:21:53.083Z] 06:21:53 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_syncIPC.js | unexpected PCompositorWidget::Msg_Initialize sync IPC before becoming idle -
[task 2020-04-28T06:21:53.083Z] 06:21:53 INFO - Stack trace:
[task 2020-04-28T06:21:53.083Z] 06:21:53 INFO - chrome://mochikit/content/browser-test.js:test_ok:1269
[task 2020-04-28T06:21:53.083Z] 06:21:53 INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_syncIPC.js:null:345
[task 2020-04-28T06:21:53.083Z] 06:21:53 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1039
[task 2020-04-28T06:21:53.084Z] 06:21:53 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1074
[task 2020-04-28T06:21:53.084Z] 06:21:53 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:904
[task 2020-04-28T06:21:53.084Z] 06:21:53 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:918
[task 2020-04-28T06:21:53.084Z] 06:21:53 INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-04-28T06:21:53.084Z] 06:21:53 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_syncIPC.js | unexpected PCompositorBridge::Msg_Initialize sync IPC before becoming idle -

Hey Arthur, seems this was filed in the wrong component, can you update it please? Thanks!

Hi Ptrick, sure. Thank you for letting me know.

Do we need more annotations for intermittent sync IPC message issues?

This is on a non-WebRender run, so moving to Layers. Looks like the three events:

PCompositorBridge::Msg_Initialize
PCompositorWidget::Msg_Initialize
PLayerTransaction::Msg_GetTextureFactoryIdentifier

happened in the "before idle" phase rather than the "before first paint" phase where they were expected to occur. Not sure why, but maybe ccov runs are really slow and so whatever window that was got delayed. If this happens again we can consider updating the annotations. So far it's only occurred once, not sure it's worth the effort to update the annotations.