Filed by: imoraru [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer?job_id=393295857&repo=try
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/Iwen7f4TQaWGSzz1OnUHCg/runs/0/artifacts/public/logs/live_backing.log

Observed in today's central-as-early-beta simulation, so far, it only failed as a [tier 2] on Linux 18.04 x64 WebRender DevEdition opt.

[task 2022-10-15T12:51:47.841Z] 12:51:47     INFO - TEST-START | browser/base/content/test/performance/browser_startup_syncIPC.js
[task 2022-10-15T12:51:47.864Z] 12:51:47     INFO - TEST-INFO | started process screentopng
[task 2022-10-15T12:51:48.053Z] 12:51:48     INFO - TEST-INFO | screentopng: exit 0
[task 2022-10-15T12:51:48.054Z] 12:51:48     INFO - Buffered messages logged at 12:51:47
[task 2022-10-15T12:51:48.054Z] 12:51:48     INFO - Entering test bound 
[task 2022-10-15T12:51:48.054Z] 12:51:48     INFO - known sync IPC before first paint:
[task 2022-10-15T12:51:48.054Z] 12:51:48     INFO -   PWebRenderBridge::Msg_EnsureConnected - at most 1 times
[task 2022-10-15T12:51:48.054Z] 12:51:48     INFO -   PCompositorBridge::Msg_NotifyChildCreated - at most 1 times
[task 2022-10-15T12:51:48.054Z] 12:51:48     INFO -   PCompositorBridge::Msg_Resume - at most 1 times
[task 2022-10-15T12:51:48.055Z] 12:51:48     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PWebRenderBridge::Msg_EnsureConnected happened as many times as expected before first paint - 
[task 2022-10-15T12:51:48.056Z] 12:51:48     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 2022-10-15T12:51:48.056Z] 12:51:48     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_Resume happened as many times as expected before first paint - 
[task 2022-10-15T12:51:48.056Z] 12:51:48     INFO - known sync IPC before handling user events:
[task 2022-10-15T12:51:48.056Z] 12:51:48     INFO -   PCompositorBridge::Msg_FlushRendering - at most 1 times
[task 2022-10-15T12:51:48.057Z] 12:51:48     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_FlushRendering allowed 1 but only happened 0 times before handling user events - 
[task 2022-10-15T12:51:48.059Z] 12:51:48     INFO - known sync IPC before becoming idle:
[task 2022-10-15T12:51:48.059Z] 12:51:48     INFO -   PCompositorBridge::Msg_NotifyChildCreated - at most 1 times
[task 2022-10-15T12:51:48.059Z] 12:51:48     INFO -   PLayerTransaction::Msg_GetTextureFactoryIdentifier - at most 1 times
[task 2022-10-15T12:51:48.059Z] 12:51:48     INFO -   PWebRenderBridge::Msg_EnsureConnected - at most 1 times
[task 2022-10-15T12:51:48.059Z] 12:51:48     INFO -   PCompositorBridge::Msg_FlushRendering - at most 1 times
[task 2022-10-15T12:51:48.060Z] 12:51:48     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_NotifyChildCreated allowed 1 but only happened 0 times before becoming idle - 
[task 2022-10-15T12:51:48.060Z] 12:51:48     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PLayerTransaction::Msg_GetTextureFactoryIdentifier allowed 1 but only happened 0 times before becoming idle - 
[task 2022-10-15T12:51:48.061Z] 12:51:48     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PWebRenderBridge::Msg_EnsureConnected allowed 1 but only happened 0 times before becoming idle - 
[task 2022-10-15T12:51:48.062Z] 12:51:48     INFO - Buffered messages finished
[task 2022-10-15T12:51:48.066Z] 12:51:48     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_FlushRendering happened 2 but max is 1 before becoming idle - 
[task 2022-10-15T12:51:48.066Z] 12:51:48     INFO - Stack trace:
[task 2022-10-15T12:51:48.067Z] 12:51:48     INFO - chrome://mochikit/content/browser-test.js:test_ok:1457
[task 2022-10-15T12:51:48.067Z] 12:51:48     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_syncIPC.js:null:407
[task 2022-10-15T12:51:48.068Z] 12:51:48     INFO - Not taking screenshot here: see the one that was previously logged
[task 2022-10-15T12:51:48.069Z] 12:51:48     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 2022-10-15T12:51:48.069Z] 12:51:48     INFO - Stack trace:
[task 2022-10-15T12:51:48.070Z] 12:51:48     INFO - chrome://mochikit/content/browser-test.js:test_ok:1457
[task 2022-10-15T12:51:48.070Z] 12:51:48     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_syncIPC.js:null:425
[task 2022-10-15T12:51:48.070Z] 12:51:48     INFO - Leaving test bound 
[task 2022-10-15T12:51:48.225Z] 12:51:48     INFO - GECKO(5577) | MEMORY STAT | vsize 11331MB | residentFast 377MB | heapAllocated 232MB
[task 2022-10-15T12:51:48.226Z] 12:51:48     INFO - TEST-OK | browser/base/content/test/performance/browser_startup_syncIPC.js | took 383ms
[task 2022-10-15T12:51:48.241Z] 12:51:48     INFO - checking window state
[task 2022-10-15T12:51:49.552Z] 12:51:49     INFO - GECKO(5577) | Completed ShutdownLeaks collections in process 5730
[task 2022-10-15T12:51:49.598Z] 12:51:49     INFO - GECKO(5577) | Completed ShutdownLeaks collections in process 5665
[task 2022-10-15T12:51:49.601Z] 12:51:49     INFO - GECKO(5577) | Completed ShutdownLeaks collections in process 5728
[task 2022-10-15T12:51:49.640Z] 12:51:49     INFO - GECKO(5577) | Completed ShutdownLeaks collections in process 5639
[task 2022-10-15T12:51:49.965Z] 12:51:49     INFO - GECKO(5577) | Completed ShutdownLeaks collections in process 5577
[task 2022-10-15T12:51:49.965Z] 12:51:49     INFO - TEST-START | Shutdown
[task 2022-10-15T12:51:49.965Z] 12:51:49     INFO - Browser Chrome Test Summary
[task 2022-10-15T12:51:49.967Z] 12:51:49     INFO - Passed:  13
[task 2022-10-15T12:51:49.968Z] 12:51:49     INFO - Failed:  2
[task 2022-10-15T12:51:49.970Z] 12:51:49     INFO - Todo:    1
[task 2022-10-15T12:51:49.976Z] 12:51:49     INFO - Mode:    e10s
[task 2022-10-15T12:51:49.977Z] 12:51:49     INFO - *** End BrowserChrome Test Results ***

This has started to fail frequently, according to our R+B range, from here: https://treeherder.mozilla.org/jobs?repo=autoland&selectedTaskRun=Wp5HNcdOREOLrC1qdz64jw.0&resultStatus=success%2Ctestfailed%2Cbusted%2Cexception%2Cretry%2Cusercancel&searchStr=linux%2C18.04%2Cx64%2Cwebrender%2Copt%2Cmochitests%2Cwith%2Csoftware%2Cwebrender%2Cenabled%2Ctest-linux1804-64-qr%2Fopt-mochitest-browser-chrome-swr%2Cbc1&tochange=3f63f21115e28d9cc2244984941105eb31d21a99&fromchange=2f1eb518f202df27967ed111753910331864ffaf
Olli, could you please take a look at this?

Set release status flags based on info from the regressing bug 1804295

Locally on linux the test fails even without my patch. It looks like a very racy test. Investigating.

The test is rather racy. I had to add the new entry for PCompositorBridge::Msg_Resume to make it ever pass locally (even without my recent patch), and
it isn't guaranteed when PCompositorBridge::Msg_FlushRendering happens.

https://hg.mozilla.org/mozilla-central/rev/4d38a714a054

Removing 'regressed by', since that part is now fixed, but this bug was filed way before bug 1804295 and the test seems to have some scheduling assumptions which may not be always quite right.

The Bugbug bot thinks this bug should belong to the 'Core::DOM: Performance' component, and is moving the bug to that component. Please correct in case you think the bot is wrong.