1577713 - Delayed `marionette-startup-requested` notification (up to 20s)

Status: RESOLVED INVALID

(Remote Protocol :: Marionette, defect, P3)

Description

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

Beside bug 1460193 which shows a delay after the marionette-startup-requested notification this is more serious given that the startup of Firefox can be delayed up to 20s before Marionette actually gets started.

Florian, do we have a way to maybe request more startup logging? If yes, I would happily enable it for our CI Mn test jobs.

Here an example from bug 1577701:

[task 2019-08-30T06:20:05.509Z] 06:20:05 INFO - PID 3504 | 1567146005494 Marionette TRACE Received observer notification profile-after-change
[task 2019-08-30T06:20:05.590Z] 06:20:05 INFO - PID 3504 | 1567146005568 Marionette TRACE Received observer notification toplevel-window-ready
[task 2019-08-30T06:20:05.687Z] 06:20:05 INFO - PID 3504 | 1567146005661 Marionette TRACE Received observer notification command-line-startup
[task 2019-08-30T06:20:05.688Z] 06:20:05 INFO - PID 3504 | 1567146005663 Marionette TRACE Received observer notification nsPref:changed
[task 2019-08-30T06:20:05.688Z] 06:20:05 INFO - PID 3504 | 1567146005663 Marionette DEBUG Init aborted (running=false, enabled=true, finalUIStartup=false)
[task 2019-08-30T06:20:05.917Z] 06:20:05 INFO - PID 3504 | 1567146005900 Marionette TRACE Received observer notification toplevel-window-ready
[task 2019-08-30T06:20:22.538Z] 06:20:22 INFO - PID 3504 | 1567146022516 Marionette TRACE Received observer notification marionette-startup-requested

Otherwise do you have any idea what could go on here?

Comment 1

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

Moving over needinfo for Mike from bug 1507121.

Comment 2

[Florian Quèze [:florian]]

(In reply to Henrik Skupin (:whimboo) [⌚️UTC+2] from comment #0)

Florian, do we have a way to maybe request more startup logging? If yes, I would happily enable it for our CI Mn test jobs.

It would be really nice to be able to look at a startup profile to figure out what's happening in that case. How easy is it to reproduce? Is this something that happens all the time on a specific configuration? Something intermittent that we could make force to happen with a few retriggers on try?

If you can somehow put the MOZ_PROFILER_STARTUP environment variable, and find a way to dump a profile and get it uploaded, we'll get the information we need.

Is there any chance we could make this slowness happen for the browser/base/content/test/performance/ folder of browser chrome mochitests? If so, if you make browser_startup_mainthreadio.js or browser_startup_syncIPC.js fail on try (eg. by removing some whitelist entries), you'll get profiles automatically uploaded with the failing jobs. I found bug 1551632 using this method.

Comment 3

[Mike Conley (:mconley) (:⚙️)]

Florian's right - we need to see a startup profile to get a clearer sense of what's happening here.

Comment 4

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

I will run some tests once the dependency has been fixed.

Comment 5

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

With bug 1726465 fixed we no longer have the marionette-startup-requested observer. As such I'm going ahead and close this bug.

Also I think that the underlying problem is actually in Firefox in regards of the toplevel-window-ready observer, which is already covered by bug 1382162.