1460193 - Delayed Marionette initialization of about 5s after `marionette-startup-requested`

Status: NEW

(Remote Protocol :: Marionette, defect, P3)

Description

[Henrik Skupin [:whimboo][⌚️UTC+2]]

I can see delays between sessionstore-windows-restored and the Marionette server initialization in various wdspec tests like the following:

https://treeherder.mozilla.org/logviewer.html#?job_id=177533609&repo=autoland

Here an excerpt:

[task 2018-05-08T19:37:26.286Z] 19:37:26     INFO - PID 4005 | 1525808246271	Marionette	DEBUG	Received observer notification command-line-startup
[task 2018-05-08T19:37:26.286Z] 19:37:26     INFO - PID 4005 | 1525808246271	Marionette	DEBUG	Received observer notification nsPref:changed
[task 2018-05-08T19:37:27.870Z] 19:37:27     INFO - PID 4005 | 1525808247863	Marionette	DEBUG	Received observer notification sessionstore-windows-restored
[task 2018-05-08T19:37:33.458Z] 19:37:33     INFO - PID 4005 | 1525808253454	Marionette	DEBUG	Setting recommended pref toolkit.cosmeticAnimations.enabled to false
[task 2018-05-08T19:37:33.459Z] 19:37:33     INFO - PID 4005 | 1525808253455	Marionette	DEBUG	Setting recommended pref datareporting.policy.dataSubmissionPolicyAccepted to false
[task 2018-05-08T19:37:33.528Z] 19:37:33     INFO - PID 4005 | 1525808253524	Marionette	DEBUG	New connections are accepted
[task 2018-05-08T19:37:33.529Z] 19:37:33     INFO - PID 4005 | 1525808253524	Marionette	INFO	Listening on port 2828

The recommended prefs are getting set with a delay of about 5s, which adds a given amount of startup delay to each test. Which then causes timeout failures for those wdspec tests which are using `new_session`.

Comment 1

[Andreas Tolfsen ❲:ato❳]

When sessionstore-windows-restored fires we also wait for the GFX
sanity test window on Windows:
https://searchfox.org/mozilla-central/rev/5ff2d7683078c96e4b11b8a13674daded935aa44/testing/marionette/components/marionette.js#371-394

Otherwise we despatch to the main thread and wait for it to become
idle twice in order to wait for delayed startup and startup tests:
https://searchfox.org/mozilla-central/rev/5ff2d7683078c96e4b11b8a13674daded935aa44/testing/marionette/components/marionette.js#420-428

Comment 2

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Yes, I think that I will add some more debug log lines to Marionette for startup. That way we could see if there is a GFX sanity test window open, how long it was open, or what else delayed us. I will do that on a different bug on Friday.

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+2]]

On bug 1418778 I noticed a possible slow startup of Firefox due to the warning "Received NS_ERROR_STORAGE_BUSY when attempting to open database '2918063365piupsah.sqlite'". But that was/is for debug builds.

Lately we mainly seem to see those failures for opt builds only, but it could still mean that this warning is the reason. It has been filed to get investigated on bug 1451621. It may have an influence.

Comment 4

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Here a log from a different debug build:

https://treeherder.mozilla.org/logviewer.html#?job_id=176421359&repo=mozilla-inbound&lineNumber=1400-1402

After `sessionstore-windows-restored` it took nearly 6 minutes before Marionette got initialized.

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Another info from:

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

> [task 2018-04-30T15:23:24.924Z] 15:23:24     INFO - PID 2621 | 1525101804915	Marionette	DEBUG	Received observer notification sessionstore-windows-restored
> [task 2018-04-30T15:23:27.034Z] 15:23:27     INFO - PID 2621 | [Parent 2929, Main Thread] WARNING: Suboptimal indexes for the SQL statement 0xe515dba0 (http://mzl.la/1FuID0j).: file /builds/worker/workspace/build/src/storage/mozStoragePrivateHelpers.cpp, line 114
> [task 2018-04-30T15:23:29.642Z] 15:23:29     INFO - PID 2621 | 1525101809630	Marionette	DEBUG	Setting recommended pref toolkit.cosmeticAnimations.enabled to false

This actually caused nearly such a 5s delay. The warning actually comes from inside the `checkAndLogStatementPerformance` method.

Comment 6

[Henrik Skupin [:whimboo][⌚️UTC+2]]

The additional logging we have in-place now already payed off given that we caught such an instance:

https://treeherder.mozilla.org/logviewer.html#?job_id=178636585&repo=mozilla-inbound&lineNumber=45252-45261

> [task 2018-05-15T23:00:10.972Z] 23:00:10     INFO - PID 4653 | 1526425210960	Marionette	DEBUG	Received observer notification sessionstore-windows-restored
> [task 2018-05-15T23:00:10.974Z] 23:00:10     INFO - PID 4653 | 1526425210962	Marionette	DEBUG	Waiting for delayed startup...
> [task 2018-05-15T23:00:12.733Z] 23:00:12     INFO - PID 4653 | [Parent 4971, Main Thread] WARNING: Suboptimal indexes for the SQL statement 0x7fb369ede2e0 (http://mzl.la/1FuID0j).: file /builds/worker/workspace/build/src/storage/mozStoragePrivateHelpers.cpp, line 114
> [task 2018-05-15T23:00:13.045Z] 23:00:13     INFO - PID 4653 | --DOMWINDOW == 2 (0x7fef0f310400) [pid = 5035] [serial = 2] [outer = (nil)] [url = about:blank]
> [task 2018-05-15T23:00:14.275Z] 23:00:14     INFO - PID 4653 | Couldn't convert chrome URL: chrome://branding/locale/brand.properties
> [task 2018-05-15T23:00:14.455Z] 23:00:14     INFO - PID 4653 | 1526425214444	Marionette	DEBUG	Waiting for startup tests...
> [task 2018-05-15T23:00:14.473Z] 23:00:14     INFO - PID 4653 | 1526425214457	Marionette	DEBUG	Setting recommended pref toolkit.cosmeticAnimations.enabled to false
> [task 2018-05-15T23:00:14.474Z] 23:00:14     INFO - PID 4653 | 1526425214461	Marionette	DEBUG	Setting recommended pref datareporting.policy.dataSubmissionPolicyAccepted to false
> [task 2018-05-15T23:00:14.475Z] 23:00:14     INFO - PID 4653 | 1526425214463	Marionette	DEBUG	Setting recommended pref dom.disable_beforeunload to true
> [task 2018-05-15T23:00:14.853Z] 23:00:14     INFO - PID 4653 | 1526425214848	Marionette	INFO	Listening on port 2828

Something clearly delays the startup here while waiting for the delayed startup. Usually it is kinda fast and doesn't take more than 1s. I wonder if the warning for "Suboptimal indexes" is related here, whereby this only happens for QuantumRender builds, so WebRender might also be a source.

The code for delayed startup can be found here:
https://dxr.mozilla.org/mozilla-central/rev/cf3ee14023483cbbb57129479537c713e22c1980/browser/base/content/browser.js#1375-1567

It means a custom build has to be made with more logging inside of delayed startup, so we could figure out which code takes that long.

Comment 7

[Henrik Skupin [:whimboo][⌚️UTC+2]]

I just found another case of delayed startup. This time for `sessionstore-windows-restored` of an opt build, which seems to take 7 seconds to restore the windows:

https://treeherder.mozilla.org/logviewer.html#?job_id=178805143&repo=autoland&lineNumber=24556-24561

> [task 2018-05-16T17:03:49.877Z] 17:03:49     INFO - PID 2960 | 1526490229873	Marionette	DEBUG	Received observer notification command-line-startup
> [task 2018-05-16T17:03:49.877Z] 17:03:49     INFO - PID 2960 | 1526490229874	Marionette	DEBUG	Received observer notification nsPref:changed
> [task 2018-05-16T17:03:49.879Z] 17:03:49     INFO - PID 2960 | 1526490229874	Marionette	DEBUG	Init aborted (running=false, enabled=true, finalUIStartup=false)
> [task 2018-05-16T17:03:56.519Z] 17:03:56     INFO - PID 2960 | GLib-GIO-Message: Using the 'memory' GSettings backend.  Your settings will not be saved or shared with other applications.
> [task 2018-05-16T17:03:56.758Z] 17:03:56     INFO - PID 2960 | 1526490236747	Marionette	DEBUG	Received observer notification sessionstore-windows-restored

Mike, do you have an idea?

Comment 8

[Mike de Boer [:mikedeboer]]

Hi Henrik, sorry for the late reply.

This could be anything - sessionstore is basically one big batching machine that opens windows, tabs and restores their contents right away when in view. This kicks of _all_ the browser machinery you can think of, so where it might seem that sessionstore is doing something silly, it is actually more likely that one or more of plugin, graphics, dom or security components is blocking the main thread for a while, which pauses JS execution on the main thread.

The only thing I could see us ever make sense of this bug is by checking out Gecko Profiler profiles, when and if they're spit out by Marionette.
(This might actually be a cool automation idea ;-) )

Comment 9

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Marionette has its own observer notification (bug 1530979) now, so adjusting the bug summary.