896025 - "Firefox seems slow to start" algorithm uses the wrong startup time after a crash

Status: RESOLVED FIXED

(Firefox :: General, defect)

Description

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

So, this is what happened:
1. I crashed while using the new google maps
2. I asked to submit the report and restart the browser
3. I selected a profile
4. Firefox started up and I was notified of slow startup, but it actually took a very short time to start, barely noticeable (I have an hybrid ssd+hard disk)

I took a look at the code and it does this:

let currentTime = Date.now() - Services.startup.getStartupInfo().process;

So, currently it's 21:30, if I execute
Services.startup.getStartupInfo().process
in the Browser console, it returns 16:37, that means it thinks my startup took 5 hours. That looks "broken".

Comment 1

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

at 16:37 I restarted the process to install today's update, that time was registered.
Looks like the crash restart didn't register a new timestamp and instead the previous restart was accounted for

Comment 2

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

I verified in Process Explorer, the process start time is correct, so the problem doesn't seem to come from the OS.

Comment 3

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

So, my first suspect is MOZ_APP_RESTART, it's an environment variable we set on restart, cause we reuse the same process and the process startup time would be wrong. we never reset this env, ideally it dies with the process.
Since env is inherited from parent to child processes, I wonder if somehow the crash reporter may pass the env from the old to the new Firefox process when restarting it.

Now, I looked at the environment of the current process, the one that shown me the notification and bang, found MOZ_APP_RESTART = 60262339134792
it should not be there as far as I can tell.
Maybe the crash reporter should create a clean env for the new process?

Comment 4

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

fwiw, a very simple fix would be to remove MOZ_APP_RESTART after first use.

Comment 5

[Gabriele Svelto [:gsvelto] (PTO)]

FYI the MOZ_APP_RESTART environment variable is also causing other problems, see bug 852250 for example. It might be worth trying to address all its issues in one go if we decide to fix it.

Comment 6

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

(In reply to Gabriele Svelto [:gsvelto] from comment #5)
> FYI the MOZ_APP_RESTART environment variable is also causing other problems,
> see bug 852250 for example. It might be worth trying to address all its
> issues in one go if we decide to fix it.

That's sort of a scope creep. We have a visible user issue here due to a support notification being shown without a valid reason, saying Firefox is slow, when it's not.  We should probably not block fixing this on a bug that is just requesting a more precise measurement. These two bugs appear having a totally different priority.

That said, looks like MOZ_APP_RESTART should not contain any value, it should just mark the fact we are reusing the process, next startup should probably just check for its existence and use Now() as the startup time, asap in the startup timeline. This can be totally done regardless of any fix taken in this bug.

Comment 7

[Gabriele Svelto [:gsvelto] (PTO)]

(In reply to Marco Bonardo [:mak] from comment #6)
> That's sort of a scope creep. We have a visible user issue here due to a
> support notification being shown without a valid reason, saying Firefox is
> slow, when it's not.

Technically that could happen also with bug 852250; I think it was noticed because we found instances in our telemetry where startup seemed slow due to the process shutdown time being accounted in it. But then again I agree, the problem is far more severe here and the fix is of different nature too.

> That said, looks like MOZ_APP_RESTART should not contain any value, it
> should just mark the fact we are reusing the process, next startup should
> probably just check for its existence and use Now() as the startup time,
> asap in the startup timeline.

That sounds like a very good approach, in fact I'll take note in bug 852250, thanks :)

Comment 8

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

(In reply to Gabriele Svelto [:gsvelto] from comment #7)
> Technically that could happen also with bug 852250.

Right, if shutdown takes more than 60 seconds it may cause the same issue. But in that case the notification may still be good, a restart has been unexpectedly slow, hints given may help the user.
Btw, if possible I totally agree both issues should be fixed.

Comment 9

[(not currently active) Ted Mielczarek]

I assume this is the underlying cause of bug 856315. I saw (but never filed a bug on) this same thing--I got the slow startup notification on my fast dev machine, looked at the FHR data and saw some ridiculously large startup value.

Comment 10

[(not currently active) Ted Mielczarek]

Sorry, I didn't answer your question. I don't think we want to clear out the environment, that seems likely to break things in other ways. If this specific variable causes problems we can remove it from the environment before restarting the app.

Comment 11

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

Gabriele has a patch that should fix this in bug 852250

Comment 12

[Gabriele Svelto [:gsvelto] (PTO)]

The fix for bug 852250 has just landed, Marco can you verify if it solved the problem for you?

Comment 13

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

I will verify with the next Nightly updates, though I need a reliable way to crash for a proper verification. I will try to cause an OOM.

Comment 14

[Gabriele Svelto [:gsvelto] (PTO)]

(In reply to Marco Bonardo [:mak] from comment #13)
> I will try to cause an OOM.

On FxOS we use attachment 734171 [details] to crash the browser :) You can reach it via http://bit.ly/membuster too.

Comment 15

[(not currently active) Ted Mielczarek]

http://people.mozilla.com/~tmielczarek/crashme/

(Currently doesn't work properly on OS X, but works fine on other platforms.)

Comment 16

[Marco Bonardo [:mak] (Away Apr 25 - May 5)]

So, looks like I don't need to crash.

I ran Services.startup.quit(Services.startup.eForceQuit | Services.startup.eRestart); in a previous build and confirmed MOZ_APP_RESTART was in the environment.
I did the same in todays Nightly and I don't see any MOZ_APP_RESTART in the environment, likely cause we set it to an empty value on first use.
Since the environment variable is properly removed on first use, it can't forward a broken value to child processes.

So I guess, this may be enough to resolve the bug as fixed by bug 852250.
Thanks everyone for the help.