Closed Bug 1633371 Opened 5 years ago Closed 5 years ago

Intermittent devtools/client/performance/test/browser_perf-options-invert-call-tree-01.js | Test timed out -

Categories

(DevTools :: Performance Tools (Profiler/Timeline), defect, P5)

Product:
DevTools
Component:
Performance Tools (Profiler/Timeline)
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

Details

(Keywords: intermittent-failure)

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

[task 2020-04-27T10:26:42.828Z] 10:26:42     INFO - TEST-OK | devtools/client/performance/test/browser_perf-options-flatten-tree-recursion-02.js | took 4269ms
[task 2020-04-27T10:26:42.908Z] 10:26:42     INFO - checking window state
[task 2020-04-27T10:26:42.967Z] 10:26:42     INFO - TEST-START | devtools/client/performance/test/browser_perf-options-invert-call-tree-01.js
[task 2020-04-27T10:26:42.988Z] 10:26:42     INFO - GECKO(1268) | Adding tab with url: http://example.com/browser/devtools/client/performance/test/doc_simple-test.html#1396938652602184.
[task 2020-04-27T10:26:43.415Z] 10:26:43     INFO - GECKO(1268) | Initializing a performance panel.
[task 2020-04-27T10:26:44.758Z] 10:26:44     INFO - GECKO(1268) | Waiting for event: 'Performance:BackendReadyRecordingStart' on [object PerformanceController] for 1 time(s).
[task 2020-04-27T10:26:44.758Z] 10:26:44     INFO - GECKO(1268) | Waiting for event: 'Performance:RecordingStateChange' on [object PerformanceController] for 1 time(s) with arguments: ["recording-started"].
[task 2020-04-27T10:26:44.758Z] 10:26:44     INFO - GECKO(1268) | Waiting for event: 'Performance:UI:StateChanged' on [object PerformanceView] for 1 time(s) with arguments: [{}].
[task 2020-04-27T10:26:44.758Z] 10:26:44     INFO - GECKO(1268) | Waiting for event: 'Performance:UI:OverviewRendered' on [object OverviewView] for 1 time(s) with arguments: [100].
[task 2020-04-27T10:26:44.858Z] 10:26:44     INFO - GECKO(1268) | Event: 'Performance:UI:StateChanged' on [object PerformanceView] received.
[task 2020-04-27T10:26:44.937Z] 10:26:44     INFO - GECKO(1268) | Event: 'Performance:RecordingStateChange' on [object PerformanceController] received.
[task 2020-04-27T10:26:44.958Z] 10:26:44     INFO - GECKO(1268) | Event: 'Performance:BackendReadyRecordingStart' on [object PerformanceController] received.
[task 2020-04-27T10:26:45.273Z] 10:26:45     INFO - GECKO(1268) | Event: 'Performance:UI:OverviewRendered' on [object OverviewView] received.
[task 2020-04-27T10:26:45.273Z] 10:26:45     INFO - GECKO(1268) | Waiting for event: 'Performance:BackendReadyRecordingStop' on [object PerformanceController] for 1 time(s).
[task 2020-04-27T10:26:45.273Z] 10:26:45     INFO - GECKO(1268) | Waiting for event: 'Performance:RecordingStateChange' on [object PerformanceController] for 1 time(s) with arguments: ["recording-stopping"].
[task 2020-04-27T10:26:45.274Z] 10:26:45     INFO - GECKO(1268) | Waiting for event: 'Performance:RecordingStateChange' on [object PerformanceController] for 1 time(s) with arguments: ["recording-stopped"].
[task 2020-04-27T10:26:45.274Z] 10:26:45     INFO - GECKO(1268) | Waiting for event: 'Performance:UI:StateChanged' on [object PerformanceView] for 1 time(s) with arguments: ["recorded"].
[task 2020-04-27T10:26:45.274Z] 10:26:45     INFO - GECKO(1268) | Waiting for event: 'Performance:UI:OverviewRendered' on [object OverviewView] for 1 time(s) with arguments: [16].
[task 2020-04-27T10:26:45.274Z] 10:26:45     INFO - GECKO(1268) | Waiting for event: 'Performance:UI:WaterfallRendered' on [object WaterfallView] for 1 time(s).
[task 2020-04-27T10:26:45.518Z] 10:26:45     INFO - GECKO(1268) | Ignoring event 'Performance:UI:OverviewRendered' with unexpected argument at index 0: 100 - expected 16
[task 2020-04-27T10:26:45.799Z] 10:26:45     INFO - GECKO(1268) | Ignoring event 'Performance:UI:OverviewRendered' with unexpected argument at index 0: 100 - expected 16
[task 2020-04-27T10:26:46.046Z] 10:26:46     INFO - GECKO(1268) | Ignoring event 'Performance:UI:OverviewRendered' with unexpected argument at index 0: 100 - expected 16
<...>
[task 2020-04-27T10:31:12.278Z] 10:31:12     INFO - GECKO(1268) | Ignoring event 'Performance:UI:OverviewRendered' with unexpected argument at index 0: 100 - expected 16
[task 2020-04-27T10:31:12.521Z] 10:31:12     INFO - GECKO(1268) | Ignoring event 'Performance:UI:OverviewRendered' with unexpected argument at index 0: 100 - expected 16
[task 2020-04-27T10:31:12.763Z] 10:31:12     INFO - GECKO(1268) | Ignoring event 'Performance:UI:OverviewRendered' with unexpected argument at index 0: 100 - expected 16
[task 2020-04-27T10:31:13.003Z] 10:31:13     INFO - GECKO(1268) | Ignoring event 'Performance:UI:OverviewRendered' with unexpected argument at index 0: 100 - expected 16
[task 2020-04-27T10:31:13.064Z] 10:31:13     INFO - TEST-INFO | started process screenshot
[task 2020-04-27T10:31:13.273Z] 10:31:13     INFO - TEST-INFO | screenshot: exit 0
[task 2020-04-27T10:31:13.273Z] 10:31:13     INFO - Buffered messages logged at 10:26:42
[task 2020-04-27T10:31:13.273Z] 10:31:13     INFO - Entering test bound 
[task 2020-04-27T10:31:13.273Z] 10:31:13     INFO - Buffered messages logged at 10:27:12
[task 2020-04-27T10:31:13.273Z] 10:31:13     INFO - Console message: [JavaScript Error: "Unknown Collection "main/messaging-experiments"" {file: "resource://services-settings/RemoteSettingsClient.jsm" line: 137}]
[task 2020-04-27T10:31:13.273Z] 10:31:13     INFO - UnknownCollectionError@resource://services-settings/RemoteSettingsClient.jsm:137:5
[task 2020-04-27T10:31:13.273Z] 10:31:13     INFO - sync@resource://services-settings/RemoteSettingsClient.jsm:373:13
[task 2020-04-27T10:31:13.273Z] 10:31:13     INFO - async*get@resource://services-settings/RemoteSettingsClient.jsm:315:22
[task 2020-04-27T10:31:13.273Z] 10:31:13     INFO - async*updateRecipes@resource://messaging-system/lib/RemoteSettingsExperimentLoader.jsm:141:49
[task 2020-04-27T10:31:13.273Z] 10:31:13     INFO - setTimer/<@resource://messaging-system/lib/RemoteSettingsExperimentLoader.jsm:188:18
[task 2020-04-27T10:31:13.273Z] 10:31:13     INFO - TM_notify/</<@resource://gre/modules/UpdateTimerManager.jsm:257:36
[task 2020-04-27T10:31:13.274Z] 10:31:13     INFO - ChromeUtils::IdleDispatch handler*TM_notify/<@resource://gre/modules/UpdateTimerManager.jsm:255:25
[task 2020-04-27T10:31:13.274Z] 10:31:13     INFO - TM_notify@resource://gre/modules/UpdateTimerManager.jsm:290:7
[task 2020-04-27T10:31:13.274Z] 10:31:13     INFO - 
[task 2020-04-27T10:31:13.274Z] 10:31:13     INFO - Buffered messages logged at 10:28:13
[task 2020-04-27T10:31:13.274Z] 10:31:13     INFO - Longer timeout required, waiting longer...  Remaining timeouts: 2
[task 2020-04-27T10:31:13.274Z] 10:31:13     INFO - Buffered messages logged at 10:29:43
[task 2020-04-27T10:31:13.274Z] 10:31:13     INFO - Longer timeout required, waiting longer...  Remaining timeouts: 1
[task 2020-04-27T10:31:13.274Z] 10:31:13     INFO - Buffered messages finished
[task 2020-04-27T10:31:13.274Z] 10:31:13     INFO - TEST-UNEXPECTED-FAIL | devtools/client/performance/test/browser_perf-options-invert-call-tree-01.js | Test timed out - 
[task 2020-04-27T10:31:13.274Z] 10:31:13     INFO - finish() was called, cleaning up...
[task 2020-04-27T10:31:13.932Z] 10:31:13     INFO - GECKO(1268) | MEMORY STAT | vsize 19406401MB | vsizeMaxContiguous 66122310MB | residentFast 3322MB
[task 2020-04-27T10:31:13.932Z] 10:31:13     INFO - TEST-OK | devtools/client/performance/test/browser_perf-options-invert-call-tree-01.js | took 270959ms
[task 2020-04-27T10:31:13.932Z] 10:31:13     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-04-27T10:31:13.932Z] 10:31:13     INFO - TEST-UNEXPECTED-FAIL | devtools/client/performance/test/browser_perf-options-invert-call-tree-01.js | Found a tab after previous test timed out: http://example.com/browser/devtools/client/performance/test/doc_simple-test.html#1396938652602184 - 
[task 2020-04-27T10:31:14.062Z] 10:31:14     INFO - checking window state
[task 2020-04-27T10:31:14.122Z] 10:31:14     INFO - GECKO(1268) | console.error: "Exception when calling onAvailable handler" "Connection closed, pending request to server0.conn12.child2/accessibilityActor15, type getSimulator failed\n\nRequest stack:\nrequest@resource://devtools/shared/protocol/Front.js:256:14\ngenerateRequestMethods/</frontProto[name]@resource://devtools/shared/protocol/Front/FrontClassWithSpec.js:47:19\nbootstrap@resource://devtools/client/fronts/accessibility.js:244:39\nasync*_updateTarget/this._updatePromise<@resource://devtools/client/accessibility/accessibility-proxy.js:344:37\nasync*_updateTarget@resource://devtools/client/accessibility/accessibility-proxy.js:353:7\n_onTargetAvailable@resource://devtools/client/accessibility/accessibility-proxy.js:291:18\nwatchTargets/promises<@resource://devtools/shared/resources/target-list.js:499:17\nwatchTargets@resource://devtools/shared/resources/target-list.js:494:8\ninitialize@resource://devtools/client/accessibility/accessibility-proxy.js:255:37\ninitAccessibility/this._initAccessibility<@resource://devtools/client/accessibility/accessibility-startup.js:44:35\nAsync*initAccessibility@resource://devtools/client/accessibility/accessibility-startup.js:57:19\nAccessibilityStartup@resource://devtools/client/accessibility/accessibility-startup.js:22:10\nbuildToolStartup@resource://devtools/client/definitions.js:457:12\n_buildPanelForTool@resource://devtools/client/framework/toolbox.js:2243:49\n_buildTabs/<@resource://devtools/client/framework/toolbox.js:1774:44\n_buildTabs@resource://devtools/client/framework/toolbox.js:1774:17\nopen/<@resource://devtools/client/framework/toolbox.js:846:12\nAsync*open@resource://devtools/client/framework/toolbox.js:956:18\ncreateToolbox@resource://devtools/client/framework/devtools.js:622:19\nasync*showToolbox@resource://devtools/client/framework/devtools.js:509:35\nexports.initPanelInTab@resource://devtools/client/performance/test/helpers/panel-utils.js:36:35\nasync*exports.initPerformanceInTab@resource://devtools/client/performance/test/helpers/panel-utils.js:56:18\nexports.initPerformanceInNewTab@resource://devtools/client/performance/test/helpers/panel-utils.js:49:18\nasync*@chrome://mochitests/content/browser/devtools/client/performance/test/browser_perf-options-invert-call-tree-01.js:26:27\nTester_execTest/<@chrome://mochikit/content/browser-test.js:1039:34\nTester_execTest@chrome://mochikit/content/browser-test.js:1074:11\nnextTest/<@chrome://mochikit/content/browser-test.js:904:14\nSimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:918:23\n" (new Error("Connection closed, pending request to server0.conn12.child2/accessibilityActor15, type getSimulator failed\n\nRequest stack:\nrequest@resource://devtools/shared/protocol/Front.js:256:14\ngenerateRequestMethods/</frontProto[name]@resource://devtools/shared/protocol/Front/FrontClassWithSpec.js:47:19\nbootstrap@resource://devtools/client/fronts/accessibility.js:244:39\nasync*_updateTarget/this._updatePromise<@resource://devtools/client/accessibility/accessibility-proxy.js:344:37\nasync*_updateTarget@resource://devtools/client/accessibility/accessibility-proxy.js:353:7\n_onTargetAvailable@resource://devtools/client/accessibility/accessibility-proxy.js:291:18\nwatchTargets/promises<@resource://devtools/shared/resources/target-list.js:499:17\nwatchTargets@resource://devtools/shared/resources/target-list.js:494:8\ninitialize@resource://devtools/client/accessibility/accessibility-proxy.js:255:37\ninitAccessibility/this._initAccessibility<@resource://devtools/client/accessibility/accessibility-startup.js:44:35\nAsync*initAccessibility@resource://devtools/client/accessibility/accessibility-startup.js:57:19\nAccessibilityStartup@resource://devtools/client/accessibility/accessibility-startup.js:22:10\nbuildToolStartup@resource://devtools/client/definitions.js:457:12\n_buildPanelForTool@resource://devtools/client/framework/toolbox.js:2243:49\n_buildTabs/<@resource://devtools/client/framework/toolbox.js:1774:44\n_buildTabs@resource://devtools/client/framework/toolbox.js:1774:17\nopen/<@resource://devtools/client/framework/toolbox.js:846:12\nAsync*open@resource://devtools/client/framework/toolbox.js:956:18\ncreateToolbox@resource://devtools/client/framework/devtools.js:622:19\nasync*showToolbox@resource://devtools/client/framework/devtools.js:509:35\nexports.initPanelInTab@resource://devtools/client/performance/test/helpers/panel-utils.js:36:35\nasync*exports.initPerformanceInTab@resource://devtools/client/performance/test/helpers/panel-utils.js:56:18\nexports.initPerformanceInNewTab@resource://devtools/client/performance/test/helpers/panel-utils.js:49:18\nasync*@chrome://mochitests/content/browser/devtools/client/performance/test/browser_perf-options-invert-call-tree-01.js:26:27\nTester_execTest/<@chrome://mochikit/content/browser-test.js:1039:34\nTester_execTest@chrome://mochikit/content/browser-test.js:1074:11\nnextTest/<@chrome://mochikit/content/browser-test.js:904:14\nSimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:918:23\n", "resource://devtools/shared/protocol/Front.js", 77))
[task 2020-04-27T10:31:14.122Z] 10:31:14     INFO - Not taking screenshot here: see the one that was previously logged
[task 2020-04-27T10:31:14.122Z] 10:31:14     INFO - TEST-UNEXPECTED-FAIL | devtools/client/performance/test/browser_perf-options-invert-call-tree-01.js | Uncaught exception received from previously timed out test - at resource://devtools/shared/protocol/Front.js:77 - Error: Connection closed, pending request to server0.conn12.child2/performanceActor10, type stopRecording failed
[task 2020-04-27T10:31:14.122Z] 10:31:14     INFO - 
[task 2020-04-27T10:31:14.122Z] 10:31:14     INFO - Request stack:
[task 2020-04-27T10:31:14.123Z] 10:31:14     INFO - request@resource://devtools/shared/protocol/Front.js:256:14
[task 2020-04-27T10:31:14.123Z] 10:31:14     INFO - generateRequestMethods/</frontProto[name]@resource://devtools/shared/protocol/Front/FrontClassWithSpec.js:47:19
[task 2020-04-27T10:31:14.123Z] 10:31:14     INFO - stopRecording@resource://devtools/client/performance/performance-controller.js:257:24
[task 2020-04-27T10:31:14.123Z] 10:31:14     INFO - exports.stopRecording@resource://devtools/client/performance/test/helpers/actions.js:35:16
[task 2020-04-27T10:31:14.123Z] 10:31:14     INFO - @chrome://mochitests/content/browser/devtools/client/performance/test/browser_perf-options-invert-call-tree-01.js:36:9
[task 2020-04-27T10:31:14.123Z] 10:31:14     INFO - Async*Tester_execTest/<@chrome://mochikit/content/browser-test.js:1039:34
[task 2020-04-27T10:31:14.123Z] 10:31:14     INFO - Tester_execTest@chrome://mochikit/content/browser-test.js:1074:11
[task 2020-04-27T10:31:14.123Z] 10:31:14     INFO - nextTest/<@chrome://mochikit/content/browser-test.js:904:14
[task 2020-04-27T10:31:14.123Z] 10:31:14     INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:918:23
[task 2020-04-27T10:31:14.123Z] 10:31:14     INFO - 
[task 2020-04-27T10:31:14.123Z] 10:31:14     INFO - Stack trace:
[task 2020-04-27T10:31:14.123Z] 10:31:14     INFO - destroy@resource://devtools/shared/protocol/Front.js:77:23
[task 2020-04-27T10:31:14.123Z] 10:31:14     INFO - _destroyTarget@resource://devtools/client/fronts/targets/target-mixin.js:437:15
[task 2020-04-27T10:31:14.123Z] 10:31:14     INFO - destroy@resource://devtools/client/fronts/targets/target-mixin.js:422:12
[task 2020-04-27T10:31:14.123Z] 10:31:14     INFO - destroy@resource://devtools/client/fronts/targets/browsing-context.js:133:27
[task 2020-04-27T10:31:14.123Z] 10:31:14     INFO - _emit@resource://devtools/shared/event-emitter.js:226:34
[task 2020-04-27T10:31:14.123Z] 10:31:14     INFO - emit@resource://devtools/shared/event-emitter.js:172:18
[task 2020-04-27T10:31:14.123Z] 10:31:14     INFO - emit@resource://devtools/shared/event-emitter.js:324:18
[task 2020-04-27T10:31:14.123Z] 10:31:14     INFO - onPacket@resource://devtools/shared/protocol/Front.js:294:13
[task 2020-04-27T10:31:14.123Z] 10:31:14     INFO - onPacket@resource://devtools/client/devtools-client.js:493:13
[task 2020-04-27T10:31:14.123Z] 10:31:14     INFO - send/<@resource://devtools/shared/transport/local-transport.js:68:25
[task 2020-04-27T10:31:14.123Z] 10:31:14     INFO - exports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:103:22
[task 2020-04-27T10:31:14.123Z] 10:31:14     INFO - DevToolsUtils.executeSoon*exports.executeSoon@resource://devtools/shared/DevToolsUtils.js:47:21
[task 2020-04-27T10:31:14.124Z] 10:31:14     INFO - send@resource://devtools/shared/transport/local-transport.js:56:21
[task 2020-04-27T10:31:14.124Z] 10:31:14     INFO - send@resource://devtools/server/devtools-server-connection.js:91:20
[task 2020-04-27T10:31:14.124Z] 10:31:14     INFO - connectToFrame/</destroy<@resource://devtools/server/connectors/frame-connector.js:270:20
[task 2020-04-27T10:31:14.124Z] 10:31:14     INFO - exports.makeInfallible/<@resource://devtools/shared/ThreadSafeDevToolsUtils.js:103:22
[task 2020-04-27T10:31:14.124Z] 10:31:14     INFO - onMessageManagerClose@resource://devtools/server/connectors/frame-connector.js:288:9
[task 2020-04-27T10:31:14.124Z] 10:31:14     INFO - _endRemoveTab@chrome://browser/content/tabbrowser.js:3759:15
[task 2020-04-27T10:31:14.124Z] 10:31:14     INFO - removeTab@chrome://browser/content/tabbrowser.js:3402:14
[task 2020-04-27T10:31:14.124Z] 10:31:14     INFO - Tester_waitForWindowsState@chrome://mochikit/content/browser-test.js:401:18
[task 2020-04-27T10:31:14.124Z] 10:31:14     INFO - nextTest@chrome://mochikit/content/browser-test.js:800:10
[task 2020-04-27T10:31:14.124Z] 10:31:14     INFO - async*timeoutFn@chrome://mochikit/content/browser-test.js:1160:18
[task 2020-04-27T10:31:14.124Z] 10:31:14     INFO - setTimeout handler*SimpleTest_setTimeoutShim@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:788:41
[task 2020-04-27T10:31:14.124Z] 10:31:14     INFO - timeoutFn@chrome://mochikit/content/browser-test.js:1128:52
[task 2020-04-27T10:31:14.124Z] 10:31:14     INFO - setTimeout handler*SimpleTest_setTimeoutShim@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:788:41
[task 2020-04-27T10:31:14.124Z] 10:31:14     INFO - timeoutFn@chrome://mochikit/content/browser-test.js:1128:52
[task 2020-04-27T10:31:14.124Z] 10:31:14     INFO - setTimeout handler*Tester_execTest@chrome://mochikit/content/browser-test.js:1107:80
[task 2020-04-27T10:31:14.124Z] 10:31:14     INFO - nextTest/<@chrome://mochikit/content/browser-test.js:904:14
[task 2020-04-27T10:31:14.124Z] 10:31:14     INFO - SimpleTest.waitForFocus/waitForFocusInner/focusedOrLoaded/<@chrome://mochikit/content/tests/SimpleTest/SimpleTest.js:918:23
[task 2020-04-27T10:31:14.145Z] 10:31:14     INFO - TEST-START | devtools/client/performance/test/browser_perf-options-invert-call-tree-02.js
[task 2020-04-27T10:31:14.164Z] 10:31:14     INFO - GECKO(1268) | Adding tab with url: http://example.com/browser/devtools/client/performance/test/doc_simple-test.html#8458313082997246.

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
You need to log in before you can comment on or make changes to this bug.