Open Bug 1577713 Opened 1 year ago Updated 9 months ago

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

Categories

(Testing :: Marionette, defect, P3)

Version 3
defect

Tracking

(Not tracked)

People

(Reporter: whimboo, Unassigned)

References

(Blocks 4 open bugs)

Details

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?

Flags: needinfo?(florian)

Moving over needinfo for Mike from bug 1507121.

Flags: needinfo?(mconley)

(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.

Flags: needinfo?(florian)

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

Flags: needinfo?(mconley) → needinfo?(hskupin)
Depends on: 1608370
Flags: needinfo?(hskupin)

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

Blocks: 1382162
You need to log in before you can comment on or make changes to this bug.