1556687 - Perma Tier 2 TEST-UNEXPECTED-TIMEOUT | devtools/client/performance/test/browser_perf-recording-notices-03.js, browser_perf-recording-notices-04.js | application timed out after 370 seconds with no output

Status: RESOLVED INVALID

(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=249878504&repo=mozilla-central
Full log: https://queue.taskcluster.net/v1/task/QLy2QFsRRPKvOVoXwnaVdQ/runs/0/artifacts/public/logs/live_backing.log

---

07:37:11 INFO - TEST-START | devtools/client/performance/test/browser_perf-recording-notices-03.js
07:37:12 INFO - GECKO(2732) | Adding tab with url: http://example.com/browser/devtools/client/performance/test/doc_simple-test.html#8293585238976075.
07:37:12 INFO - GECKO(2732) | ++DOCSHELL 0000027064C93000 == 2 [pid = 9272] [id = {14ec432a-3785-46df-93a2-858ad02c7733}]
07:37:12 INFO - GECKO(2732) | ++DOMWINDOW == 3 (0000027064C237A0) [pid = 9272] [serial = 75] [outer = 0000000000000000]
07:37:12 INFO - GECKO(2732) | [Child 9272, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 662
07:37:12 INFO - GECKO(2732) | ++DOMWINDOW == 4 (000002705E9DAC00) [pid = 9272] [serial = 76] [outer = 0000027064C237A0]
07:37:12 INFO - GECKO(2732) | ++DOMWINDOW == 5 (0000027064C68C00) [pid = 9272] [serial = 77] [outer = 0000027064C237A0]
07:37:12 INFO - GECKO(2732) | Initializing a webconsole panel.
...
07:37:29 INFO - GECKO(2732) | Waiting for event: 'Performance:UI:RecordingProfilerStatusRendered' on [object PerformanceView] for 1 time(s).
07:37:29 INFO - GECKO(2732) | Event: 'Performance:UI:RecordingProfilerStatusRendered' on [object PerformanceView] received.
07:37:29 INFO - GECKO(2732) | Predicate returned true after 1 tries.
07:37:29 INFO - GECKO(2732) | Waiting for event: 'recording-started' on [Front for performance/server1.conn60.child1/performanceActor10] for 1 time(s).
07:37:29 INFO - GECKO(2732) | [Parent 4148, Main Thread] WARNING: NS_ENSURE_SUCCESS(rv, nullptr) failed with result 0x804B000A: file z:/build/build/src/extensions/permissions/nsPermission.cpp, line 42
07:37:29 INFO - GECKO(2732) | [Parent 4148, Main Thread] WARNING: NS_ENSURE_TRUE(principal) failed: file z:/build/build/src/extensions/permissions/nsPermission.cpp, line 54
07:37:31 INFO - GECKO(2732) | [Child 9272, Main Thread] WARNING: Silently denied access to property "wrappedJSObject": value shadows a property on the standard prototype (@resource://devtools/server/performance/profiler.js:569:30): file z:/build/build/src/js/xpconnect/wrappers/XrayWrapper.cpp, line 223
07:37:35 INFO - GECKO(2732) | Event: 'recording-started' on [Front for performance/server1.conn60.child1/performanceActor10] received.
07:37:35 INFO - GECKO(2732) | Waiting for event: 'Performance:UI:RecordingProfilerStatusRendered' on [object PerformanceView] for 1 time(s).
07:37:35 INFO - GECKO(2732) | Event: 'Performance:UI:RecordingProfilerStatusRendered' on [object PerformanceView] received.
07:37:35 INFO - GECKO(2732) | Predicate returned true after 1 tries.
07:37:35 INFO - GECKO(2732) | Waiting for event: 'Performance:RecordingSelected' on [object PerformanceController] for 1 time(s).
07:37:35 INFO - GECKO(2732) | Event: 'Performance:RecordingSelected' on [object PerformanceController] received.
07:37:35 INFO - GECKO(2732) | Waiting for event: 'Performance:UI:RecordingProfilerStatusRendered' on [object PerformanceView] for 1 time(s).
07:37:35 INFO - GECKO(2732) | Event: 'Performance:UI:RecordingProfilerStatusRendered' on [object PerformanceView] received.
07:37:35 INFO - GECKO(2732) | Idly waiting for: 100 milliseconds.
07:37:38 INFO - GECKO(2732) | Waiting for event: 'Performance:UI:RecordingProfilerStatusRendered' on [object PerformanceView] for 1 time(s).
07:37:38 INFO - GECKO(2732) | Event: 'Performance:UI:RecordingProfilerStatusRendered' on [object PerformanceView] received.
07:37:38 INFO - GECKO(2732) | Predicate returned true after 2 tries.
07:37:38 INFO - GECKO(2732) | Waiting for event: 'recording-stopped' on [Front for performance/server1.conn60.child1/performanceActor10] for 1 time(s).
07:37:42 INFO - GECKO(2732) | [Child 9272, Main Thread] WARNING: Silently denied access to property "wrappedJSObject": value shadows a property on the standard prototype (@resource://devtools/server/performance/profiler.js:569:30): file z:/build/build/src/js/xpconnect/wrappers/XrayWrapper.cpp, line 223
07:37:50 INFO - GECKO(2732) | [Child 9272, Main Thread] WARNING: No active window: file z:/build/build/src/js/xpconnect/src/XPCJSContext.cpp, line 662
07:37:52 INFO - GECKO(2732) | Event: 'recording-stopped' on [Front for performance/server1.conn60.child1/performanceActor10] received.
07:37:53 INFO - GECKO(2732) | Waiting for event: 'Performance:RecordingSelected' on [object PerformanceController] for 1 time(s).
07:37:53 INFO - GECKO(2732) | Event: 'Performance:RecordingSelected' on [object PerformanceController] received.
07:37:53 INFO - GECKO(2732) | Waiting for event: 'Performance:UI:RecordingProfilerStatusRendered' on [object PerformanceView] for 1 time(s).
07:37:53 INFO - GECKO(2732) | Event: 'Performance:UI:RecordingProfilerStatusRendered' on [object PerformanceView] received.
07:37:53 INFO - GECKO(2732) | Predicate returned true after 1 tries.
07:37:53 INFO - GECKO(2732) | Waiting for event: 'Performance:BackendReadyRecordingStop' on [object PerformanceController] for 1 time(s).
07:37:53 INFO - GECKO(2732) | Waiting for event: 'Performance:RecordingStateChange' on [object PerformanceController] for 1 time(s) with arguments: ["recording-stopping"].
07:37:53 INFO - GECKO(2732) | Waiting for event: 'Performance:RecordingStateChange' on [object PerformanceController] for 1 time(s) with arguments: ["recording-stopped"].
07:37:53 INFO - GECKO(2732) | Waiting for event: 'Performance:UI:StateChanged' on [object PerformanceView] for 1 time(s) with arguments: ["recorded"].
07:37:53 INFO - GECKO(2732) | Waiting for event: 'Performance:UI:OverviewRendered' on [object OverviewView] for 1 time(s) with arguments: [16].
07:37:53 INFO - GECKO(2732) | Waiting for event: 'Performance:UI:WaterfallRendered' on [object WaterfallView] for 1 time(s).
07:37:54 INFO - GECKO(2732) | Ignoring event 'Performance:UI:StateChanged' with unexpected argument at index 0: loading - expected recorded
07:37:54 INFO - GECKO(2732) | Event: 'Performance:RecordingStateChange' on [object PerformanceController] received.
07:37:54 INFO - GECKO(2732) | Ignoring event 'Performance:RecordingStateChange' with unexpected argument at index 0: recording-stopping - expected recording-stopped
07:37:55 INFO - GECKO(2732) | Event: 'Performance:UI:OverviewRendered' on [object OverviewView] received.
07:37:57 INFO - GECKO(2732) | Event: 'Performance:UI:StateChanged' on [object PerformanceView] received.
07:37:57 INFO - GECKO(2732) | Event: 'Performance:UI:WaterfallRendered' on [object WaterfallView] received.
07:37:57 INFO - GECKO(2732) | Event: 'Performance:RecordingStateChange' on [object PerformanceController] received.
07:37:58 INFO - GECKO(2732) | Event: 'Performance:BackendReadyRecordingStop' on [object PerformanceController] received.
07:37:58 INFO - GECKO(2732) | Destroying panel.
07:39:20 INFO - JavaScript error: resource://gre/modules/PlacesExpiration.jsm, line 762: TypeError: this._db is undefined
07:46:03 INFO - Buffered messages logged at 07:37:11
07:46:03 INFO - Entering test bound
07:46:03 INFO - Buffered messages logged at 07:37:29
07:46:03 INFO - TEST-PASS | devtools/client/performance/test/browser_perf-recording-notices-03.js | Buffer percentage increased in display (1). -
07:46:03 INFO - TEST-PASS | devtools/client/performance/test/browser_perf-recording-notices-03.js | Container has [buffer-status=in-progress] or [buffer-status=full]. -
07:46:03 INFO - TEST-PASS | devtools/client/performance/test/browser_perf-recording-notices-03.js | Buffer status text has correct percentage. -
07:46:03 INFO - Buffered messages logged at 07:37:35
07:46:03 INFO - TEST-PASS | devtools/client/performance/test/browser_perf-recording-notices-03.js | Buffer percentage increased in display (2). -
07:46:03 INFO - TEST-PASS | devtools/client/performance/test/browser_perf-recording-notices-03.js | Container has [buffer-status=in-progress] or [buffer-status=full]. -
07:46:03 INFO - TEST-PASS | devtools/client/performance/test/browser_perf-recording-notices-03.js | Buffer status text has correct percentage. -
07:46:03 INFO - Console message: [JavaScript Warning: "XrayWrapper denied access to property "wrappedJSObject" (reason: value shadows a property on the standard prototype). See https://developer.mozilla.org/en-US/docs/Xray_vision for more information. Note that only the first denied property access from a given global object will be reported." {file: "resource://devtools/server/performance/profiler.js" line: 569}]
07:46:03 INFO - Buffered messages logged at 07:37:38
07:46:03 INFO - TEST-PASS | devtools/client/performance/test/browser_perf-recording-notices-03.js | Percentage updated for newly selected recording. -
07:46:03 INFO - TEST-PASS | devtools/client/performance/test/browser_perf-recording-notices-03.js | Container has [buffer-status=in-progress] or [buffer-status=full]. -
07:46:03 INFO - TEST-PASS | devtools/client/performance/test/browser_perf-recording-notices-03.js | Buffer status text has correct percentage for console recording. -
07:46:03 INFO - Buffered messages logged at 07:37:53
07:46:03 INFO - TEST-PASS | devtools/client/performance/test/browser_perf-recording-notices-03.js | Buffer percentage increased in display (3). -
07:46:03 INFO - TEST-PASS | devtools/client/performance/test/browser_perf-recording-notices-03.js | Container has [buffer-status=in-progress] or [buffer-status=full]. -
07:46:03 INFO - TEST-PASS | devtools/client/performance/test/browser_perf-recording-notices-03.js | Buffer status text has correct percentage. -
07:46:03 INFO - Buffered messages logged at 07:39:53
07:46:03 INFO - Longer timeout required, waiting longer... Remaining timeouts: 2
07:46:03 INFO - Buffered messages finished
07:46:03 ERROR - TEST-UNEXPECTED-TIMEOUT | devtools/client/performance/test/browser_perf-recording-notices-03.js | application timed out after 370 seconds with no output
07:46:03 ERROR - Force-terminating active process(es).
07:46:03 INFO - Determining child pids from psutil...
07:46:03 INFO - [4148]
07:46:03 INFO - ==> process 4148 launched child process 6332 ("Z:\task_1559626268\build\application\firefox\firefox.exe" -contentproc --channel="4148.0.342940576\389759677" -parentBuildID 20190604034541 -prefsHandle 1880 -prefMapHandle 1876 -prefsLen 1 -prefMapSize 202526 -greomni "Z:\task_1559626268\build\application\firefox\omni.ja" -appomni "Z:\task_1559626268\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1559626268\build\application\firefox\browser" - 4148 "\.\pipe\gecko-crash-server-pipe.4148" 1968 gpu)
07:46:03 INFO - ==> process 4148 launched child process 9272 ("Z:\task_1559626268\build\application\firefox\firefox.exe" -contentproc --channel="4148.6.1141184224\1460662372" -childID 1 -isForBrowser -prefsHandle 2784 -prefMapHandle 2788 -prefsLen 2072 -prefMapSize 202526 -parentBuildID 20190604034541 -greomni "Z:\task_1559626268\build\application\firefox\omni.ja" -appomni "Z:\task_1559626268\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1559626268\build\application\firefox\browser" - 4148 "\.\pipe\gecko-crash-server-pipe.4148" 2796 tab)
07:46:03 INFO - ==> process 4148 launched child process 5504 ("Z:\task_1559626268\build\application\firefox\firefox.exe" -contentproc --channel="4148.13.1060068178\1873575098" -childID 2 -isForBrowser -prefsHandle 2812 -prefMapHandle 2764 -prefsLen 2169 -prefMapSize 202526 -parentBuildID 20190604034541 -greomni "Z:\task_1559626268\build\application\firefox\omni.ja" -appomni "Z:\task_1559626268\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1559626268\build\application\firefox\browser" - 4148 "\.\pipe\gecko-crash-server-pipe.4148" 2872 tab)
07:46:03 INFO - ==> process 4148 launched child process 8988 ("Z:\task_1559626268\build\application\firefox\firefox.exe" -contentproc --channel="4148.20.1676272298\319840345" -childID 3 -isForBrowser -prefsHandle 2896 -prefMapHandle 2888 -prefsLen 2169 -prefMapSize 202526 -parentBuildID 20190604034541 -greomni "Z:\task_1559626268\build\application\firefox\omni.ja" -appomni "Z:\task_1559626268\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1559626268\build\application\firefox\browser" - 4148 "\.\pipe\gecko-crash-server-pipe.4148" 2884 tab)
07:46:03 INFO - ==> process 4148 launched child process 9240 ("Z:\task_1559626268\build\application\firefox\firefox.exe" -contentproc --channel="4148.27.2126713031\904326899" -childID 4 -isForBrowser -prefsHandle 3552 -prefMapHandle 3556 -prefsLen 10544 -prefMapSize 202526 -parentBuildID 20190604034541 -greomni "Z:\task_1559626268\build\application\firefox\omni.ja" -appomni "Z:\task_1559626268\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1559626268\build\application\firefox\browser" - 4148 "\.\pipe\gecko-crash-server-pipe.4148" 3920 tab)
07:46:03 INFO - ==> process 4148 launched child process 3748 ("Z:\task_1559626268\build\application\firefox\firefox.exe" -contentproc --channel="4148.34.162411730\58430876" -childID 5 -isForBrowser -prefsHandle 3132 -prefMapHandle 3100 -prefsLen 10875 -prefMapSize 202526 -parentBuildID 20190604034541 -greomni "Z:\task_1559626268\build\application\firefox\omni.ja" -appomni "Z:\task_1559626268\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1559626268\build\application\firefox\browser" - 4148 "\.\pipe\gecko-crash-server-pipe.4148" 3904 tab)
07:46:03 INFO - ==> process 4148 launched child process 3064 ("Z:\task_1559626268\build\application\firefox\firefox.exe" -contentproc --channel="4148.41.46977239\247225983" -childID 6 -isForBrowser -prefsHandle 4280 -prefMapHandle 4284 -prefsLen 10875 -prefMapSize 202526 -parentBuildID 20190604034541 -greomni "Z:\task_1559626268\build\application\firefox\omni.ja" -appomni "Z:\task_1559626268\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1559626268\build\application\firefox\browser" - 4148 "\.\pipe\gecko-crash-server-pipe.4148" 4104 tab)
07:46:03 INFO - ==> process 4148 launched child process 2400 ("Z:\task_1559626268\build\application\firefox\firefox.exe" -contentproc --channel="4148.48.823327661\737994584" -childID 7 -isForBrowser -prefsHandle 4016 -prefMapHandle 1700 -prefsLen 12424 -prefMapSize 202526 -parentBuildID 20190604034541 -greomni "Z:\task_1559626268\build\application\firefox\omni.ja" -appomni "Z:\task_1559626268\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1559626268\build\application\firefox\browser" - 4148 "\.\pipe\gecko-crash-server-pipe.4148" 4164 tab)
07:46:03 INFO - ==> process 4148 launched child process 8816 ("Z:\task_1559626268\build\application\firefox\firefox.exe" -contentproc --channel="4148.55.1022841796\643678592" -childID 8 -isForBrowser -prefsHandle 4608 -prefMapHandle 4596 -prefsLen 12568 -prefMapSize 202526 -parentBuildID 20190604034541 -greomni "Z:\task_1559626268\build\application\firefox\omni.ja" -appomni "Z:\task_1559626268\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1559626268\build\application\firefox\browser" - 4148 "\.\pipe\gecko-crash-server-pipe.4148" 4624 tab)
07:46:03 INFO - ==> process 4148 launched child process 140 ("Z:\task_1559626268\build\application\firefox\firefox.exe" -contentproc --channel="4148.62.376080684\2006784891" -childID 9 -isForBrowser -prefsHandle 3640 -prefMapHandle 3608 -prefsLen 12568 -prefMapSize 202526 -parentBuildID 20190604034541 -greomni "Z:\task_1559626268\build\application\firefox\omni.ja" -appomni "Z:\task_1559626268\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1559626268\build\application\firefox\browser" - 4148 "\.\pipe\gecko-crash-server-pipe.4148" 4732 tab)
07:46:03 INFO - ==> process 4148 launched child process 2548 ("Z:\task_1559626268\build\application\firefox\firefox.exe" -contentproc --channel="4148.69.313441168\1449560734" -childID 10 -isForBrowser -prefsHandle 4788 -prefMapHandle 4792 -prefsLen 12568 -prefMapSize 202526 -parentBuildID 20190604034541 -greomni "Z:\task_1559626268\build\application\firefox\omni.ja" -appomni "Z:\task_1559626268\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1559626268\build\application\firefox\browser" - 4148 "\.\pipe\gecko-crash-server-pipe.4148" 4560 tab)
07:46:03 INFO - Found child pids: set([5504, 2400, 3748, 8988, 140, 8816, 9240, 4148, 3064, 9272, 2548, 6332])
07:46:03 INFO - Killing process: 5504
07:46:03 INFO - TEST-INFO | started process screenshot
07:46:04 INFO - TEST-INFO | screenshot: exit 0

Comment 1

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

Bisection reveals this gets caused by bug 1413546. Miko, please take a look.

The #ifdef rule by bug 1413546 looks obsolete now. Please drop it.
https://hg.mozilla.org/integration/autoland/rev/87409f291fa6a003f00ae782528bcd4734eeaee0

Comment 2

[Timothy Nikkel (:tnikkel)]

Seems like we timeout waiting on this line

https://searchfox.org/mozilla-central/rev/9eb2f739c165b4e294929f7b99fbb4d90f8a396b/devtools/client/performance/test/helpers/panel-utils.js#105

At least in the browser_perf-recording-notices-03.js failure. The browser_perf-recording-notices-04.js seems a little different.

Comment 3

[Miko Mynttinen]

Looking into this.

Comment 4

[Intermittent Failures Robot]

42 failures in 5197 pushes (0.008 failures/push) were associated with this bug in the last 7 days.

** 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:

• mozilla-central: 42

Platform breakdown:

• windows10-64-ccov: 42

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1556687&startday=2019-06-03&endday=2019-06-09&tree=all

Comment 5

[Timothy Nikkel (:tnikkel)]

We hang on this line

https://searchfox.org/mozilla-central/rev/c606cdd6d014fee4034da1702d484c0d41b604c9/devtools/client/performance/modules/widgets/graphs.js#245

(destroy of GraphController)

and that is because an earlier call to render in GraphController is hanging on this line

https://searchfox.org/mozilla-central/rev/c606cdd6d014fee4034da1702d484c0d41b604c9/devtools/client/performance/modules/widgets/graphs.js#222

That line does some communication with a worker, so I suspect that somehow the communication between that worker gets messed up.

Comment 6

[Timothy Nikkel (:tnikkel)]

Yeah, the work never responds back. More try pushes to see why.

Comment 7

[Timothy Nikkel (:tnikkel)]

The message runnable to the worker to start work never runs on the worker thread. It successfully gets dispatched. But it doesn't run on the worker thread. Some event does run on the worker thread. Trying to figure out what event does run and why the event we dispatched does not run.

Comment 8

[Timothy Nikkel (:tnikkel)]

A CompileScriptRunnable is dispatched to the worker when it is created, and it seems to be hanging when running this.

Comment 9

[Timothy Nikkel (:tnikkel)]

(In reply to Timothy Nikkel (:tnikkel) from comment #8)

A CompileScriptRunnable is dispatched to the worker when it is created, and
it seems to be hanging when running this.

Oh wait, that runs a sync run event loop thingy. But then why doesn't that process the event?

Comment 10

[Intermittent Failures Robot]

19 failures in 4753 pushes (0.004 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 19

Platform breakdown:

• windows10-64-ccov: 19

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1556687&startday=2019-06-10&endday=2019-06-16&tree=all

Comment 11

[Timothy Nikkel (:tnikkel)]

It seems that ScriptLoaderRunnable in dom/workers/ScriptedLoader.cpp never finishes because it never gets the stream complete notification.

Specifically,

https://searchfox.org/mozilla-central/rev/b3b401254229f0a26f7ee625ef5f09c6c31e3949/dom/workers/ScriptLoader.cpp#539

LoaderListener::OnStreamComplete just doesn't get called. What's weird about this is that LoaderListener is both a nsIStreamLoaderObserver and nsIRequestObserver but only the nsIStreamLoaderObserver part gets attached to anything to get notifications. The nsIRequestObserver doesn't get attached and so its methods are never called.

LoaderListener::OnStartRequest calls ScriptLoaderRunnable::OnStartRequest and that is a pretty long function with a bunch of code, and as best I can tell it's all dead code right now, it never runs. But that seems fishy.

Comment 12

[Timothy Nikkel (:tnikkel)]

If I try hooking up the nsIRequestObserver part of LoaderListener by passing listener as the third argument (as well as the second one) here

https://searchfox.org/mozilla-central/rev/b3b401254229f0a26f7ee625ef5f09c6c31e3949/dom/workers/ScriptLoader.cpp#1024

we can't even start the browser. So I don't know where or how that "dead" code was ever used.

Comment 13

[Miko Mynttinen]

The test failures seem timing related. Since this code is not being actively developed, I think that the reasonable action here is to disable this test for Tier2 platforms. Greg Tatum who works on DevTools agreed with this.

Comment 14

[Miko Mynttinen]

Timothy speculated that the root cause might be main thread starvation caused by additional paints. This happens only in the parent process, because the handling of the vsync events is slightly different1. The relevant code was added in bug 1339135.

Comment 15

[Timothy Nikkel (:tnikkel)]

We seem to be painting a lot more in the parent process because we get a ton of nsRefreshDriver::ScheduleViewManagerFlush calls there. Without parent rdl we very rarely get a ScheduleViewManagerFlush call in the parent, you can go tens of seconds without one. I modified the worker to "hang" at the same place as it "hangs" with parent RDL due to the main thread being flooded with paints to make sure we are comparing apples to apples.

Comment 16

[Timothy Nikkel (:tnikkel)]

The things causing the ScheduleViewManagerFlush calls is the devtools-throbber. It's in a hidden panel of a deck, so it's not visible. Not sure what prevents us from doing so many of these useless paints when parent RDL is disabled yet. It is not the retained display list check in nsIFrame::TryUpdateTransformOnly, we bail out and return false in both cases, just for a different reason when rdl is disabled (because there is no layer).

Comment 17

[Timothy Nikkel (:tnikkel)]

(In reply to Timothy Nikkel (:tnikkel) from comment #15)

Without parent rdl
we very rarely get a ScheduleViewManagerFlush call in the parent, you can go
tens of seconds without one.

This seems to not quite be true. I must have made a mistake.

I think I understand the root cause now.

With parent rdl disabled the hidden devtools throbber causes paints every refresh driver tick. It takes about 44ms to run this tick. So we fail to run at 60fps, and we get behind on transactions. The refresh driver checks if we are behind more than two transactions and makes ticks do nothing until we have caught up and composited a transaction two transaction ids ago. This in effect throttles the amount of work we do because we can't keep up and we don't flood the main thread.

When parent rdl is enabled the difference is that we immediately notice that the transaction is not necessary (nothing has changed visually) and we revoke the transaction id when we try to EndTransaction and paint on the layer manager. When we revoke the id we stay at the same transaction id and so the throttling code can't tell that we are "behind" a transaction and so we try to paint again immediately, and it gets revoke again etc. So we just try to paint continuously, painting takes more than 17ms (44ms) aka 60 fps and since refresh driver ticks can get higher priority this dominates the main thread and can prevent anything else from running.

Comment 18

[Intermittent Failures Robot]

22 failures in 2581 pushes (0.009 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 22

Platform breakdown:

• windows10-64-ccov: 22

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1556687&startday=2019-06-17&endday=2019-06-23&tree=all

Comment 19

[Intermittent Failures Robot]

10 failures in 4409 pushes (0.002 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 10

Platform breakdown:

• windows10-64-ccov: 10

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1556687&startday=2019-06-24&endday=2019-06-30&tree=all

Comment 20

[Intermittent Failures Robot]

19 failures in 3501 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 19

Platform breakdown:

• windows10-64-ccov: 19

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1556687&startday=2019-07-01&endday=2019-07-07&tree=all

Comment 21

[Intermittent Failures Robot]

22 failures in 4710 pushes (0.005 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 22

Platform breakdown:

• windows10-64-ccov: 22

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

Comment 22

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

Attachment: Bug 1556687 - Disable devtools/client/performance/test/browser_perf-recording-notices-03.js on Windows ccov because it always fails. r=jmaher

Comment 23

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/d97f5591d6e0
Disable devtools/client/performance/test/browser_perf-recording-notices-03.js on Windows ccov because it always fails. r=jmaher

Comment 24

[Noemi Erli[:noemi_erli]]

https://hg.mozilla.org/mozilla-central/rev/d97f5591d6e0

Comment 25

[Andreea Pavel [:apavel]]

Joel, looks like the failure here moved on to the next test, browser_perf-recording-notices-04.js : https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-07-15&endday=2019-07-20&tree=trunk&bug=1556687

Recent failure log: https://treeherder.mozilla.org/logviewer.html#/jobs?job_id=257523636&repo=mozilla-central&lineNumber=7586
12:13:08 INFO - TEST-START | devtools/client/performance/test/browser_perf-recording-notices-04.js
12:13:08 INFO - GECKO(9708) | Adding tab with url: http://example.com/browser/devtools/client/performance/test/doc_simple-test.html#4325110129536394.
12:13:08 INFO - GECKO(9708) | ++DOCSHELL 00000259F1399000 == 2 [pid = 11244] [id = {bc3f0014-ffd9-4b20-9538-ee31a054fff6}]
12:13:08 INFO - GECKO(9708) | ++DOMWINDOW == 4 (00000259F1340980) [pid = 11244] [serial = 91] [outer = 0000000000000000]

12:21:33 INFO - TEST-PASS | devtools/client/performance/test/browser_perf-recording-notices-04.js | Buffer status text has correct percentage. -
12:21:33 INFO - Buffered messages logged at 12:15:23
12:21:33 INFO - Longer timeout required, waiting longer... Remaining timeouts: 2
12:21:33 INFO - Buffered messages finished
12:21:33 ERROR - TEST-UNEXPECTED-TIMEOUT | devtools/client/performance/test/browser_perf-recording-notices-04.js | application timed out after 370 seconds with no output
12:21:33 ERROR - Force-terminating active process(es).
12:21:33 INFO - Determining child pids from psutil...
12:21:33 INFO - [7552]
12:21:33 INFO - ==> process 7552 launched child process 10956 ("Z:\task_1563618512\build\application\firefox\firefox.exe" -contentproc --channel="7552.0.371968468\1311554987" -parentBuildID 20190720095435 -prefsHandle 1896 -prefMapHandle 1804 -prefsLen 1 -prefMapSize 210449 -greomni "Z:\task_1563618512\build\application\firefox\omni.ja" -appomni "Z:\task_1563618512\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1563618512\build\application\firefox\browser" - 7552 "\.\pipe\gecko-crash-server-pipe.7552" 1984 gpu)
12:21:33 INFO - ==> process 7552 launched child process 11244 ("Z:\task_1563618512\build\application\firefox\firefox.exe" -contentproc --channel="7552.6.154125510\1389333477" -childID 1 -isForBrowser -prefsHandle 2780 -prefMapHandle 2784 -prefsLen 2091 -prefMapSize 210449 -parentBuildID 20190720095435 -greomni "Z:\task_1563618512\build\application\firefox\omni.ja" -appomni "Z:\task_1563618512\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1563618512\build\application\firefox\browser" - 7552 "\.\pipe\gecko-crash-server-pipe.7552" 1808 tab)
12:21:33 INFO - ==> process 7552 launched child process 9496 ("Z:\task_1563618512\build\application\firefox\firefox.exe" -contentproc --channel="7552.13.1940602718\1132489225" -childID 2 -isForBrowser -prefsHandle 2856 -prefMapHandle 2848 -prefsLen 2188 -prefMapSize 210449 -parentBuildID 20190720095435 -greomni "Z:\task_1563618512\build\application\firefox\omni.ja" -appomni "Z:\task_1563618512\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1563618512\build\application\firefox\browser" - 7552 "\.\pipe\gecko-crash-server-pipe.7552" 2908 tab)
12:21:33 INFO - ==> process 7552 launched child process 3444 ("Z:\task_1563618512\build\application\firefox\firefox.exe" -contentproc --channel="7552.20.1739087782\1968020784" -childID 3 -isForBrowser -prefsHandle 2972 -prefMapHandle 2968 -prefsLen 2249 -prefMapSize 210449 -parentBuildID 20190720095435 -greomni "Z:\task_1563618512\build\application\firefox\omni.ja" -appomni "Z:\task_1563618512\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1563618512\build\application\firefox\browser" - 7552 "\.\pipe\gecko-crash-server-pipe.7552" 2956 tab)
12:21:33 INFO - ==> process 7552 launched child process 11040 ("Z:\task_1563618512\build\application\firefox\firefox.exe" -contentproc --channel="7552.27.8328764\1876646847" -childID 4 -isForBrowser -prefsHandle 3920 -prefMapHandle 3924 -prefsLen 10662 -prefMapSize 210449 -parentBuildID 20190720095435 -greomni "Z:\task_1563618512\build\application\firefox\omni.ja" -appomni "Z:\task_1563618512\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1563618512\build\application\firefox\browser" - 7552 "\.\pipe\gecko-crash-server-pipe.7552" 3912 tab)
12:21:33 INFO - ==> process 7552 launched child process 7884 ("Z:\task_1563618512\build\application\firefox\firefox.exe" -contentproc --channel="7552.34.1797892364\647188854" -childID 5 -isForBrowser -prefsHandle 4140 -prefMapHandle 4144 -prefsLen 10993 -prefMapSize 210449 -parentBuildID 20190720095435 -greomni "Z:\task_1563618512\build\application\firefox\omni.ja" -appomni "Z:\task_1563618512\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1563618512\build\application\firefox\browser" - 7552 "\.\pipe\gecko-crash-server-pipe.7552" 3288 tab)
12:21:33 INFO - ==> process 7552 launched child process 7888 ("Z:\task_1563618512\build\application\firefox\firefox.exe" -contentproc --channel="7552.41.1931805783\1000939609" -childID 6 -isForBrowser -prefsHandle 4340 -prefMapHandle 4344 -prefsLen 10993 -prefMapSize 210449 -parentBuildID 20190720095435 -greomni "Z:\task_1563618512\build\application\firefox\omni.ja" -appomni "Z:\task_1563618512\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1563618512\build\application\firefox\browser" - 7552 "\.\pipe\gecko-crash-server-pipe.7552" 4248 tab)
12:21:33 INFO - ==> process 7552 launched child process 7316 ("Z:\task_1563618512\build\application\firefox\firefox.exe" -contentproc --channel="7552.48.302324948\638327261" -childID 7 -isForBrowser -prefsHandle 4308 -prefMapHandle 3624 -prefsLen 12542 -prefMapSize 210449 -parentBuildID 20190720095435 -greomni "Z:\task_1563618512\build\application\firefox\omni.ja" -appomni "Z:\task_1563618512\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1563618512\build\application\firefox\browser" - 7552 "\.\pipe\gecko-crash-server-pipe.7552" 3600 tab)
12:21:33 INFO - ==> process 7552 launched child process 10120 ("Z:\task_1563618512\build\application\firefox\firefox.exe" -contentproc --channel="7552.55.1822027337\786678957" -childID 8 -isForBrowser -prefsHandle 1332 -prefMapHandle 2696 -prefsLen 12686 -prefMapSize 210449 -parentBuildID 20190720095435 -greomni "Z:\task_1563618512\build\application\firefox\omni.ja" -appomni "Z:\task_1563618512\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1563618512\build\application\firefox\browser" - 7552 "\.\pipe\gecko-crash-server-pipe.7552" 3972 tab)
12:21:33 INFO - ==> process 7552 launched child process 4796 ("Z:\task_1563618512\build\application\firefox\firefox.exe" -contentproc --channel="7552.62.11765753\1632502399" -childID 9 -isForBrowser -prefsHandle 2416 -prefMapHandle 4568 -prefsLen 12686 -prefMapSize 210449 -parentBuildID 20190720095435 -greomni "Z:\task_1563618512\build\application\firefox\omni.ja" -appomni "Z:\task_1563618512\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1563618512\build\application\firefox\browser" - 7552 "\.\pipe\gecko-crash-server-pipe.7552" 3396 tab)
12:21:33 INFO - ==> process 7552 launched child process 7636 ("Z:\task_1563618512\build\application\firefox\firefox.exe" -contentproc --channel="7552.69.369346490\1774876153" -childID 10 -isForBrowser -prefsHandle 3972 -prefMapHandle 4592 -prefsLen 12686 -prefMapSize 210449 -parentBuildID 20190720095435 -greomni "Z:\task_1563618512\build\application\firefox\omni.ja" -appomni "Z:\task_1563618512\build\application\firefox\browser\omni.ja" -appdir "Z:\task_1563618512\build\application\firefox\browser" - 7552 "\.\pipe\gecko-crash-server-pipe.7552" 1560 tab)
12:21:33 INFO - Found child pids: set([7552, 11040, 7884, 10120, 10956, 11244, 7888, 3444, 7636, 9496, 7316, 4796])
12:21:33 INFO - Killing process: 7552
12:21:33 INFO - TEST-INFO | started process screenshot
12:21:33 INFO - TEST-INFO | screenshot: exit 0
12:21:34 INFO - Killing process: 11040

Should we disable this too? If we do, what are the changes this moves again to the next test?

Comment 26

[Timothy Nikkel (:tnikkel)]

(In reply to Andreea Pavel [:apavel] from comment #25)

Joel, looks like the failure here moved on to the next test, browser_perf-recording-notices-04.js : https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?startday=2019-07-15&endday=2019-07-20&tree=trunk&bug=1556687

Should we disable this too? If we do, what are the changes this moves again to the next test?

Yeah, any test that has the hidden devtools throbber, so anything with devtools open, they could happen in.

Comment 27

[Intermittent Failures Robot]

35 failures in 4298 pushes (0.008 failures/push) were associated with this bug in the last 7 days.

** 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:

• mozilla-central: 35

Platform breakdown:

• windows10-64-ccov: 35

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1556687&startday=2019-07-15&endday=2019-07-21&tree=all

Comment 28

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

:tnikkel, could you get us a list of tests with the hidden throbber? then we don't have to keep finding another regression the next week and so forth.

Comment 29

[Timothy Nikkel (:tnikkel)]

I'm not sure I can give you a list. Any test that has the devtools panel open I would think this could happen.

Comment 30

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

:apavel, can you skip browser_perf-recording-notices-04.js on win ccov. I am not sure how to search for other tests, so we will take this one at a time.

Comment 31

[Oana Pop-Rus]

Attachment: Bug 1556687 - disable browser_perf-recording-notices-04.js for frequent failures. r=jmaher

Comment 32

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/0cf1fcb2ff00
disable browser_perf-recording-notices-04.js for frequent failures. r=jmaher

Comment 33

[Noemi Erli[:noemi_erli]]

https://hg.mozilla.org/mozilla-central/rev/0cf1fcb2ff00

Comment 34

[Intermittent Failures Robot]

16 failures in 4608 pushes (0.003 failures/push) were associated with this bug in the last 7 days.

Repository breakdown:

• mozilla-central: 15
• try: 1

Platform breakdown:

• windows10-64-ccov: 16

For more details, see:
https://treeherder.mozilla.org/intermittent-failures.html#/bugdetails?bug=1556687&startday=2019-07-22&endday=2019-07-28&tree=all

Comment 35

[Jan Honza Odvarko [:Honza] (always need-info? me)]

I believe that this report is related to the old DevTools Profiler.
The Performance panel in DevTools now points to the new Firefox profiler available at profiler.firefox.com
Closing as Invalid bug