1216232 - MozRegression takes too long to launch a downloaded build

Status: RESOLVED FIXED

(Testing :: mozregression, defect)

Description

[:Felipe Gomes (needinfo for replies!)]

From the moment it prints  "Running nightly" to the moment it prints "Launching", mozregression takes usually at least 30s for me, sometimes taking over 90s. It really adds up during regression-finding..

e.g.
> 33:16.61 LOG: MainThread Test Runner INFO Testing inbound build built on 2015-07-16 12:11:26.667000, revision 02187d02
> 33:42.86 LOG: MainThread Test Runner INFO Launching /private/var/folders/_5/zc0pb1x91qx2_qkwhcbxd_640000gn/T/tmpnC3O_y/Nightly.app/Contents/MacOS/firefox

Comment 1

[Julien Pagès (:parkouss)]

Wow, that seems really long. On my GNU/Linux box, it takes around 10 seconds probably the time to untar the file.

Not sure about mac tough.

> 0:04.90 LOG: MainThread Test Runner INFO Running nightly for 2015-08-18
> 0:13.85 LOG: MainThread Test Runner INFO Launching /tmp/tmprXigIi/firefox/firefox

We could investigate this more, and try to reduce the time needed here. I highly suspect that we should look into mozinstall, not mozregression itself.

Will, any ideas ? Do you also need to wait 30 seconds ?

Comment 2

[William Lachance (:wlach)]

Not noticing this here on my Mac 10.11 laptop. Felipe, I think this might be something particular to your system?

Comment 3

[:Felipe Gomes (needinfo for replies!)]

It could be. Is there some verbose mode or something else that I could do to see what it is doing during this time?

Comment 4

[William Lachance (:wlach)]

(In reply to :Felipe Gomes from comment #3)
> It could be. Is there some verbose mode or something else that I could do to
> see what it is doing during this time?

Try --log-mach-verbose ?

Comment 5

[MikeLing]

Hmm, I got almost same time to run the build

> ===== Downloaded 100% =====
> 7:58.37 LOG: MainThread Test Runner INFO Testing inbound build built on 2015-10-15 11:23:51.038000, revision ceb07c2b
>  8:26.66 LOG: MainThread Test Runner INFO Launching /private/var/folders/z3/kxrbxwz55q55qfnrg17v_4wm0000gn/T/tmpm9yyA6/Nightly.app/Contents/MacOS/firefox

and I'm using Mac 10.11 laptop too

Comment 6

[Julien Pagès (:parkouss)]

Attachment: profile_start.patch

Hm, I suspect that mozinstall is the root cause here, but it might be the profile creation/cloning also. Mikeling, do you mind applying this patch and post here the numbers ?

Comment 7

[MikeLing]

(In reply to Julien Pagès (:parkouss) from comment #6)
> Created attachment 8678085 [details] [diff] [review]
> profile_start.patch
> 
> Hm, I suspect that mozinstall is the root cause here, but it might be the
> profile creation/cloning also. Mikeling, do you mind applying this patch and
> post here the numbers ?

i'm totally ok with that, but I can't reply you soon because my network in the evening is always bad, so I will test that in the tomorrow morning or so.

Comment 8

[:Felipe Gomes (needinfo for replies!)]

I applied the patch and, for me, most of the time was spent in mozinstall.

I'm also seeing a big gap between the time the time it shows "Using local file" until it shows "Running nightly". This gap doesn't happen when the file was downloaded.

> 3:53.09 LOG: MainThread download INFO Using local file: /Users/felipe/moz/mozregression/persist/2015-02-05--mozilla-central--firefox-38.0a1.en-US.mac.dmg
> 4:11.35 LOG: MainThread Test Runner INFO Running nightly for 2015-02-05
> 4:11.35 LOG: MainThread Test Runner INFO BEGIN MOZINSTALL
> 4:37.81 LOG: MainThread Test Runner INFO END MOZINSTALL
> 4:37.81 LOG: MainThread Test Runner INFO BEGIN PROFILE
> 4:37.81 LOG: MainThread Test Runner INFO END PROFILE


fwiw, --log-mach-verbose doesn't do anything for me.

Another sample:

> $ mozregression --good 2015-09-15 --bad 2015-09-20 --log-mach-verbose
>  0:07.09 LOG: MainThread download INFO Using local file: /Users/felipe/moz/mozregression/persist/2015-09-18--mozilla-> central--firefox-43.0a1.en-US.mac.dmg
>  0:10.79 LOG: MainThread Test Runner INFO Running nightly for 2015-09-18
>  0:10.80 LOG: MainThread Test Runner INFO BEGIN MOZINSTALL
>  0:25.11 LOG: MainThread Test Runner INFO END MOZINSTALL
>  0:25.11 LOG: MainThread Test Runner INFO BEGIN PROFILE
>  0:25.11 LOG: MainThread Test Runner INFO END PROFILE
>  0:25.11 LOG: MainThread Test Runner INFO Launching /private/var/folders/_5/zc0pb1x91qx2_qkwhcbxd_640000gn/T/tmpYzGlGH/> FirefoxNightly.app/Contents/MacOS/firefox

Comment 9

[Julien Pagès (:parkouss)]

Thanks Felipe.

So, based on your two samples, 15 - 26 seconds for mozinstall step. So this could be something to look at (again, not sure what we can do, still we can have a look), but the real problem seems to be the other gap.

This other big gap is most probably due to mozregression trying to find the next builds to download. So adding "--no-background-dl" should remove that gap. Without that flag, mozregression downloads the two future good/bad builds in background while you are trying the current build - this usually makes things faster since you wait less after, but it has the side effect of being slow just after the current build has been downloaded since it have to look for future builds. Note that I think generally it is a good option - please compare and give me some feedback.

For now you can't set this option in the config file (if you want --no-background-dl to be the default for you) - please open a bug if you need or want it, I'll be happy to fix that. :)

Please note that current mozregression use an old http/ftp server (which is slow) since a couple days, but I will change that soon (this week end or early next week) and this should use again the faster server archive.mozilla.org (it was broken for maintenance).

Comment 10

[Julien Pagès (:parkouss)]

So, I don't think we can do much here. The background in download feature is a nice default to most user I think.

One last thing you can try to save a few seconds in the "mozinstall" step would be to use --profile-persistence=clone-first. It would only create a copy of the profile for the first tested build, then reuse it directly for other tested builds during the run. Note that it may not be what you want, because profile modifications are then persistent accross a run. As a side note, you can set this as the default in your configuration file:

In ~/.mozilla/mozregression/mozregression.cfg:
profile-persistence = clone-first

:Felipe, Does that help ?

Comment 11

[Julien Pagès (:parkouss)]

Attachment: reduce build launch time

After more thinking, I came up with a new idea to improve the build launch time.

The idea is to look for the next builds to download and run the application in parallel, in a dedicated thread. In the given example below, we had two gaps (14s + 26s = 40s). Now this should be reduced to only 26s (the time to install) since both actions are parallelized.

I'd like your review/feedback on this guys!

Comment 12

[MikeLing]

Comment on attachment 8698565 [details] [review]
reduce build launch time

I like this ideal, and I test it. https://pastebin.mozilla.org/8854753

You can see the intervals between found build(2015-12-17T09:57:45) and launch it(2015-12-17T09:58:12) is about 27 seconds. 

BTW, why we always have error like ERROR : Unable to stop the application? Not sure if we have it in the early version(I haven't pay attention to the information in log view before) I will roll back to the early version and look more into it.

I gonna feedback+ for this anyway, thank you parkouss :)

Comment 13

[Julien Pagès (:parkouss)]

(In reply to MikeLing from comment #12)
> Comment on attachment 8698565 [details] [review]
> reduce build launch time
> 
> I like this ideal, and I test it. https://pastebin.mozilla.org/8854753
> 
> You can see the intervals between found build(2015-12-17T09:57:45) and
> launch it(2015-12-17T09:58:12) is about 27 seconds. 

So as discussed on irc, this is a command line only feature for now. Once accepted and merged, I'm going to do the same for the GUI. (I already started to work on it, but this relies on the current work)

> BTW, why we always have error like ERROR : Unable to stop the application?
> Not sure if we have it in the early version(I haven't pay attention to the
> information in log view before) I will roll back to the early version and
> look more into it.

Oh, I don't see that. If you can investigate a bit more and open a bug if needed, that would be awesome!

Comment 14

[William Lachance (:wlach)]

Comment on attachment 8698565 [details] [review]
reduce build launch time

lgtm

Comment 15

[Julien Pagès (:parkouss)]

Landed in https://github.com/mozilla/mozregression/commit/339c1792cac782b0bcd9a8581b70d1b3f1930107.