Closed Bug 1585574 Opened 6 years ago Closed 5 years ago

Intermittent browser/base/content/test/performance/browser_startup_syncIPC.js | unexpected PCompositorBridge::Msg_MakeSnapshot sync IPC before becoming idle - | Unexpected sync IPC behavior during startup; open the profile_startup_syncIPC.json artifact in

Categories

(Firefox :: General, defect, P5)

Product:
Firefox
Component:
General
Type:
defect

Tracking

()

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure, regression)

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

[task 2019-10-02T06:18:20.287Z] 06:18:20 INFO - TEST-START | browser/base/content/test/performance/browser_startup_syncIPC.js
[task 2019-10-02T06:18:20.290Z] 06:18:20 INFO - TEST-INFO | started process screenshot
[task 2019-10-02T06:18:20.360Z] 06:18:20 INFO - TEST-INFO | screenshot: exit 0
[task 2019-10-02T06:18:20.361Z] 06:18:20 INFO - Buffered messages logged at 06:18:20
[task 2019-10-02T06:18:20.361Z] 06:18:20 INFO - Entering test bound
[task 2019-10-02T06:18:20.362Z] 06:18:20 INFO - whitelisted sync IPC before first paint:
[task 2019-10-02T06:18:20.362Z] 06:18:20 INFO - PLayerTransaction::Msg_GetTextureFactoryIdentifier - at most 3 times
[task 2019-10-02T06:18:20.362Z] 06:18:20 INFO - PCompositorBridge::Msg_NotifyChildCreated - at most 2 times
[task 2019-10-02T06:18:20.363Z] 06:18:20 INFO - PCompositorBridge::Msg_MapAndNotifyChildCreated - at most 2 times
[task 2019-10-02T06:18:20.363Z] 06:18:20 INFO - PCompositorBridge::Msg_FlushRendering - at most 1 times
[task 2019-10-02T06:18:20.363Z] 06:18:20 INFO - PCompositorBridge::Msg_Initialize - at most 3 times
[task 2019-10-02T06:18:20.363Z] 06:18:20 INFO - PGPU::Msg_AddLayerTreeIdMapping - at most 5 times
[task 2019-10-02T06:18:20.363Z] 06:18:20 INFO - PCompositorBridge::Msg_MakeSnapshot - at most 1 times
[task 2019-10-02T06:18:20.363Z] 06:18:20 INFO - PCompositorBridge::Msg_WillClose - at most 2 times
[task 2019-10-02T06:18:20.364Z] 06:18:20 INFO - PAPZInputBridge::Msg_ProcessUnhandledEvent - at most 1 times
[task 2019-10-02T06:18:20.364Z] 06:18:20 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-10-02T06:18:20.364Z] 06:18:20 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-10-02T06:18:20.365Z] 06:18:20 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-10-02T06:18:20.365Z] 06:18:20 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-10-02T06:18:20.365Z] 06:18:20 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-10-02T06:18:20.365Z] 06:18:20 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-10-02T06:18:20.366Z] 06:18:20 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 2019-10-02T06:18:20.366Z] 06:18:20 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 2019-10-02T06:18:20.366Z] 06:18:20 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-10-02T06:18:20.366Z] 06:18:20 INFO - whitelisted sync IPC before handling user events:
[task 2019-10-02T06:18:20.366Z] 06:18:20 INFO - PLayerTransaction::Msg_GetTextureFactoryIdentifier - at most 1 times
[task 2019-10-02T06:18:20.366Z] 06:18:20 INFO - PCompositorBridge::Msg_Initialize - at most 1 times
[task 2019-10-02T06:18:20.367Z] 06:18:20 INFO - PCompositorBridge::Msg_WillClose - at most 2 times
[task 2019-10-02T06:18:20.367Z] 06:18:20 INFO - PCompositorBridge::Msg_MakeSnapshot - at most 1 times
[task 2019-10-02T06:18:20.367Z] 06:18:20 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 2019-10-02T06:18:20.367Z] 06:18:20 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-10-02T06:18:20.367Z] 06:18:20 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-10-02T06:18:20.368Z] 06:18:20 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-10-02T06:18:20.368Z] 06:18:20 INFO - whitelisted sync IPC before becoming idle:
[task 2019-10-02T06:18:20.368Z] 06:18:20 INFO - PCompositorBridge::Msg_NotifyChildCreated - at most 1 times
[task 2019-10-02T06:18:20.368Z] 06:18:20 INFO - PAPZInputBridge::Msg_ProcessUnhandledEvent - at most 1 times
[task 2019-10-02T06:18:20.368Z] 06:18:20 INFO - PAPZInputBridge::Msg_ReceiveMouseInputEvent - at most 1 times
[task 2019-10-02T06:18:20.368Z] 06:18:20 INFO - PCompositorBridge::Msg_MapAndNotifyChildCreated - at most 1 times
[task 2019-10-02T06:18:20.368Z] 06:18:20 INFO - PCompositorBridge::Msg_WillClose - at most 2 times
[task 2019-10-02T06:18:20.368Z] 06:18:20 INFO - Buffered messages finished
[task 2019-10-02T06:18:20.369Z] 06:18:20 INFO - TEST-UNEXPECTED-FAIL | browser/base/content/test/performance/browser_startup_syncIPC.js | unexpected PCompositorBridge::Msg_MakeSnapshot sync IPC before becoming idle -
[task 2019-10-02T06:18:20.369Z] 06:18:20 INFO - Stack trace:
[task 2019-10-02T06:18:20.369Z] 06:18:20 INFO - chrome://mochikit/content/browser-test.js:test_ok:1580
[task 2019-10-02T06:18:20.369Z] 06:18:20 INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_syncIPC.js:null:326
[task 2019-10-02T06:18:20.369Z] 06:18:20 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1350
[task 2019-10-02T06:18:20.369Z] 06:18:20 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1385
[task 2019-10-02T06:18:20.369Z] 06:18:20 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1213
[task 2019-10-02T06:18:20.369Z] 06:18:20 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:805
[task 2019-10-02T06:18:20.370Z] 06:18:20 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-10-02T06:18:20.370Z] 06:18:20 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-10-02T06:18:20.370Z] 06:18:20 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-10-02T06:18:20.370Z] 06:18:20 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-10-02T06:18:20.370Z] 06:18:20 INFO - TEST-PASS | browser/base/content/test/performance/browser_startup_syncIPC.js | sync IPC PCompositorBridge::Msg_WillClose allowed 1 more times before becoming idle -
[task 2019-10-02T06:18:20.370Z] 06:18:20 INFO - Not taking screenshot here: see the one that was previously logged
[task 2019-10-02T06:18:20.370Z] 06:18:20 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-10-02T06:18:20.370Z] 06:18:20 INFO - Stack trace:
[task 2019-10-02T06:18:20.370Z] 06:18:20 INFO - chrome://mochikit/content/browser-test.js:test_ok:1580
[task 2019-10-02T06:18:20.370Z] 06:18:20 INFO - chrome://mochitests/content/browser/browser/base/content/test/performance/browser_startup_syncIPC.js:null:363
[task 2019-10-02T06:18:20.371Z] 06:18:20 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest/<:1350
[task 2019-10-02T06:18:20.371Z] 06:18:20 INFO - chrome://mochikit/content/browser-test.js:Tester_execTest:1385
[task 2019-10-02T06:18:20.371Z] 06:18:20 INFO - chrome://mochikit/content/browser-test.js:nextTest/<:1213
[task 2019-10-02T06:18:20.371Z] 06:18:20 INFO - chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<:805
[task 2019-10-02T06:18:20.371Z] 06:18:20 INFO - Leaving test bound
[task 2019-10-02T06:18:20.378Z] 06:18:20 INFO - GECKO(1136) | MEMORY STAT | vsize 789MB | vsizeMaxContiguous 604MB | residentFast 279MB | heapAllocated 148MB
[task 2019-10-02T06:18:20.379Z] 06:18:20 INFO - TEST-OK | browser/base/content/test/performance/browser_startup_syncIPC.js | took 95ms
[task 2019-10-02T06:18:20.406Z] 06:18:20 INFO - checking window state
[task 2019-10-02T06:18:21.804Z] 06:18:21 INFO - GECKO(1136) | Completed ShutdownLeaks collections in process 2464
[task 2019-10-02T06:18:21.819Z] 06:18:21 INFO - GECKO(1136) | Completed ShutdownLeaks collections in process 5712
[task 2019-10-02T06:18:21.819Z] 06:18:21 INFO - GECKO(1136) | Completed ShutdownLeaks collections in process 5272
[task 2019-10-02T06:18:21.834Z] 06:18:21 INFO - GECKO(1136) | Completed ShutdownLeaks collections in process 5032
[task 2019-10-02T06:18:21.834Z] 06:18:21 INFO - GECKO(1136) | Completed ShutdownLeaks collections in process 4072
[task 2019-10-02T06:18:21.849Z] 06:18:21 INFO - GECKO(1136) | Completed ShutdownLeaks collections in process 3264
[task 2019-10-02T06:18:22.509Z] 06:18:22 INFO - GECKO(1136) | Completed ShutdownLeaks collections in process 5260
[task 2019-10-02T06:18:22.509Z] 06:18:22 INFO - TEST-START | Shutdown
[task 2019-10-02T06:18:22.509Z] 06:18:22 INFO - Browser Chrome Test Summary
[task 2019-10-02T06:18:22.510Z] 06:18:22 INFO - Passed: 148
[task 2019-10-02T06:18:22.510Z] 06:18:22 INFO - Failed: 2
[task 2019-10-02T06:18:22.510Z] 06:18:22 INFO - Todo: 1
[task 2019-10-02T06:18:22.510Z] 06:18:22 INFO - Mode: e10s
[task 2019-10-02T06:18:22.510Z] 06:18:22 INFO - *** End BrowserChrome Test Results ***

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

Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=273984679&repo=autoland&lineNumber=1239

Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---

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

Status: REOPENED → RESOLVED
Closed: 5 years ago → 5 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.