Closed Bug 1621077 Opened 5 years ago Closed 4 years ago

Intermittent devtools/client/performance-new/test/browser/browser_devtools-previously-started.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N)

Categories

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

defect

Tracking

(Not tracked)

RESOLVED INCOMPLETE

People

(Reporter: intermittent-bug-filer, Unassigned)

References

(Regression)

Details

(Keywords: intermittent-failure, regression)

Filed by: nerli [at] mozilla.com
Parsed log: https://treeherder.mozilla.org/logviewer.html#?job_id=292283722&repo=autoland
Full log: https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/S99S3w4FSPyc7XFlEJV7CQ/runs/0/artifacts/public/logs/live_backing.log
Reftest URL: https://hg.mozilla.org/mozilla-central/raw-file/tip/layout/tools/reftest/reftest-analyzer.xhtml#logurl=https://firefox-ci-tc.services.mozilla.com/api/queue/v1/task/S99S3w4FSPyc7XFlEJV7CQ/runs/0/artifacts/public/logs/live_backing.log&only_show_unexpected=1


[task 2020-03-09T16:09:42.742Z] 16:09:42 INFO - TEST-START | devtools/client/performance-new/test/browser/browser_devtools-previously-started.js
[task 2020-03-09T16:09:43.229Z] 16:09:43 INFO - GECKO(12973) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpA7n1pQ.mozrunner/runtests_leaks_tab_pid13196.log
[task 2020-03-09T16:09:50.511Z] 16:09:50 INFO - GECKO(12973) | [Child 13139: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f82e454f000 == 0 [pid = 13139] [id = {656faded-8f97-439a-bb42-d09bf739a1d4}] [url = about:blank]
[task 2020-03-09T16:09:50.841Z] 16:09:50 INFO - GECKO(12973) | [Child 13139: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (0x7f8316093520) [pid = 13139] [serial = 1] [outer = (nil)] [url = about:blank]
[task 2020-03-09T16:09:50.858Z] 16:09:50 INFO - GECKO(12973) | [Child 13109: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f14bd8ec800 == 0 [pid = 13109] [id = {ddeb1d5e-553a-436f-89de-d813157b32c0}] [url = about:blank]
[task 2020-03-09T16:09:54.799Z] 16:09:54 INFO - GECKO(12973) | [Parent 12973: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 14 (0x7f5e557ce400) [pid = 12973] [serial = 13] [outer = (nil)] [url = about:blank]
[task 2020-03-09T16:09:54.841Z] 16:09:54 INFO - GECKO(12973) | [Child 13139: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (0x7f82e446a800) [pid = 13139] [serial = 3] [outer = (nil)] [url = about:blank]
[task 2020-03-09T16:09:55.106Z] 16:09:55 INFO - GECKO(12973) | [Child 13109: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 1 (0x7f14d8993520) [pid = 13109] [serial = 1] [outer = (nil)] [url = about:blank]
[task 2020-03-09T16:09:59.055Z] 16:09:59 INFO - GECKO(12973) | [Child 13109: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 0 (0x7f14be05fc00) [pid = 13109] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2020-03-09T16:10:02.512Z] 16:10:02 INFO - GECKO(12973) | [Parent 12973: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 13 (0x7f5e799c8d40) [pid = 12973] [serial = 12] [outer = (nil)] [url = about:devtools-toolbox]
[task 2020-03-09T16:10:02.701Z] 16:10:02 INFO - GECKO(12973) | [Parent 12973: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 12 (0x7f5e799c99f0) [pid = 12973] [serial = 15] [outer = (nil)] [url = chrome://devtools/content/performance-new/index.xhtml]
[task 2020-03-09T16:10:07.203Z] 16:10:07 INFO - GECKO(12973) | [Child 13196, Main Thread] WARNING: No CID found when attempting to map contract ID: file /builds/worker/checkouts/gecko/xpcom/components/nsComponentManager.cpp, line 721
[task 2020-03-09T16:10:09.243Z] 16:10:09 INFO - GECKO(12973) | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2020-03-09T16:10:09.670Z] 16:10:09 INFO - GECKO(12973) | [Parent 12973: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 11 (0x7f5e557cf000) [pid = 12973] [serial = 14] [outer = (nil)] [url = about:devtools-toolbox]
[task 2020-03-09T16:10:09.672Z] 16:10:09 INFO - GECKO(12973) | [Parent 12973: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 10 (0x7f5e74fdf800) [pid = 12973] [serial = 16] [outer = (nil)] [url = about:blank]
[task 2020-03-09T16:10:10.277Z] 16:10:10 INFO - GECKO(12973) | [Child 13196, Main Thread] WARNING: could not set real-time limit at process startup: file /builds/worker/checkouts/gecko/dom/ipc/ContentChild.cpp, line 1808
[task 2020-03-09T16:10:10.362Z] 16:10:10 INFO - GECKO(12973) | [Child 13196: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7efd16e4f000 == 1 [pid = 13196] [id = {a4300d93-8e36-425d-b47a-c02fe3c8853f}]
[task 2020-03-09T16:10:10.700Z] 16:10:10 INFO - GECKO(12973) | [Child 13196: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (0x7efd48a93520) [pid = 13196] [serial = 1] [outer = (nil)]
[task 2020-03-09T16:10:10.720Z] 16:10:10 INFO - GECKO(12973) | [Child 13196, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/base/nsPresContext.cpp, line 839
[task 2020-03-09T16:10:10.737Z] 16:10:10 INFO - GECKO(12973) | [Child 13196: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (0x7efd1707c000) [pid = 13196] [serial = 2] [outer = 0x7efd48a93520]
[task 2020-03-09T16:10:16.993Z] 16:10:16 INFO - GECKO(12973) | [Child 13196: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 3 (0x7efd16d9d000) [pid = 13196] [serial = 3] [outer = 0x7efd48a93520]
[task 2020-03-09T16:10:20.925Z] 16:10:20 INFO - GECKO(12973) | [Parent 12973: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7f5e559d5800 == 6 [pid = 12973] [id = {22e130c8-d4ad-41de-834c-63a57ca5d315}]
[task 2020-03-09T16:10:20.933Z] 16:10:20 INFO - GECKO(12973) | [Parent 12973: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 11 (0x7f5e799c8d40) [pid = 12973] [serial = 17] [outer = (nil)]
[task 2020-03-09T16:10:21.944Z] 16:10:21 INFO - GECKO(12973) | [Parent 12973: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 12 (0x7f5e557d0400) [pid = 12973] [serial = 18] [outer = 0x7f5e799c8d40]
[task 2020-03-09T16:10:23.690Z] 16:10:23 INFO - GECKO(12973) | [Parent 12973: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 13 (0x7f5e557cc800) [pid = 12973] [serial = 19] [outer = 0x7f5e799c8d40]
[task 2020-03-09T16:10:29.554Z] 16:10:29 INFO - GECKO(12973) | [Child 13196: Main Thread]: I/DocShellAndDOMWindowLeak --DOMWINDOW == 2 (0x7efd1707c000) [pid = 13196] [serial = 2] [outer = (nil)] [url = about:blank]
[task 2020-03-09T16:10:47.846Z] 16:10:47 INFO - GECKO(12973) | [Parent 12973, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /builds/worker/checkouts/gecko/dom/base/nsContentUtils.cpp, line 3786
[task 2020-03-09T16:10:48.994Z] 16:10:48 INFO - GECKO(12973) | ### XPCOM_MEM_BLOAT_LOG defined -- logging bloat/leaks to /tmp/tmpA7n1pQ.mozrunner/runtests_leaks_tab_pid13234.log
[task 2020-03-09T16:10:59.002Z] 16:10:59 INFO - GECKO(12973) | [Parent 12973: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7f5e753e0800 == 7 [pid = 12973] [id = {892fabec-0516-40bc-93fb-43c6ddb36576}]
[task 2020-03-09T16:10:59.004Z] 16:10:59 INFO - GECKO(12973) | [Parent 12973: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 14 (0x7f5e799c9820) [pid = 12973] [serial = 20] [outer = (nil)]
[task 2020-03-09T16:10:59.066Z] 16:10:59 INFO - GECKO(12973) | [Parent 12973: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 15 (0x7f5e797c9c00) [pid = 12973] [serial = 21] [outer = 0x7f5e799c9820]
[task 2020-03-09T16:11:16.800Z] 16:11:16 INFO - GECKO(12973) | [Child 13234, Main Thread] WARNING: No CID found when attempting to map contract ID: file /builds/worker/checkouts/gecko/xpcom/components/nsComponentManager.cpp, line 721
[task 2020-03-09T16:11:16.965Z] 16:11:16 INFO - GECKO(12973) | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
[task 2020-03-09T16:11:17.183Z] 16:11:17 INFO - GECKO(12973) | [Child 13234, Main Thread] WARNING: could not set real-time limit at process startup: file /builds/worker/checkouts/gecko/dom/ipc/ContentChild.cpp, line 1808
[task 2020-03-09T16:11:17.795Z] 16:11:17 INFO - GECKO(12973) | [Parent 12973, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/JSWindowActorService.cpp, line 182
[task 2020-03-09T16:11:17.797Z] 16:11:17 INFO - GECKO(12973) | [Parent 12973, Main Thread] WARNING: '!inner', file /builds/worker/checkouts/gecko/dom/ipc/JSWindowActorService.cpp, line 182
[task 2020-03-09T16:11:17.830Z] 16:11:17 INFO - GECKO(12973) | [Parent 12973: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f5e753e0800 == 6 [pid = 12973] [id = {892fabec-0516-40bc-93fb-43c6ddb36576}] [url = chrome://devtools/content/performance-new/index.xhtml]
[task 2020-03-09T16:11:17.852Z] 16:11:17 INFO - GECKO(12973) | [Parent 12973: Main Thread]: I/DocShellAndDOMWindowLeak --DOCSHELL 0x7f5e559d5800 == 5 [pid = 12973] [id = {22e130c8-d4ad-41de-834c-63a57ca5d315}] [url = about:devtools-toolbox]
[task 2020-03-09T16:11:18.318Z] 16:11:18 INFO - TEST-INFO | started process screentopng
[task 2020-03-09T16:11:18.578Z] 16:11:18 INFO - TEST-INFO | screentopng: exit 0
[task 2020-03-09T16:11:18.579Z] 16:11:18 INFO - Buffered messages logged at 16:09:42
[task 2020-03-09T16:11:18.580Z] 16:11:18 INFO - Entering test bound test
[task 2020-03-09T16:11:18.581Z] 16:11:18 INFO - Test what happens if the profiler was previously started by another tool.
[task 2020-03-09T16:11:18.582Z] 16:11:18 INFO - Start the profiler before DevTools is loaded.
[task 2020-03-09T16:11:18.583Z] 16:11:18 INFO - Create a new about:blank tab.
[task 2020-03-09T16:11:18.584Z] 16:11:18 INFO - Buffered messages logged at 16:09:43
[task 2020-03-09T16:11:18.585Z] 16:11:18 INFO - Begin to open the DevTools and the performance-new panel.
[task 2020-03-09T16:11:18.586Z] 16:11:18 INFO - Buffered messages logged at 16:11:08
[task 2020-03-09T16:11:18.586Z] 16:11:18 INFO - Console message: [JavaScript Error: "Content Security Policy: The page’s settings blocked the loading of a resource at inline (“default-src”)." {file: "chrome://global/content/elements/panel.js" line: 62}]
[task 2020-03-09T16:11:18.587Z] 16:11:18 INFO - Buffered messages logged at 16:11:13
[task 2020-03-09T16:11:18.588Z] 16:11:18 INFO - The performance-new panel is now open and ready to use.
[task 2020-03-09T16:11:18.589Z] 16:11:18 INFO - TEST-PASS | devtools/client/performance-new/test/browser/browser_devtools-previously-started.js | The component starts out in an unknown state. -
[task 2020-03-09T16:11:18.590Z] 16:11:18 INFO - Trying to find the element with the text "Cancel recording".
[task 2020-03-09T16:11:18.590Z] 16:11:18 INFO - Buffered messages logged at 16:11:14
[task 2020-03-09T16:11:18.591Z] 16:11:18 INFO - Trying to find the element with the text "Cancel recording". (After 1 second)
[task 2020-03-09T16:11:18.592Z] 16:11:18 INFO - Waiting until the button is not disabled.
[task 2020-03-09T16:11:18.592Z] 16:11:18 INFO - TEST-PASS | devtools/client/performance-new/test/browser/browser_devtools-previously-started.js | The profiler is reflecting the recording state. -
[task 2020-03-09T16:11:18.593Z] 16:11:18 INFO - Click the button to cancel the recording
[task 2020-03-09T16:11:18.594Z] 16:11:18 INFO - TEST-PASS | devtools/client/performance-new/test/browser/browser_devtools-previously-started.js | We can request to stop the profiler. -
[task 2020-03-09T16:11:18.595Z] 16:11:18 INFO - Trying to find the element with the text "Start recording".
[task 2020-03-09T16:11:18.596Z] 16:11:18 INFO - Buffered messages logged at 16:11:16
[task 2020-03-09T16:11:18.599Z] 16:11:18 INFO - Trying to find the element with the text "Start recording". (After 1 second)
[task 2020-03-09T16:11:18.600Z] 16:11:18 INFO - Waiting until the button is not disabled.
[task 2020-03-09T16:11:18.601Z] 16:11:18 INFO - TEST-PASS | devtools/client/performance-new/test/browser/browser_devtools-previously-started.js | The profiler is now available to record. -
[task 2020-03-09T16:11:18.602Z] 16:11:18 INFO - About to remove the about:blank tab
[task 2020-03-09T16:11:18.602Z] 16:11:18 INFO - Buffered messages logged at 16:11:17
[task 2020-03-09T16:11:18.604Z] 16:11:18 INFO - The about:blank tab is now removed.
[task 2020-03-09T16:11:18.605Z] 16:11:18 INFO - Buffered messages logged at 16:11:18
[task 2020-03-09T16:11:18.606Z] 16:11:18 INFO - Leaving test bound test
[task 2020-03-09T16:11:18.608Z] 16:11:18 INFO - Buffered messages finished
[task 2020-03-09T16:11:18.609Z] 16:11:18 INFO - TEST-UNEXPECTED-FAIL | devtools/client/performance-new/test/browser/browser_devtools-previously-started.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 2020-03-09T16:11:18.610Z] 16:11:18 INFO - GECKO(12973) | MEMORY STAT | vsize 3252MB | residentFast 490MB | heapAllocated 259MB
[task 2020-03-09T16:11:18.612Z] 16:11:18 INFO - TEST-OK | devtools/client/performance-new/test/browser/browser_devtools-previously-started.js | took 95575ms
[task 2020-03-09T16:11:18.613Z] 16:11:18 INFO - GECKO(12973) | [Child 13234: Main Thread]: I/DocShellAndDOMWindowLeak ++DOCSHELL 0x7fe991650800 == 1 [pid = 13234] [id = {af7248fc-cde9-4d70-b6c0-5ac70b079d7c}]
[task 2020-03-09T16:11:18.614Z] 16:11:18 INFO - GECKO(12973) | [Child 13234: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 1 (0x7fe9c3193520) [pid = 13234] [serial = 1] [outer = (nil)]
[task 2020-03-09T16:11:18.615Z] 16:11:18 INFO - GECKO(12973) | [Child 13234, Main Thread] WARNING: NS_ENSURE_TRUE(mPresShell) failed: file /builds/worker/checkouts/gecko/layout/base/nsPresContext.cpp, line 839
[task 2020-03-09T16:11:18.616Z] 16:11:18 INFO - GECKO(12973) | [Child 13234: Main Thread]: I/DocShellAndDOMWindowLeak ++DOMWINDOW == 2 (0x7fe99184fc00) [pid = 13234] [serial = 2] [outer = 0x7fe9c3193520]
[task 2020-03-09T16:11:18.617Z] 16:11:18 INFO - checking window state

Regressed by: 1620323
Has Regression Range: --- → yes
Keywords: regression
Status: NEW → RESOLVED
Closed: 5 years ago
Resolution: --- → INCOMPLETE
Status: RESOLVED → REOPENED
Resolution: INCOMPLETE → ---
Summary: Intermittent TV devtools/client/performance-new/test/browser/browser_devtools-previously-started.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N) → Intermittent devtools/client/performance-new/test/browser/browser_devtools-previously-started.js | This test exceeded the timeout threshold. It should be rewritten or split up. If that's not possible, use requestLongerTimeout(N)
Status: REOPENED → RESOLVED
Closed: 5 years ago4 years ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.