Open Bug 1715331 Opened 5 years ago Updated 4 years ago

Permanent DevEdition browser/base/content/test/performance/browser_startup_syncIPC.js | unexpected PWebRenderBridge::Msg_EnsureConnected sync IPC before becoming idle -

Categories

(Core :: Graphics, defect, P5)

defect

Tracking

()

People

(Reporter: intermittent-bug-filer, Unassigned, NeedInfo)

References

(Blocks 1 open bug)

Details

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

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


Observed both for today's central-as-early-beta and for the the late beta simulation, all with macOS DevEdition.

[task 2021-06-08T13:08:40.671Z] 13:08:40     INFO - TEST-START | browser/base/content/test/performance/browser_startup_syncIPC.js
[task 2021-06-08T13:08:40.677Z] 13:08:40     INFO - TEST-INFO | started process screencapture
[task 2021-06-08T13:08:40.796Z] 13:08:40     INFO - TEST-INFO | screencapture: exit 0
[task 2021-06-08T13:08:40.797Z] 13:08:40     INFO - Buffered messages logged at 13:08:40
[task 2021-06-08T13:08:40.797Z] 13:08:40     INFO - Entering test bound 
[task 2021-06-08T13:08:40.798Z] 13:08:40     INFO - known sync IPC before first paint:
[task 2021-06-08T13:08:40.798Z] 13:08:40     INFO -   PWebRenderBridge::Msg_EnsureConnected - at most 1 times
[task 2021-06-08T13:08:40.798Z] 13:08:40     INFO -   PCompositorBridge::Msg_NotifyChildCreated - at most 1 times
[task 2021-06-08T13:08:40.798Z] 13:08:40     INFO -   PCompositorBridge::Msg_FlushRendering - at most 1 times
[task 2021-06-08T13:08:40.799Z] 13:08:40     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 2021-06-08T13:08:40.799Z] 13:08:40     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 2021-06-08T13:08:40.800Z] 13:08:40     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 2021-06-08T13:08:40.800Z] 13:08:40     INFO - known sync IPC before handling user events:
[task 2021-06-08T13:08:40.800Z] 13:08:40     INFO -   PCompositorBridge::Msg_FlushRendering - at most 1 times
[task 2021-06-08T13:08:40.801Z] 13:08:40     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_FlushRendering allowed 1 more times before handling user events - 
[task 2021-06-08T13:08:40.801Z] 13:08:40     INFO - known sync IPC before becoming idle:
[task 2021-06-08T13:08:40.801Z] 13:08:40     INFO -   PCompositorBridge::Msg_NotifyChildCreated - at most 1 times
[task 2021-06-08T13:08:40.802Z] 13:08:40     INFO -   PCompositorBridge::Msg_FlushRendering - at most 1 times
[task 2021-06-08T13:08:40.802Z] 13:08:40     INFO - Buffered messages finished
[task 2021-06-08T13:08:40.802Z] 13:08:40     INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_syncIPC.js | unexpected PWebRenderBridge::Msg_EnsureConnected sync IPC before becoming idle - 
[task 2021-06-08T13:08:40.802Z] 13:08:40     INFO - Stack trace:
[task 2021-06-08T13:08:40.803Z] 13:08:40     INFO - chrome://mochikit/content/browser-test.js:test_ok:1334
[task 2021-06-08T13:08:40.803Z] 13:08:40     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_syncIPC.js:null:375
[task 2021-06-08T13:08:40.803Z] 13:08:40     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_NotifyChildCreated allowed 1 more times before becoming idle - 
[task 2021-06-08T13:08:40.803Z] 13:08:40     INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_FlushRendering allowed 1 more times before becoming idle - 
[task 2021-06-08T13:08:40.804Z] 13:08:40     INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-06-08T13:08:40.805Z] 13:08:40     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 2021-06-08T13:08:40.805Z] 13:08:40     INFO - Stack trace:
[task 2021-06-08T13:08:40.805Z] 13:08:40     INFO - chrome://mochikit/content/browser-test.js:test_ok:1334
[task 2021-06-08T13:08:40.805Z] 13:08:40     INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_syncIPC.js:null:412
[task 2021-06-08T13:08:40.805Z] 13:08:40     INFO - Leaving test bound 
See Also: → 1716213

Dave, this along with Bug 1716213 are failing frequently on beta sims,
could you please take a look?

Flags: needinfo?(dtownsend)
Flags: needinfo?(dtownsend) → needinfo?(florian)

Here is a profile from a failed run: https://share.firefox.dev/3wfwDNi

We are blocked twice on a PWebRenderBridge::Msg_EnsureConnected sync IPC. Andrew, do you know if this is an expected behavior?

Flags: needinfo?(florian) → needinfo?(aosmond)

Recent failures here are on Beta and try
Recent log: https://treeherder.mozilla.org/logviewer?job_id=345934663&repo=mozilla-beta&lineNumber=2426

[task 2021-07-21T20:59:32.931Z] 20:59:32 INFO - TEST-START | browser/base/content/test/performance/browser_startup_syncIPC.js
[task 2021-07-21T20:59:32.938Z] 20:59:32 INFO - TEST-INFO | started process screencapture
[task 2021-07-21T20:59:33.055Z] 20:59:33 INFO - TEST-INFO | screencapture: exit 0
[task 2021-07-21T20:59:33.055Z] 20:59:33 INFO - Buffered messages logged at 20:59:32
[task 2021-07-21T20:59:33.055Z] 20:59:33 INFO - Entering test bound
[task 2021-07-21T20:59:33.056Z] 20:59:33 INFO - known sync IPC before first paint:
[task 2021-07-21T20:59:33.056Z] 20:59:33 INFO - PWebRenderBridge::Msg_EnsureConnected - at most 1 times
[task 2021-07-21T20:59:33.056Z] 20:59:33 INFO - PCompositorBridge::Msg_NotifyChildCreated - at most 1 times
[task 2021-07-21T20:59:33.056Z] 20:59:33 INFO - PCompositorBridge::Msg_FlushRendering - at most 1 times
[task 2021-07-21T20:59:33.057Z] 20:59:33 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 2021-07-21T20:59:33.057Z] 20:59:33 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 2021-07-21T20:59:33.058Z] 20:59:33 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 2021-07-21T20:59:33.058Z] 20:59:33 INFO - known sync IPC before handling user events:
[task 2021-07-21T20:59:33.059Z] 20:59:33 INFO - PCompositorBridge::Msg_FlushRendering - at most 1 times
[task 2021-07-21T20:59:33.059Z] 20:59:33 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_FlushRendering allowed 1 more times before handling user events -
[task 2021-07-21T20:59:33.060Z] 20:59:33 INFO - known sync IPC before becoming idle:
[task 2021-07-21T20:59:33.060Z] 20:59:33 INFO - PCompositorBridge::Msg_NotifyChildCreated - at most 1 times
[task 2021-07-21T20:59:33.060Z] 20:59:33 INFO - PCompositorBridge::Msg_FlushRendering - at most 1 times
[task 2021-07-21T20:59:33.060Z] 20:59:33 INFO - Buffered messages finished
[task 2021-07-21T20:59:33.061Z] 20:59:33 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_syncIPC.js | unexpected PWebRenderBridge::Msg_EnsureConnected sync IPC before becoming idle -
[task 2021-07-21T20:59:33.061Z] 20:59:33 INFO - Stack trace:
[task 2021-07-21T20:59:33.061Z] 20:59:33 INFO - chrome://mochikit/content/browser-test.js:test_ok:1326
[task 2021-07-21T20:59:33.061Z] 20:59:33 INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_syncIPC.js:null:375
[task 2021-07-21T20:59:33.061Z] 20:59:33 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_NotifyChildCreated allowed 1 more times before becoming idle -
[task 2021-07-21T20:59:33.062Z] 20:59:33 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_FlushRendering allowed 1 more times before becoming idle -
[task 2021-07-21T20:59:33.062Z] 20:59:33 INFO - Not taking screenshot here: see the one that was previously logged
[task 2021-07-21T20:59:33.063Z] 20:59:33 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 2021-07-21T20:59:33.063Z] 20:59:33 INFO - Stack trace:
[task 2021-07-21T20:59:33.063Z] 20:59:33 INFO - chrome://mochikit/content/browser-test.js:test_ok:1326
[task 2021-07-21T20:59:33.063Z] 20:59:33 INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_syncIPC.js:null:412
[task 2021-07-21T20:59:33.064Z] 20:59:33 INFO - Leaving test bound
[task 2021-07-21T20:59:33.064Z] 20:59:33 INFO - GECKO(1425) | MEMORY STAT | vsize 7199MB | residentFast 308MB | heapAllocated 158MB
[task 2021-07-21T20:59:33.065Z] 20:59:33 INFO - TEST-OK | browser/base/content/test/performance/browser_startup_syncIPC.js | took 37ms
[task 2021-07-21T20:59:33.065Z] 20:59:33 INFO - checking window state
[task 2021-07-21T20:59:34.274Z] 20:59:34 INFO - GECKO(1425) | Completed ShutdownLeaks collections in process 1433
[task 2021-07-21T20:59:34.274Z] 20:59:34 INFO - GECKO(1425) | Completed ShutdownLeaks collections in process 1427
[task 2021-07-21T20:59:34.275Z] 20:59:34 INFO - GECKO(1425) | Completed ShutdownLeaks collections in process 1428
[task 2021-07-21T20:59:34.279Z] 20:59:34 INFO - GECKO(1425) | Completed ShutdownLeaks collections in process 1426
[task 2021-07-21T20:59:34.466Z] 20:59:34 INFO - GECKO(1425) | Completed ShutdownLeaks collections in process 1425

Whiteboard: [stockwell needswork:owner]
Regressions: 1721846
Summary: Intermittent browser/base/content/test/performance/browser_startup_syncIPC.js | unexpected PWebRenderBridge::Msg_EnsureConnected sync IPC before becoming idle - → Permanent macOS DevEdition browser/base/content/test/performance/browser_startup_syncIPC.js | unexpected PWebRenderBridge::Msg_EnsureConnected sync IPC before becoming idle -

Recent failures here are on mozilla-beta and try.

The affected Try pushes are central-as-beta simulations.

This is also permafailing on linux devedition, failures on that platform were tracked in Bug 1716213.

Summary: Permanent macOS DevEdition browser/base/content/test/performance/browser_startup_syncIPC.js | unexpected PWebRenderBridge::Msg_EnsureConnected sync IPC before becoming idle - → Permanent DevEdition browser/base/content/test/performance/browser_startup_syncIPC.js | unexpected PWebRenderBridge::Msg_EnsureConnected sync IPC before becoming idle -

Andrew, can you investigate this permanent Linux + macOS DevEdition failure?

See Also: → 1739615

Hey, just a reminder to take a look at this bug when you have a chance. Thanks!

Component: General → IPC
Product: Firefox → Core

This looks like it's something to do with graphics; the artifacts from the flagged test runs seem to have all expired, but comment #6 mentions PWebRenderBridge::EnsureConnected and links to a profile which also has a long-running PCompositorBridge::FlushRendering.

Component: IPC → Graphics
You need to log in before you can comment on or make changes to this bug.