1273422 - Intermittent browser_perf-recording-notices-02.js,browser_perf-console-record-07.js | application timed out after 330 seconds with no output

Status: RESOLVED FIXED

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

Description

[Sebastian Hengst [:aryx] (needinfo me if it's about an intermittent or backout)]

https://treeherder.mozilla.org/logviewer.html#?job_id=27995332&repo=mozilla-inbound

06:42:14     INFO -  Event: 'Performance:UI:StateChanged' on [object PerformanceView] received.
06:42:14     INFO -  Event: 'Performance:RecordingStateChange' on [object PerformanceController] received.
06:42:27     INFO -  Event: 'Performance:UI:WaterfallRendered' on [object WaterfallView] received.
06:42:27     INFO -  Event: 'Performance:BackendReadyRecordingStop' on [object PerformanceController] received.
06:47:57     INFO -  123 INFO checking window state
06:47:57     INFO -  124 INFO Entering test bound
06:47:57  WARNING -  TEST-UNEXPECTED-TIMEOUT | devtools/client/performance/test/browser_perf-recording-notices-02.js | application timed out after 330 seconds with no output

Comment 1

[Intermittent Failures Robot]

21 failures in 137 pushes (0.153 failures/push) were associated with this bug yesterday.  
Repository breakdown:
* mozilla-inbound: 6
* try: 4
* mozilla-central: 4
* autoland: 4
* graphics: 3

Platform breakdown:
* linux64: 21

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1273422&startday=2017-03-09&endday=2017-03-09&tree=all

Comment 2

[Joel Maher ( :jmaher ) (UTC -8)]

this bug spiked up on March 8th and is going for an spot on the podium (for most frequent oranges).  Linux64 debug non-e10s is the failure pattern

you can see the trend here:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1273422&startday=2017-03-07&endday=2017-03-10&tree=all

this test seems to take 46.x seconds normally (at least when looking at a few green logs.  And the failure rate, this is run under normal (i.e. high) load, once out of every 5 pushes, so the 15% reported rate from orange factor could be as high as 75%.

I am backfilling and retriggering:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-searchStr=dt1%20linux%20debug&tochange=4e90c48f26179dc59150ae002a46666014fd3cbc&fromchange=c55c0ec84a7275becab95d39edfd3a7b42119023&selectedJob=82300214

here is a failure log:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-searchStr=dt1%20linux%20debug&tochange=4e90c48f26179dc59150ae002a46666014fd3cbc&fromchange=c55c0ec84a7275becab95d39edfd3a7b42119023&selectedJob=82300214

and screenshot;
https://public-artifacts.taskcluster.net/Kgo1vimLS8OnrbhodW9WSw/0/public/test_info//mozilla-test-fail-screenshot_4EJS1M.png

and the data from the above log:
[task 2017-03-08T06:13:59.525005Z] 06:13:59     INFO - TEST-START | devtools/client/performance/test/browser_perf-console-record-07.js
[task 2017-03-08T06:13:59.563486Z] 06:13:59     INFO - Adding tab with url: http://example.com/browser/devtools/client/performance/test/doc_simple-test.html#2331537035477701.
[task 2017-03-08T06:13:59.569046Z] 06:13:59     INFO - ++DOCSHELL 0x7f407a0b5000 == 9 [pid = 1660] [id = {edae4be9-181b-41f0-8b0c-623eb9a9f59d}]
[task 2017-03-08T06:13:59.570896Z] 06:13:59     INFO - ++DOMWINDOW == 17 (0x7f40794fd800) [pid = 1660] [serial = 209] [outer = (nil)]
[task 2017-03-08T06:13:59.613438Z] 06:13:59     INFO - [1660] WARNING: NS_ENSURE_TRUE(standardURL) failed: file /home/worker/workspace/build/src/caps/nsPrincipal.cpp, line 229
[task 2017-03-08T06:13:59.615793Z] 06:13:59     INFO - ++DOMWINDOW == 18 (0x7f4079f4fc00) [pid = 1660] [serial = 210] [outer = 0x7f40794fd800]
[task 2017-03-08T06:13:59.617304Z] 06:13:59     INFO - [1660] WARNING: NS_ENSURE_TRUE(standardURL) failed: file /home/worker/workspace/build/src/caps/nsPrincipal.cpp, line 229
[task 2017-03-08T06:13:59.618877Z] 06:13:59     INFO - [1660] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /home/worker/workspace/build/src/extensions/cookie/nsPermissionManager.cpp, line 107
[task 2017-03-08T06:13:59.620410Z] 06:13:59     INFO - [1660] WARNING: 'NS_FAILED(aResult)', file /home/worker/workspace/build/src/extensions/cookie/nsPermissionManager.cpp, line 614
[task 2017-03-08T06:13:59.621959Z] 06:13:59     INFO - [1660] WARNING: NS_ENSURE_TRUE(standardURL) failed: file /home/worker/workspace/build/src/caps/nsPrincipal.cpp, line 229
[task 2017-03-08T06:13:59.623460Z] 06:13:59     INFO - [1660] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /home/worker/workspace/build/src/extensions/cookie/nsPermissionManager.cpp, line 107
[task 2017-03-08T06:13:59.625249Z] 06:13:59     INFO - [1660] WARNING: 'NS_FAILED(aResult)', file /home/worker/workspace/build/src/extensions/cookie/nsPermissionManager.cpp, line 614
[task 2017-03-08T06:13:59.632973Z] 06:13:59     INFO - [1660] WARNING: NS_ENSURE_TRUE(standardURL) failed: file /home/worker/workspace/build/src/caps/nsPrincipal.cpp, line 229
[task 2017-03-08T06:13:59.637837Z] 06:13:59     INFO - [1660] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80004005: file /home/worker/workspace/build/src/extensions/cookie/nsPermissionManager.cpp, line 107
[task 2017-03-08T06:13:59.639665Z] 06:13:59     INFO - [1660] WARNING: 'NS_FAILED(aResult)', file /home/worker/workspace/build/src/extensions/cookie/nsPermissionManager.cpp, line 614
[task 2017-03-08T06:13:59.959970Z] 06:13:59     INFO - ++DOMWINDOW == 19 (0x7f407bd59800) [pid = 1660] [serial = 211] [outer = 0x7f40794fd800]
[task 2017-03-08T06:14:00.319317Z] 06:14:00     INFO - Tab added and finished loading: http://example.com/browser/devtools/client/performance/test/doc_simple-test.html#2331537035477701.
[task 2017-03-08T06:14:00.320358Z] 06:14:00     INFO - Initializing a webconsole panel.
[task 2017-03-08T06:14:00.583422Z] 06:14:00     INFO - ++DOCSHELL 0x7f407bc25000 == 10 [pid = 1660] [id = {2ac20d6b-ed06-4a06-b934-66881b5b8e80}]
[task 2017-03-08T06:14:00.584921Z] 06:14:00     INFO - ++DOMWINDOW == 20 (0x7f407bc2c800) [pid = 1660] [serial = 212] [outer = (nil)]
[task 2017-03-08T06:14:00.585085Z] 06:14:00     INFO - [1660] WARNING: NS_ENSURE_TRUE(standardURL) failed: file /home/worker/workspace/build/src/caps/nsPrincipal.cpp, line 229
[task 2017-03-08T06:14:00.585644Z] 06:14:00     INFO - ++DOMWINDOW == 21 (0x7f407bc2e000) [pid = 1660] [serial = 213] [outer = 0x7f407bc2c800]
[task 2017-03-08T06:14:00.604019Z] 06:14:00     INFO - [1660] WARNING: NS_ENSURE_TRUE(standardURL) failed: file /home/worker/workspace/build/src/caps/nsPrincipal.cpp, line 229
[task 2017-03-08T06:14:00.705557Z] 06:14:00     INFO - ++DOMWINDOW == 22 (0x7f407c036000) [pid = 1660] [serial = 214] [outer = 0x7f407bc2c800]
[task 2017-03-08T06:14:00.874892Z] 06:14:00     INFO - [1660] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x8007000E: file /home/worker/workspace/build/src/dom/xul/nsXULPrototypeCache.cpp, line 338
[task 2017-03-08T06:14:01.840031Z] 06:14:01     INFO - ++DOCSHELL 0x7f4084514000 == 11 [pid = 1660] [id = {98bfa627-4f49-44e9-ad3a-bec93682bee9}]
[task 2017-03-08T06:14:01.841638Z] 06:14:01     INFO - ++DOMWINDOW == 23 (0x7f4084514800) [pid = 1660] [serial = 215] [outer = (nil)]
[task 2017-03-08T06:14:01.842975Z] 06:14:01     INFO - [1660] WARNING: NS_ENSURE_TRUE(standardURL) failed: file /home/worker/workspace/build/src/caps/nsPrincipal.cpp, line 229
[task 2017-03-08T06:14:01.844716Z] 06:14:01     INFO - ++DOMWINDOW == 24 (0x7f4084515800) [pid = 1660] [serial = 216] [outer = 0x7f4084514800]
[task 2017-03-08T06:14:02.783975Z] 06:14:02     INFO - [1660] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file /home/worker/workspace/build/src/layout/style/Loader.cpp, line 2442
[task 2017-03-08T06:14:02.784553Z] 06:14:02     INFO - [1660] WARNING: NS_ENSURE_SUCCESS(rv, rv) failed with result 0x80520012: file /home/worker/workspace/build/src/dom/base/nsDocument.cpp, line 4438
[task 2017-03-08T06:14:04.254105Z] 06:14:04     INFO - Initializing a performance panel.
[task 2017-03-08T06:14:04.436519Z] 06:14:04     INFO - ++DOCSHELL 0x7f407a29e800 == 12 [pid = 1660] [id = {600f3cdd-4a5b-4f9a-a661-4ea1abf821f0}]
[task 2017-03-08T06:14:04.436621Z] 06:14:04     INFO - ++DOMWINDOW == 25 (0x7f407a2a0800) [pid = 1660] [serial = 217] [outer = (nil)]
[task 2017-03-08T06:14:04.437510Z] 06:14:04     INFO - [1660] WARNING: NS_ENSURE_TRUE(standardURL) failed: file /home/worker/workspace/build/src/caps/nsPrincipal.cpp, line 229
[task 2017-03-08T06:14:04.440982Z] 06:14:04     INFO - ++DOMWINDOW == 26 (0x7f40926af800) [pid = 1660] [serial = 218] [outer = 0x7f407a2a0800]
[task 2017-03-08T06:14:05.660471Z] 06:14:05     INFO - Waiting for event: 'Performance:RecordingStateChange' on [object PerformanceController] for 1 time(s) with arguments: {"1":"recording-started"}.
[task 2017-03-08T06:14:05.661687Z] 06:14:05     INFO - Waiting for event: 'Performance:UI:StateChanged' on [object PerformanceView] for 1 time(s) with arguments: {"1":{}}.
[task 2017-03-08T06:14:05.661772Z] 06:14:05     INFO - Waiting for event: 'Performance:UI:OverviewRendered' on [object OverviewView] for 1 time(s) with arguments: {"1":100}.
[task 2017-03-08T06:14:05.665044Z] 06:14:05     INFO - Waiting for event: 'recording-started' on [Front for performance/server1.conn12.child1/performanceActor22] for 1 time(s).
[task 2017-03-08T06:14:05.910149Z] 06:14:05     INFO - [1660] WARNING: Silently denied access to property "wrappedJSObject": value shadows a property on the standard prototype (@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/performance/profiler.js:568:25): file /home/worker/workspace/build/src/js/xpconnect/wrappers/XrayWrapper.cpp, line 254
[task 2017-03-08T06:14:06.309009Z] 06:14:06     INFO - Event: 'recording-started' on [Front for performance/server1.conn12.child1/performanceActor22] received.
[task 2017-03-08T06:14:06.599055Z] 06:14:06     INFO - Event: 'Performance:UI:StateChanged' on [object PerformanceView] received.
[task 2017-03-08T06:14:06.619961Z] 06:14:06     INFO - ++DOCSHELL 0x7f40831b4800 == 13 [pid = 1660] [id = {b54a848e-0361-4182-a31e-83635fa1e5a3}]
[task 2017-03-08T06:14:06.620068Z] 06:14:06     INFO - ++DOMWINDOW == 27 (0x7f40831b7800) [pid = 1660] [serial = 219] [outer = (nil)]
[task 2017-03-08T06:14:06.898631Z] 06:14:06     INFO - Event: 'Performance:RecordingStateChange' on [object PerformanceController] received.
[task 2017-03-08T06:14:07.138021Z] 06:14:07     INFO - ++DOMWINDOW == 28 (0x7f4084507800) [pid = 1660] [serial = 220] [outer = 0x7f40831b7800]
[task 2017-03-08T06:14:07.502196Z] 06:14:07     INFO - ++DOCSHELL 0x7f4086456800 == 14 [pid = 1660] [id = {ab6a9071-f68d-4017-b551-57c70a6f72bc}]
[task 2017-03-08T06:14:07.503698Z] 06:14:07     INFO - ++DOMWINDOW == 29 (0x7f408645e000) [pid = 1660] [serial = 221] [outer = (nil)]
[task 2017-03-08T06:14:07.583794Z] 06:14:07     INFO - ++DOMWINDOW == 30 (0x7f408454e800) [pid = 1660] [serial = 222] [outer = 0x7f408645e000]
[task 2017-03-08T06:14:08.891679Z] 06:14:08     INFO - Event: 'Performance:UI:OverviewRendered' on [object OverviewView] received.
[task 2017-03-08T06:14:08.899461Z] 06:14:08     INFO - Waiting for event: 'Performance:RecordingStateChange' on [object PerformanceController] for 1 time(s) with arguments: {"1":"recording-started"}.
[task 2017-03-08T06:14:08.907464Z] 06:14:08     INFO - Waiting for event: 'recording-started' on [Front for performance/server1.conn12.child1/performanceActor22] for 1 time(s).
[task 2017-03-08T06:14:09.227171Z] 06:14:09     INFO - [1660] WARNING: Silently denied access to property "wrappedJSObject": value shadows a property on the standard prototype (@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/performance/profiler.js:568:25): file /home/worker/workspace/build/src/js/xpconnect/wrappers/XrayWrapper.cpp, line 254
[task 2017-03-08T06:14:09.434266Z] 06:14:09     INFO - Event: 'recording-started' on [Front for performance/server1.conn12.child1/performanceActor22] received.
[task 2017-03-08T06:14:09.800201Z] 06:14:09     INFO - Event: 'Performance:RecordingStateChange' on [object PerformanceController] received.
[task 2017-03-08T06:14:10.010153Z] 06:14:10     INFO - Waiting for event: 'Performance:RecordingStateChange' on [object PerformanceController] for 1 time(s) with arguments: {"1":"recording-started"}.
[task 2017-03-08T06:14:10.017805Z] 06:14:10     INFO - Waiting for event: 'recording-started' on [Front for performance/server1.conn12.child1/performanceActor22] for 1 time(s).
[task 2017-03-08T06:14:10.277169Z] 06:14:10     INFO - [1660] WARNING: Silently denied access to property "wrappedJSObject": value shadows a property on the standard prototype (@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/performance/profiler.js:568:25): file /home/worker/workspace/build/src/js/xpconnect/wrappers/XrayWrapper.cpp, line 254
[task 2017-03-08T06:14:10.434161Z] 06:14:10     INFO - Event: 'recording-started' on [Front for performance/server1.conn12.child1/performanceActor22] received.
[task 2017-03-08T06:14:10.738859Z] 06:14:10     INFO - Event: 'Performance:RecordingStateChange' on [object PerformanceController] received.
[task 2017-03-08T06:14:10.961336Z] 06:14:10     INFO - Waiting for event: 'Performance:RecordingStateChange' on [object PerformanceController] for 1 time(s) with arguments: {"1":"recording-stopping"}.
[task 2017-03-08T06:14:10.961602Z] 06:14:10     INFO - Waiting for event: 'Performance:RecordingStateChange' on [object PerformanceController] for 1 time(s) with arguments: {"1":"recording-stopped"}.
[task 2017-03-08T06:14:10.969417Z] 06:14:10     INFO - Waiting for event: 'recording-stopped' on [Front for performance/server1.conn12.child1/performanceActor22] for 1 time(s).
[task 2017-03-08T06:14:11.238698Z] 06:14:11     INFO - [1660] WARNING: Silently denied access to property "wrappedJSObject": value shadows a property on the standard prototype (@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/performance/profiler.js:568:25): file /home/worker/workspace/build/src/js/xpconnect/wrappers/XrayWrapper.cpp, line 254
[task 2017-03-08T06:14:12.841862Z] 06:14:12     INFO - Event: 'Performance:RecordingStateChange' on [object PerformanceController] received.
[task 2017-03-08T06:14:12.841975Z] 06:14:12     INFO - Ignoring event 'Performance:RecordingStateChange' with unexpected argument at index 1: recording-stopping
[task 2017-03-08T06:14:12.858182Z] 06:14:12     INFO - Event: 'recording-stopped' on [Front for performance/server1.conn12.child1/performanceActor22] received.
[task 2017-03-08T06:14:12.981402Z] 06:14:12     INFO - Event: 'Performance:RecordingStateChange' on [object PerformanceController] received.
[task 2017-03-08T06:14:13.231707Z] 06:14:13     INFO - Idly waiting for: 1000 milliseconds.
[task 2017-03-08T06:14:14.284406Z] 06:14:14     INFO - Waiting for event: 'Performance:RecordingStateChange' on [object PerformanceController] for 1 time(s) with arguments: {"1":"recording-stopping"}.
[task 2017-03-08T06:14:14.286028Z] 06:14:14     INFO - Waiting for event: 'Performance:RecordingStateChange' on [object PerformanceController] for 1 time(s) with arguments: {"1":"recording-stopped"}.
[task 2017-03-08T06:14:14.293469Z] 06:14:14     INFO - Waiting for event: 'recording-stopped' on [Front for performance/server1.conn12.child1/performanceActor22] for 1 time(s).
[task 2017-03-08T06:14:14.815901Z] 06:14:14     INFO - [1660] WARNING: Silently denied access to property "wrappedJSObject": value shadows a property on the standard prototype (@resource://gre/modules/commonjs/toolkit/loader.js -> resource://devtools/server/performance/profiler.js:568:25): file /home/worker/workspace/build/src/js/xpconnect/wrappers/XrayWrapper.cpp, line 254
[task 2017-03-08T06:14:15.351322Z] 06:14:15     INFO - ###!!! ERROR: Potential deadlock detected:
[task 2017-03-08T06:14:15.351523Z] 06:14:15     INFO - === Cyclical dependency starts at
[task 2017-03-08T06:14:15.351614Z] 06:14:15     INFO - --- Mutex : StaticMutex (currently acquired)
[task 2017-03-08T06:14:15.351693Z] 06:14:15     INFO -  calling context
[task 2017-03-08T06:14:15.351773Z] 06:14:15     INFO -   [stack trace unavailable]
[task 2017-03-08T06:14:15.351841Z] 06:14:15     INFO - === Cycle completed at
[task 2017-03-08T06:14:15.351927Z] 06:14:15     INFO - --- Mutex : StaticMutex (currently acquired)
[task 2017-03-08T06:14:15.352006Z] 06:14:15     INFO -  calling context
[task 2017-03-08T06:14:15.352087Z] 06:14:15     INFO -   [stack trace unavailable]
[task 2017-03-08T06:14:15.352166Z] 06:14:15     INFO - ###!!! Deadlock may happen NOW!
[task 2017-03-08T06:14:15.352244Z] 06:14:15     INFO - [1660] ###!!! ASSERTION: Potential deadlock detected:
[task 2017-03-08T06:14:15.352371Z] 06:14:15     INFO - Cyclical dependency starts at
[task 2017-03-08T06:14:15.352589Z] 06:14:15     INFO - Mutex : StaticMutex (currently acquired)
[task 2017-03-08T06:14:15.352892Z] 06:14:15     INFO - Cycle completed at
[task 2017-03-08T06:14:15.353336Z] 06:14:15     INFO - Mutex : StaticMutex (currently acquired)
[task 2017-03-08T06:14:15.353798Z] 06:14:15     INFO - ###!!! Deadlock may happen NOW!
[task 2017-03-08T06:14:15.354264Z] 06:14:15     INFO - : 'Error', file /home/worker/workspace/build/src/xpcom/threads/BlockingResourceBase.cpp, line 307
[task 2017-03-08T06:14:42.648491Z] 06:14:42     INFO - #01: mozilla::OffTheBooksMutex::Lock [xpcom/threads/BlockingResourceBase.cpp:382]
[task 2017-03-08T06:14:42.649144Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.650085Z] 06:14:42     INFO - #02: profiler_log [tools/profiler/core/platform.cpp:1569]
[task 2017-03-08T06:14:42.650578Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.651308Z] 06:14:42     INFO - #03: vprintf_stderr [xpcom/base/nsCRTGlue.cpp:417]
[task 2017-03-08T06:14:42.651788Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.652770Z] 06:14:42     INFO - #04: printf_stderr [xpcom/base/nsCRTGlue.cpp:428]
[task 2017-03-08T06:14:42.652813Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.653839Z] 06:14:42     INFO - #05: nsDocShell::~nsDocShell [docshell/base/nsDocShell.cpp:889]
[task 2017-03-08T06:14:42.654329Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.654948Z] 06:14:42     INFO - #06: nsDocShell::~nsDocShell [docshell/base/nsDocShell.cpp:891]
[task 2017-03-08T06:14:42.655624Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.656734Z] 06:14:42     INFO - #07: nsDocLoader::Release [uriloader/base/nsDocLoader.cpp:172]
[task 2017-03-08T06:14:42.657585Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.658646Z] 06:14:42     INFO - #08: nsDocShell::Release [docshell/base/nsDocShell.cpp:940]
[task 2017-03-08T06:14:42.659772Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.660790Z] 06:14:42     INFO - #09: mozilla::SegmentedVector<nsCOMPtr<nsISupports>, 4096ul, mozilla::MallocAllocPolicy>::SegmentImpl<509ul>::~SegmentImpl [xpcom/base/nsCOMPtr.h:801]
[task 2017-03-08T06:14:42.661588Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.662516Z] 06:14:42     INFO - #10: mozilla::SegmentedVector<nsCOMPtr<nsISupports>, 4096ul, mozilla::MallocAllocPolicy>::PopLastN [mfbt/AllocPolicy.h:118]
[task 2017-03-08T06:14:42.663589Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.664385Z] 06:14:42     INFO - #11: mozilla::dom::DeferredFinalizerImpl<nsISupports>::DeferredFinalize [dom/bindings/BindingUtils.h:2802]
[task 2017-03-08T06:14:42.664944Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.665691Z] 06:14:42     INFO - #12: mozilla::IncrementalFinalizeRunnable::ReleaseNow [xpcom/base/CycleCollectedJSContext.cpp:1613]
[task 2017-03-08T06:14:42.666564Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.667399Z] 06:14:42     INFO - #13: mozilla::CycleCollectedJSContext::FinalizeDeferredThings [xpcom/base/CycleCollectedJSContext.cpp:1687]
[task 2017-03-08T06:14:42.667658Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.668829Z] 06:14:42     INFO - #14: mozilla::CycleCollectedJSContext::OnGC [xpcom/base/CycleCollectedJSContext.cpp:1733]
[task 2017-03-08T06:14:42.669395Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.669460Z] 06:14:42     INFO - #15: js::gc::GCRuntime::gcCycle [js/src/jsgc.cpp:6369]
[task 2017-03-08T06:14:42.670092Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.670182Z] 06:14:42     INFO - #16: js::gc::GCRuntime::collect [js/src/jsgc.cpp:6500]
[task 2017-03-08T06:14:42.670789Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.671416Z] 06:14:42     INFO - #17: js::gc::GCRuntime::gcSlice [js/src/jsgc.cpp:6585]
[task 2017-03-08T06:14:42.671462Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.672077Z] 06:14:42     INFO - #18: js::gc::GCRuntime::gcIfRequested [js/src/jsgc.cpp:6779]
[task 2017-03-08T06:14:42.672125Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.672753Z] 06:14:42     INFO - #19: js::gc::GCRuntime::gcIfNeededPerAllocation [js/src/gc/Allocator.cpp:236]
[task 2017-03-08T06:14:42.672802Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.673418Z] 06:14:42     INFO - #20: js::gc::GCRuntime::checkAllocatorState<(js::AllowGC)1u> [js/src/gc/Allocator.cpp:191]
[task 2017-03-08T06:14:42.673467Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.674093Z] 06:14:42     INFO - #21: js::Allocate<JSString, (js::AllowGC)1u> [js/src/gc/Allocator.cpp:142]
[task 2017-03-08T06:14:42.674141Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.674765Z] 06:14:42     INFO - #22: JSFlatString::new_<(js::AllowGC)1u, unsigned char> [js/src/vm/String-inl.h:229]
[task 2017-03-08T06:14:42.674814Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.675402Z] 06:14:42     INFO - #23: NewStringDeflated<(js::AllowGC)1u> [js/src/vm/String.cpp:1221]
[task 2017-03-08T06:14:42.675481Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.675555Z] 06:14:42     INFO - #24: js::JSONParser<char16_t>::readString<(js::JSONParserBase::StringType)1u> [js/src/vm/JSONParser.cpp:139]
[task 2017-03-08T06:14:42.676127Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.676187Z] 06:14:42     INFO - #25: js::JSONParser<char16_t>::parse [js/src/vm/JSONParser.cpp:701]
[task 2017-03-08T06:14:42.676779Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.676881Z] 06:14:42     INFO - #26: js::ParseJSONWithReviver<char16_t> [js/src/json.cpp:877]
[task 2017-03-08T06:14:42.676926Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.677521Z] 06:14:42     INFO - #27: JS_ParseJSON [js/src/jsapi.cpp:5674]
[task 2017-03-08T06:14:42.678103Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.678171Z] 06:14:42     INFO - #28: profiler_get_profile_jsobject [tools/profiler/core/platform.cpp:1932]
[task 2017-03-08T06:14:42.678216Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.678787Z] 06:14:42     INFO - #29: nsProfiler::GetProfileData [tools/profiler/gecko/nsProfiler.cpp:171]
[task 2017-03-08T06:14:42.678834Z] 06:14:42     INFO - 
[task 2017-03-08T06:14:42.678956Z] 06:14:42     INFO - #30: NS_InvokeByIndex
[task 2017-03-08T06:14:42.678990Z] 06:14:42     INFO - 
[task 2017-03-08T06:20:12.675141Z] 06:20:12     INFO - Buffered messages logged at 06:13:59
[task 2017-03-08T06:20:12.676457Z] 06:20:12     INFO - Entering test bound 
[task 2017-03-08T06:20:12.677497Z] 06:20:12     INFO - Buffered messages logged at 06:14:10
[task 2017-03-08T06:20:12.678832Z] 06:20:12     INFO - TEST-PASS | devtools/client/performance/test/browser_perf-console-record-07.js | Three recordings found in the performance panel. - 
[task 2017-03-08T06:20:12.680051Z] 06:20:12     INFO - TEST-PASS | devtools/client/performance/test/browser_perf-console-record-07.js | Checking label of recording 1 - 
[task 2017-03-08T06:20:12.681280Z] 06:20:12     INFO - TEST-PASS | devtools/client/performance/test/browser_perf-console-record-07.js | Checking label of recording 2 - 
[task 2017-03-08T06:20:12.682135Z] 06:20:12     INFO - TEST-PASS | devtools/client/performance/test/browser_perf-console-record-07.js | Checking label of recording 3 - 
[task 2017-03-08T06:20:12.683136Z] 06:20:12     INFO - TEST-PASS | devtools/client/performance/test/browser_perf-console-record-07.js | The first console recording should be selected. - 
[task 2017-03-08T06:20:12.684375Z] 06:20:12     INFO - TEST-PASS | devtools/client/performance/test/browser_perf-console-record-07.js | All recordings should now be started. (1) - 
[task 2017-03-08T06:20:12.685336Z] 06:20:12     INFO - TEST-PASS | devtools/client/performance/test/browser_perf-console-record-07.js | All recordings should now be started. (2) - 
[task 2017-03-08T06:20:12.686589Z] 06:20:12     INFO - TEST-PASS | devtools/client/performance/test/browser_perf-console-record-07.js | All recordings should now be started. (3) - 
[task 2017-03-08T06:20:12.687746Z] 06:20:12     INFO - Buffered messages logged at 06:14:13
[task 2017-03-08T06:20:12.688924Z] 06:20:12     INFO - TEST-PASS | devtools/client/performance/test/browser_perf-console-record-07.js | Three recordings found in the performance panel. - 
[task 2017-03-08T06:20:12.689888Z] 06:20:12     INFO - TEST-PASS | devtools/client/performance/test/browser_perf-console-record-07.js | The first console recording should still be selected. - 
[task 2017-03-08T06:20:12.690889Z] 06:20:12     INFO - TEST-PASS | devtools/client/performance/test/browser_perf-console-record-07.js | The not most recent recording should not stop when calling console.profileEnd with no args. - 
[task 2017-03-08T06:20:12.692134Z] 06:20:12     INFO - TEST-PASS | devtools/client/performance/test/browser_perf-console-record-07.js | The not most recent recording should not stop when calling console.profileEnd with no args. - 
[task 2017-03-08T06:20:12.693454Z] 06:20:12     INFO - TEST-PASS | devtools/client/performance/test/browser_perf-console-record-07.js | Only the most recent recording should stop when calling console.profileEnd with no args. - 
[task 2017-03-08T06:20:12.694375Z] 06:20:12     INFO - Trying to `profileEnd` a non-existent console recording.
[task 2017-03-08T06:20:12.695408Z] 06:20:12     INFO - Buffered messages logged at 06:14:14
[task 2017-03-08T06:20:12.696643Z] 06:20:12     INFO - TEST-PASS | devtools/client/performance/test/browser_perf-console-record-07.js | Three recordings found in the performance panel. - 
[task 2017-03-08T06:20:12.697961Z] 06:20:12     INFO - TEST-PASS | devtools/client/performance/test/browser_perf-console-record-07.js | The first console recording should still be selected. - 
[task 2017-03-08T06:20:12.699161Z] 06:20:12     INFO - TEST-PASS | devtools/client/performance/test/browser_perf-console-record-07.js | The first recording should not be ended yet. - 
[task 2017-03-08T06:20:12.700126Z] 06:20:12     INFO - TEST-PASS | devtools/client/performance/test/browser_perf-console-record-07.js | The second recording should not be ended yet. - 
[task 2017-03-08T06:20:12.701080Z] 06:20:12     INFO - TEST-PASS | devtools/client/performance/test/browser_perf-console-record-07.js | The third recording should still be ended. - 
[task 2017-03-08T06:20:12.702050Z] 06:20:12     INFO - Buffered messages finished
[task 2017-03-08T06:20:12.702989Z] 06:20:12     INFO - TEST-UNEXPECTED-TIMEOUT | devtools/client/performance/test/browser_perf-console-record-07.js | application timed out after 330 seconds with no output
[task 2017-03-08T06:20:12.703951Z] 06:20:12    ERROR - Force-terminating active process(es).
[task 2017-03-08T06:20:12.705056Z] 06:20:12     INFO - Determining child pids from psutil
[task 2017-03-08T06:20:12.706282Z] 06:20:12     INFO - Found child pids: []
[task 2017-03-08T06:20:12.707153Z] 06:20:12     INFO - Killing process: 1660
[task 2017-03-08T06:20:12.708003Z] 06:20:12     INFO - TEST-INFO | started process screentopng
[task 2017-03-08T06:20:13.047745Z] 06:20:13     INFO - TEST-INFO | screentopng: exit 0
[task 2017-03-08T06:20:13.221385Z] 06:20:13     INFO - TEST-INFO | Main app process: exit 6
[task 2017-03-08T06:20:13.222859Z] 06:20:13    ERROR - TEST-UNEXPECTED-FAIL | ShutdownLeaks | process() called before end of test suite
[task 2017-03-08T06:20:13.222912Z] 06:20:13     INFO - Buffered messages finished
[task 2017-03-08T06:20:13.223218Z] 06:20:13    ERROR - TEST-UNEXPECTED-FAIL | devtools/client/performance/test/browser_perf-console-record-07.js | application terminated with exit code 6
[task 2017-03-08T06:20:13.223358Z] 06:20:13     INFO - runtests.py | Application ran for: 0:12:31.949021


that assertion and stack looks interesting.

I am not clear where this happens in the test file, here is a link to the source of the test:
https://dxr.mozilla.org/mozilla-central/source/devtools/client/performance/test/browser_perf-console-record-07.js?q=path%3Abrowser_perf-console-record-07.js&redirect_type=single

:gregtatum, can you help find someone to look at this, hopefully with a root cause it will be easier- but we should get this scheduled in for hacking on.

Comment 3

[Joel Maher ( :jmaher ) (UTC -8)]

my retriggers show a clear root cause:
https://treeherder.mozilla.org/#/jobs?repo=mozilla-inbound&filter-searchStr=dt1%20linux%20debug&tochange=4e90c48f26179dc59150ae002a46666014fd3cbc&fromchange=c55c0ec84a7275becab95d39edfd3a7b42119023&selectedJob=83109826

and the winner is bug 1342306 (part 3 patch).  :njn, I see you authored the patch in bug 1342306, can you help figure out why this is causing the devtools test to timeout?

Comment 4

[Greg Tatum [:gregtatum]]

I'm wrapping up my day here and I'll be out on a work week next week with less time to work on something like this. I looked into it a bit and it looks like the JSON.parse(JSON.stringify(value)) is failing in https://dxr.mozilla.org/mozilla-central/source/devtools/server/performance/profiler.js#564-575

There is a lot of privileged JS magic with the Xrays that is happening here that I'm not really familiar with. I tried rewriting that JSON trick to use plain JS, but couldn't get it working in the limited time I tried to tackle it.

Comment 5

[Nicholas Nethercote [inactive]]

I'll take a look on Monday.

Comment 6

[Intermittent Failures Robot]

30 failures in 172 pushes (0.174 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* autoland: 8
* try: 7
* mozilla-inbound: 7
* mozilla-central: 4
* oak: 2
* graphics: 2

Platform breakdown:
* linux64: 30

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1273422&startday=2017-03-10&endday=2017-03-10&tree=all

Comment 7

[Markus Stange [:mstange]]

That's a very useful debug message!

I just put a patch up in bug 1346356 which should fix the deadlock.

Comment 8

[Intermittent Failures Robot]

76 failures in 790 pushes (0.096 failures/push) were associated with this bug in the last 7 days. 

This is the #21 most frequent failure this week. 

** This failure happened more than 75 times this week! Resolving this bug is a very high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 1 week, the affected test(s) may be disabled. **  

Repository breakdown:
* mozilla-inbound: 25
* try: 16
* autoland: 15
* mozilla-central: 12
* graphics: 5
* oak: 3

Platform breakdown:
* linux64: 76

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1273422&startday=2017-03-06&endday=2017-03-12&tree=all

Comment 9

[Intermittent Failures Robot]

20 failures in 142 pushes (0.141 failures/push) were associated with this bug yesterday.   

Repository breakdown:
* autoland: 7
* try: 4
* mozilla-inbound: 4
* mozilla-central: 3
* oak: 1
* graphics: 1

Platform breakdown:
* linux64: 20

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1273422&startday=2017-03-13&endday=2017-03-13&tree=all

Comment 10

[Nicholas Nethercote [inactive]]

(In reply to Markus Stange [:mstange] from comment #7)
> That's a very useful debug message!
> 
> I just put a patch up in bug 1346356 which should fix the deadlock.

I believe the deadlock in that bug is a different deadlock. Look at comment 2.

- profiler_get_profile_jsobject() locks gPSMutex, calls ToJSON() and then
  calls JS_ParseJSON() on the result.

- JS_ParseJSON() does allocations, triggers a GC, which causes an nsDocShell to
  be freed, which prints a "--DOCSHELL" string via printf_stderr(), which the
  profiler has re-rerouted to profiler_log(), which locks gPSMutex.

We can attack this at either end. The easier end is in
profiler_get_profiler_jsobject() -- we can unlock gPSMutex before calling
JS_ParseJSON(). That's easy and sensible and I will do that.

But I also now understand how profiler_log() is hooked into printf_stderr(),
which bug 1004899 added. Wow, we really augment profiler logs with every bit of
info that goes through printf_stderr()? It's a profiler, not Google, so the
idea of sucking up any piece of data that might be useful is bizarre
to me. mstange, do you know if any of the printf_stderr() calls are used
meaningfully by the profiler add-on? I would love to remove this
printf_stderr/profiler integration...

Comment 11

[Joel Maher ( :jmaher ) (UTC -8)]

:njn, thanks for working on this, I am glad to see that there is progress towards finding a real fix- let me know if you need help testing stuff on try.

Comment 12

[Markus Stange [:mstange]]

(In reply to Nicholas Nethercote [:njn] from comment #10)
> (In reply to Markus Stange [:mstange] from comment #7)
> > That's a very useful debug message!
> > 
> > I just put a patch up in bug 1346356 which should fix the deadlock.
> 
> I believe the deadlock in that bug is a different deadlock. Look at comment
> 2.

Oops, you're completely right. And there is an actual stack trace there. I only saw the string "[stack trace unavailable]" and stopped reading...

> Wow, we really augment profiler logs with every bit of
> info that goes through printf_stderr()? It's a profiler, not Google, so the
> idea of sucking up any piece of data that might be useful is bizarre
> to me. mstange, do you know if any of the printf_stderr() calls are used
> meaningfully by the profiler add-on?

At the moment, all that happens with this data is that it ends up in the Log tab. The old cleopatra was also using it to draw layer trees and display lists, which was certainly a very roundabout way to get at the information.

I do think there is value in capturing everything you might need in a profile, as long as the overhead is acceptably low or there's a way to turn it off. The profiler makes it easy to share what was captured, and we can add UI that makes such data easier to look at. For example, perf.html lets you look at the stdout log per thread, instead of interleaving all threads the way your console would.

Comment 13

[Nathan Froyd [:froydnj]]

I can reproduce this consistently with the patch in bug 1312087.  My deadlock happens in browser_perf-console-record-04.js, but there are any number of open intermittent bugs around browser_perf-console-record*.js tests; I suspect we've been seeing deadlocks like this for a long time and some problem prevented them from being surfaced as actual deadlocks.

Comment 14

[Markus Stange [:mstange]]

(In reply to Nathan Froyd [:froydnj] from comment #13)
> I can reproduce this consistently with the patch in bug 1312087.

Can you check whether the patch in bug 1347044 fixes this for you?

> I suspect we've been seeing deadlocks like this for a long time and
> some problem prevented them from being surfaced as actual deadlocks.

I don't know if that's true because in the past we didn't really have much locking at all around the profiler. The lock that is creating the problem here is the one that was just added in bug 1342306.

Comment 15

[Nicholas Nethercote [inactive]]

froydnj: as mstange says, I'm confident this is my fault. At least, the recent spike is my fault.

jmaher: I just landed bug 1347044's patch on inbound. I'm confident it will fix this problem, but I'll let you make the final judgment and close this bug. Thanks.

Comment 16

[Joel Maher ( :jmaher ) (UTC -8)]

I haven't seen many failures in the last 12 hours other than try and autoland.  will check back in later in the day after the merge and a chance for more intermittents to show up.  Thanks for fixing this :)

Comment 17

[Intermittent Failures Robot]

38 failures in 777 pushes (0.049 failures/push) were associated with this bug in the last 7 days. 

This is the #46 most frequent failure this week.  

** This failure happened more than 30 times this week! Resolving this bug is a high priority. **

** Try to resolve this bug as soon as possible. If unresolved for 2 weeks, the affected test(s) may be disabled. ** 

Repository breakdown:
* try: 16
* autoland: 11
* mozilla-inbound: 4
* mozilla-central: 3
* graphics: 3
* oak: 1

Platform breakdown:
* linux64: 38

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1273422&startday=2017-03-13&endday=2017-03-19&tree=all

Comment 18

[Greg Tatum [:gregtatum]]

Thank you all for tackling this! I noticed a few other intermittents in the perf tools that spiked that aren't flaring up anymore with this fix.

Comment 19

[Intermittent Failures Robot]

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

Repository breakdown:
* mozilla-inbound: 1

Platform breakdown:
* windows7-32-vm: 1

For more details, see:
https://brasstacks.mozilla.com/orangefactor/?display=Bug&bugid=1273422&startday=2017-06-12&endday=2017-06-18&tree=all