1573971 - Intermittent Tier 2 devtools/client/performance/test/browser_perf-options-propagate-profiler.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort.

Status: RESOLVED INCOMPLETE

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

Description

[Treeherder Bug Filer]

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

---

[task 2019-08-14T20:35:00.622Z] 20:35:00 INFO - TEST-START | devtools/client/performance/test/browser_perf-options-propagate-profiler.js
[task 2019-08-14T20:35:00.660Z] 20:35:00 INFO - GECKO(8308) | Adding tab with url: http://example.com/browser/devtools/client/performance/test/doc_simple-test.html#6975204308340048.
[task 2019-08-14T20:35:00.679Z] 20:35:00 INFO - GECKO(8308) | ++DOCSHELL 000001D0CD37A800 == 2 [pid = 9516] [id = {a27f8250-f151-4487-a5fc-299b7a1bae29}]
[task 2019-08-14T20:35:00.679Z] 20:35:00 INFO - GECKO(8308) | ++DOMWINDOW == 3 (000001D0D14DB5C0) [pid = 9516] [serial = 116] [outer = 0000000000000000]
[task 2019-08-14T20:35:00.679Z] 20:35:00 INFO - GECKO(8308) | ++DOMWINDOW == 4 (000001D0CD3D1C00) [pid = 9516] [serial = 117] [outer = 000001D0D14DB5C0]
[task 2019-08-14T20:35:00.698Z] 20:35:00 INFO - GECKO(8308) | [Child 9516, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 664
[task 2019-08-14T20:35:00.707Z] 20:35:00 INFO - GECKO(8308) | [Child 9516, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 664
[task 2019-08-14T20:35:00.732Z] 20:35:00 INFO - GECKO(8308) | [Parent 4348, Main Thread] WARNING: Constructing RangeBoundary with invalid value: 'mRef || aOffset == 0', file z:/build/build/src/obj-firefox/dist/include\mozilla/RangeBoundary.h, line 79
[task 2019-08-14T20:35:00.732Z] 20:35:00 INFO - GECKO(8308) | [Parent 4348, Main Thread] WARNING: Constructing RangeBoundary with invalid value: 'mRef || aOffset == 0', file z:/build/build/src/obj-firefox/dist/include\mozilla/RangeBoundary.h, line 79
[task 2019-08-14T20:35:01.008Z] 20:35:01 INFO - GECKO(8308) | ++DOMWINDOW == 5 (000001D0D3C83800) [pid = 9516] [serial = 118] [outer = 000001D0D14DB5C0]
[task 2019-08-14T20:35:01.191Z] 20:35:01 INFO - GECKO(8308) | Initializing a performance panel.
[task 2019-08-14T20:35:01.411Z] 20:35:01 INFO - GECKO(8308) | ++DOCSHELL 00000198C1468000 == 7 [pid = 4348] [id = {c1f4ca79-5d4c-4b1f-9203-c9d5cf8766dd}]
[task 2019-08-14T20:35:01.411Z] 20:35:01 INFO - GECKO(8308) | ++DOMWINDOW == 23 (00000198CB6E3020) [pid = 4348] [serial = 423] [outer = 0000000000000000]
[task 2019-08-14T20:35:01.416Z] 20:35:01 INFO - GECKO(8308) | ++DOMWINDOW == 24 (00000198CB6CB000) [pid = 4348] [serial = 424] [outer = 00000198CB6E3020]
[task 2019-08-14T20:35:01.639Z] 20:35:01 INFO - GECKO(8308) | ++DOMWINDOW == 25 (00000198CC109800) [pid = 4348] [serial = 425] [outer = 00000198CB6E3020]
[task 2019-08-14T20:35:02.519Z] 20:35:02 INFO - GECKO(8308) | ++DOCSHELL 00000198C1471800 == 8 [pid = 4348] [id = {8d9c3c9f-ae56-45bd-a3ab-f4f51d04fa38}]
[task 2019-08-14T20:35:02.519Z] 20:35:02 INFO - GECKO(8308) | ++DOMWINDOW == 26 (00000198CCE967A0) [pid = 4348] [serial = 426] [outer = 0000000000000000]
[task 2019-08-14T20:35:02.519Z] 20:35:02 INFO - GECKO(8308) | ++DOMWINDOW == 27 (00000198CC10AC00) [pid = 4348] [serial = 427] [outer = 00000198CCE967A0]
[task 2019-08-14T20:35:02.903Z] 20:35:02 INFO - GECKO(8308) | [Parent 4348, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x805D0021: file z:/build/build/src/modules/libjar/nsJARChannel.cpp, line 994
[task 2019-08-14T20:35:03.430Z] 20:35:03 INFO - GECKO(8308) | --DOCSHELL 000001D0CD371000 == 1 [pid = 9516] [id = {6da76095-58fc-42da-a4f0-cc92e3d8224e}] [url = http://example.com/browser/devtools/client/performance/test/doc_simple-test.html#667508617118618]
[task 2019-08-14T20:35:03.774Z] 20:35:03 INFO - GECKO(8308) | --DOMWINDOW == 4 (000001D0D14DB020) [pid = 9516] [serial = 113] [outer = 0000000000000000] [url = http://example.com/browser/devtools/client/performance/test/doc_simple-test.html#667508617118618]
[task 2019-08-14T20:35:04.482Z] 20:35:04 INFO - GECKO(8308) | Waiting for event: 'Performance:BackendReadyRecordingStart' on [object PerformanceController] for 1 time(s).
[task 2019-08-14T20:35:04.482Z] 20:35:04 INFO - GECKO(8308) | Waiting for event: 'Performance:RecordingStateChange' on [object PerformanceController] for 1 time(s) with arguments: ["recording-started"].
[task 2019-08-14T20:35:04.482Z] 20:35:04 INFO - GECKO(8308) | Waiting for event: 'Performance:UI:StateChanged' on [object PerformanceView] for 1 time(s) with arguments: [{}].
[task 2019-08-14T20:35:04.482Z] 20:35:04 INFO - GECKO(8308) | Waiting for event: 'Performance:UI:OverviewRendered' on [object OverviewView] for 1 time(s) with arguments: [100].
[task 2019-08-14T20:35:04.738Z] 20:35:04 INFO - GECKO(8308) | Event: 'Performance:UI:StateChanged' on [object PerformanceView] received.
[task 2019-08-14T20:35:04.748Z] 20:35:04 INFO - GECKO(8308) | ++DOCSHELL 00000198CC483000 == 9 [pid = 4348] [id = {e5562ca7-6e60-4554-868c-2d2873bd569e}]
[task 2019-08-14T20:35:04.748Z] 20:35:04 INFO - GECKO(8308) | ++DOMWINDOW == 28 (00000198D6B1E880) [pid = 4348] [serial = 428] [outer = 0000000000000000]
[task 2019-08-14T20:35:04.748Z] 20:35:04 INFO - GECKO(8308) | ++DOMWINDOW == 29 (00000198CD41E400) [pid = 4348] [serial = 429] [outer = 00000198D6B1E880]
[task 2019-08-14T20:35:04.991Z] 20:35:04 INFO - GECKO(8308) | Event: 'Performance:RecordingStateChange' on [object PerformanceController] received.
[task 2019-08-14T20:35:05.036Z] 20:35:05 INFO - GECKO(8308) | Event: 'Performance:BackendReadyRecordingStart' on [object PerformanceController] received.
[task 2019-08-14T20:35:05.176Z] 20:35:05 INFO - GECKO(8308) | [Parent 4348, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x805D0021: file z:/build/build/src/modules/libjar/nsJARChannel.cpp, line 994
[task 2019-08-14T20:35:05.744Z] 20:35:05 INFO - GECKO(8308) | ++DOCSHELL 00000198CC489000 == 10 [pid = 4348] [id = {39258811-6601-47e3-98d8-b4d0ec25585c}]
[task 2019-08-14T20:35:05.744Z] 20:35:05 INFO - GECKO(8308) | ++DOMWINDOW == 30 (00000198D955F3E0) [pid = 4348] [serial = 430] [outer = 0000000000000000]
[task 2019-08-14T20:35:05.744Z] 20:35:05 INFO - GECKO(8308) | ++DOMWINDOW == 31 (00000198CD55E000) [pid = 4348] [serial = 431] [outer = 00000198D955F3E0]
[task 2019-08-14T20:35:05.973Z] 20:35:05 INFO - GECKO(8308) | [Parent 4348, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x805D0021: file z:/build/build/src/modules/libjar/nsJARChannel.cpp, line 994
[task 2019-08-14T20:35:08.738Z] 20:35:08 INFO - GECKO(8308) | --DOCSHELL 0000020C90F70800 == 0 [pid = 2956] [id = {18e65e6b-50f4-4b46-a8d9-35304eb97429}] [url = about:blank]
[task 2019-08-14T20:35:09.836Z] 20:35:09 INFO - GECKO(8308) | --DOMWINDOW == 3 (000001D0CD3D1C00) [pid = 9516] [serial = 117] [outer = 0000000000000000] [url = about:blank]
[task 2019-08-14T20:35:09.836Z] 20:35:09 INFO - GECKO(8308) | --DOMWINDOW == 2 (000001D0D27A6400) [pid = 9516] [serial = 115] [outer = 0000000000000000] [url = http://example.com/browser/devtools/client/performance/test/doc_simple-test.html#667508617118618]
[task 2019-08-14T20:35:10.646Z] 20:35:10 INFO - GECKO(8308) | Event: 'Performance:UI:OverviewRendered' on [object OverviewView] received.
[task 2019-08-14T20:35:11.406Z] 20:35:11 INFO - GECKO(8308) | --DOMWINDOW == 2 (0000020FC02AA400) [pid = 4648] [serial = 66] [outer = 0000000000000000] [url = about:blank]
[task 2019-08-14T20:35:12.826Z] 20:35:12 INFO - GECKO(8308) | Waiting for event: 'Performance:BackendReadyRecordingStop' on [object PerformanceController] for 1 time(s).
[task 2019-08-14T20:35:12.827Z] 20:35:12 INFO - GECKO(8308) | Waiting for event: 'Performance:RecordingStateChange' on [object PerformanceController] for 1 time(s) with arguments: ["recording-stopping"].
[task 2019-08-14T20:35:12.827Z] 20:35:12 INFO - GECKO(8308) | Waiting for event: 'Performance:RecordingStateChange' on [object PerformanceController] for 1 time(s) with arguments: ["recording-stopped"].
[task 2019-08-14T20:35:12.827Z] 20:35:12 INFO - GECKO(8308) | Waiting for event: 'Performance:UI:StateChanged' on [object PerformanceView] for 1 time(s) with arguments: ["recorded"].
[task 2019-08-14T20:35:12.827Z] 20:35:12 INFO - GECKO(8308) | Waiting for event: 'Performance:UI:OverviewRendered' on [object OverviewView] for 1 time(s) with arguments: [16].
[task 2019-08-14T20:35:12.827Z] 20:35:12 INFO - GECKO(8308) | Waiting for event: 'Performance:UI:WaterfallRendered' on [object WaterfallView] for 1 time(s).
[task 2019-08-14T20:35:13.068Z] 20:35:13 INFO - GECKO(8308) | --DOMWINDOW == 1 (0000020C954D7020) [pid = 2956] [serial = 62] [outer = 0000000000000000] [url = about:blank]
[task 2019-08-14T20:35:16.557Z] 20:35:16 INFO - GECKO(8308) | Ignoring event 'Performance:UI:StateChanged' with unexpected argument at index 0: loading - expected recorded
[task 2019-08-14T20:35:16.559Z] 20:35:16 INFO - GECKO(8308) | Event: 'Performance:RecordingStateChange' on [object PerformanceController] received.
[task 2019-08-14T20:35:16.559Z] 20:35:16 INFO - GECKO(8308) | Ignoring event 'Performance:RecordingStateChange' with unexpected argument at index 0: recording-stopping - expected recording-stopped
[task 2019-08-14T20:35:16.666Z] 20:35:16 INFO - GECKO(8308) | Event: 'Performance:UI:StateChanged' on [object PerformanceView] received.
[task 2019-08-14T20:35:16.695Z] 20:35:16 INFO - GECKO(8308) | Event: 'Performance:RecordingStateChange' on [object PerformanceController] received.
[task 2019-08-14T20:35:17.089Z] 20:35:17 INFO - GECKO(8308) | --DOMWINDOW == 0 (0000020C962B4C00) [pid = 2956] [serial = 64] [outer = 0000000000000000] [url = about:blank]
[task 2019-08-14T20:35:17.352Z] 20:35:17 INFO - GECKO(8308) | Event: 'Performance:UI:WaterfallRendered' on [object WaterfallView] received.
[task 2019-08-14T20:35:17.411Z] 20:35:17 INFO - GECKO(8308) | Event: 'Performance:BackendReadyRecordingStop' on [object PerformanceController] received.
[task 2019-08-14T20:35:29.360Z] 20:35:29 INFO - GECKO(8308) | Ignoring event 'Performance:UI:OverviewRendered' with unexpected argument at index 0: 100 - expected 16
[task 2019-08-14T20:36:14.286Z] 20:36:14 INFO - [4792, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 664
[task 2019-08-14T20:36:14.286Z] 20:36:14 INFO - JavaScript error: resource://gre/modules/PlacesExpiration.jsm, line 851: TypeError: this._db is undefined
[task 2019-08-14T20:42:25.651Z] 20:42:25 INFO - GECKO(8308) | Event: 'Performance:UI:OverviewRendered' on [object OverviewView] received.
[task 2019-08-14T20:42:25.656Z] 20:42:25 INFO - GECKO(8308) | Destroying panel.
[task 2019-08-14T20:42:28.640Z] 20:42:28 INFO - GECKO(8308) | --DOCSHELL 00000198CC483000 == 9 [pid = 4348] [id = {e5562ca7-6e60-4554-868c-2d2873bd569e}] [url = chrome://devtools/content/shared/widgets/graphs-frame.xhtml]
[task 2019-08-14T20:42:28.640Z] 20:42:28 INFO - GECKO(8308) | --DOCSHELL 00000198CC489000 == 8 [pid = 4348] [id = {39258811-6601-47e3-98d8-b4d0ec25585c}] [url = chrome://devtools/content/shared/widgets/graphs-frame.xhtml]
[task 2019-08-14T20:42:29.174Z] 20:42:29 INFO - GECKO(8308) | [Parent 4348, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 664
[task 2019-08-14T20:42:29.179Z] 20:42:29 INFO - GECKO(8308) | Removing tab: http://example.com/browser/devtools/client/performance/test/doc_simple-test.html#6975204308340048.
[task 2019-08-14T20:42:29.259Z] 20:42:29 INFO - GECKO(8308) | [Parent 4348, Main Thread] WARNING: Constructing RangeBoundary with invalid value: 'mRef || aOffset == 0', file z:/build/build/src/obj-firefox/dist/include\mozilla/RangeBoundary.h, line 79
[task 2019-08-14T20:42:29.259Z] 20:42:29 INFO - GECKO(8308) | [Parent 4348, Main Thread] WARNING: Constructing RangeBoundary with invalid value: 'mRef || aOffset == 0', file z:/build/build/src/obj-firefox/dist/include\mozilla/RangeBoundary.h, line 79
[task 2019-08-14T20:42:29.259Z] 20:42:29 INFO - GECKO(8308) | [Child 4648, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 664
[task 2019-08-14T20:42:29.358Z] 20:42:29 INFO - GECKO(8308) | [Parent 4348, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 664
[task 2019-08-14T20:42:32.247Z] 20:42:32 INFO - GECKO(8308) | --DOCSHELL 00000198C1468000 == 7 [pid = 4348] [id = {c1f4ca79-5d4c-4b1f-9203-c9d5cf8766dd}] [url = about:devtools-toolbox]
[task 2019-08-14T20:42:32.247Z] 20:42:32 INFO - GECKO(8308) | --DOCSHELL 00000198C1471800 == 6 [pid = 4348] [id = {8d9c3c9f-ae56-45bd-a3ab-f4f51d04fa38}] [url = chrome://devtools/content/performance/index.xul]
[task 2019-08-14T20:42:32.247Z] 20:42:32 INFO - GECKO(8308) | --DOMWINDOW == 30 (00000198CC10E400) [pid = 4348] [serial = 418] [outer = 0000000000000000] [url = about:blank]
[task 2019-08-14T20:42:32.247Z] 20:42:32 INFO - GECKO(8308) | --DOMWINDOW == 29 (00000198CCE96200) [pid = 4348] [serial = 417] [outer = 0000000000000000] [url = chrome://devtools/content/performance/index.xul]
[task 2019-08-14T20:42:32.247Z] 20:42:32 INFO - GECKO(8308) | --DOMWINDOW == 28 (00000198CCE96020) [pid = 4348] [serial = 414] [outer = 0000000000000000] [url = about:devtools-toolbox]
[task 2019-08-14T20:42:32.248Z] 20:42:32 INFO - GECKO(8308) | --DOMWINDOW == 27 (00000198D6B1EE20) [pid = 4348] [serial = 419] [outer = 0000000000000000] [url = chrome://devtools/content/shared/widgets/graphs-frame.xhtml]
[task 2019-08-14T20:42:32.248Z] 20:42:32 INFO - GECKO(8308) | --DOMWINDOW == 26 (00000198D955F020) [pid = 4348] [serial = 421] [outer = 0000000000000000] [url = chrome://devtools/content/shared/widgets/graphs-frame.xhtml]
[task 2019-08-14T20:42:32.248Z] 20:42:32 INFO - GECKO(8308) | --DOMWINDOW == 25 (00000198CB6CB000) [pid = 4348] [serial = 424] [outer = 0000000000000000] [url = about:blank]
[task 2019-08-14T20:42:32.248Z] 20:42:32 INFO - GECKO(8308) | --DOMWINDOW == 24 (00000198D090D800) [pid = 4348] [serial = 422] [outer = 0000000000000000] [url = about:blank]
[task 2019-08-14T20:42:32.249Z] 20:42:32 INFO - GECKO(8308) | --DOMWINDOW == 23 (00000198D07CD400) [pid = 4348] [serial = 420] [outer = 0000000000000000] [url = about:blank]
[task 2019-08-14T20:42:32.249Z] 20:42:32 INFO - GECKO(8308) | --DOMWINDOW == 22 (00000198CB6D2000) [pid = 4348] [serial = 416] [outer = 0000000000000000] [url = about:devtools-toolbox]
[task 2019-08-14T20:42:36.070Z] 20:42:36 INFO - TEST-INFO | started process screenshot
[task 2019-08-14T20:42:36.132Z] 20:42:36 INFO - TEST-INFO | screenshot: exit 0
[task 2019-08-14T20:42:36.133Z] 20:42:36 INFO - Buffered messages logged at 20:35:00
[task 2019-08-14T20:42:36.133Z] 20:42:36 INFO - Entering test bound
[task 2019-08-14T20:42:36.133Z] 20:42:36 INFO - Console message: [JavaScript Error: "uncaught exception: Object" {file: "resource://testing-common/PromiseTestUtils.jsm" line: 112}]
[task 2019-08-14T20:42:36.133Z] 20:42:36 INFO - Buffered messages logged at 20:37:01
[task 2019-08-14T20:42:36.133Z] 20:42:36 INFO - Longer timeout required, waiting longer... Remaining timeouts: 2
[task 2019-08-14T20:42:36.133Z] 20:42:36 INFO - Buffered messages logged at 20:39:48
[task 2019-08-14T20:42:36.133Z] 20:42:36 INFO - Longer timeout required, waiting longer... Remaining timeouts: 1
[task 2019-08-14T20:42:36.133Z] 20:42:36 INFO - Buffered messages logged at 20:42:25
[task 2019-08-14T20:42:36.134Z] 20:42:36 INFO - TEST-PASS | devtools/client/performance/test/browser_perf-options-propagate-profiler.js | profiler entries option is set on profiler -
[task 2019-08-14T20:42:36.134Z] 20:42:36 INFO - TEST-PASS | devtools/client/performance/test/browser_perf-options-propagate-profiler.js | profiler interval option is set on profiler -
[task 2019-08-14T20:42:36.134Z] 20:42:36 INFO - Buffered messages logged at 20:42:29
[task 2019-08-14T20:42:36.134Z] 20:42:36 INFO - Leaving test bound
[task 2019-08-14T20:42:36.134Z] 20:42:36 INFO - finish() was called, cleaning up...
[task 2019-08-14T20:42:36.134Z] 20:42:36 INFO - Buffered messages finished
[task 2019-08-14T20:42:36.134Z] 20:42:36 INFO - TEST-UNEXPECTED-FAIL | devtools/client/performance/test/browser_perf-options-propagate-profiler.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N), but only as a last resort. -
[task 2019-08-14T20:42:36.134Z] 20:42:36 INFO - GECKO(8308) | MEMORY STAT | vsize 2104640MB | vsizeMaxContiguous 65774975MB | residentFast 430MB | heapAllocated 98MB
[task 2019-08-14T20:42:36.134Z] 20:42:36 INFO - TEST-OK | devtools/client/performance/test/browser_perf-options-propagate-profiler.js | took 455464ms

Comment 1

[Intermittent Failures Robot]

1 failures in 4839 pushes (0.0 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 1

Platform breakdown:

• windows10-64-ccov: 1

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1573971&startday=2019-08-12&endday=2019-08-18&tree=all

Comment 2

[Firefox Bug Husbandry Bot]

https://wiki.mozilla.org/Bug_Triage#Intermittent_Test_Failure_Cleanup