Closed Bug 1737058 Opened 3 months ago Closed 3 months ago

Shutdown profile produces invalid json files

Categories

(Core :: Gecko Profiler, defect, P2)

defect

Tracking

()

RESOLVED FIXED
95 Branch
Tracking Status
firefox95 --- fixed

People

(Reporter: julienw, Assigned: gerald)

Details

Attachments

(1 file)

STR:
I used this command line:
MOZ_PROFILER_STARTUP=1 MOZ_PROFILER_STARTUP_ENTRIES=20000000 MOZ_PROFILER_SHUTDOWN=./my-profile.json ./firefox-nightly/firefox

I waited until firefox loaded, then closed it.

Then I loaded my-profile.json into profiler.firefox.com => the file was invalid.

I had a look into the file, and indeed it was incorrect. I tried it twice: first time there were a lot of ^@ characters inserted in the middle (this may be null characters, but I'm not sure). The second time there was just bad json, eg an unfinished array, followed by another array. It looks like that the data for 2 processes ended up in the same area...

What's probably happening here is that the MOZ_PROFILER_SHUTDOWN variable is inherited into child processes, and each child process writes its own profile out to the file. All those writes to the same file from different processes then create a scrambled profile.
I think we need to unset MOZ_PROFILER_SHUTDOWN when launching child processes, or ignore it inside child processes.

Reasonable guess Markus. In my experience, the parent process was always last to write the file (after receiving child process data), so it was always "winning" the race-to-be-last and writing the full profile without clashes.

But there have been situations when the parent process gives up waiting for children, in which case it's possible that the parent writes its file, but near the same time a child finally finishes its work and also writes its profile shutdown!

In any case, yes, unsetting MOZ_PROFILER_SHUTDOWN sounds like a good idea, and easy to do, thank you!

I have other related projects in line, which should also help:

  • Bug 1528859: Make "MOZ_PROFILER_SHUTDOWN=filename-%p.json" output profiles from all processes -- I had a prototype working, I should revive it; but the hard part is stitching the profiles together!
  • Bug 1638236: Profiler should handle timeout when gathering child process profiles -- This should resolve slow-children issues, but the problem could still theoretically happen.
Assignee: nobody → gsquelart
Severity: -- → S3
Priority: -- → P2

The user shouldn't set MOZ_PROFILER_SHUTDOWN to an empty string, it wouldn't work anyway.
So now there is an extra check for that, to avoid even attempting to write a profile when there is no actual filename.

Thanks to this, the parent process can now just re-set MOZ_PROFILER_SHUTDOWN to "" in its children, so that they won't try to output their own profile into the same file. (This used to mostly work, because the parent process was the last to write its profile; but anecdotal data shows this may not alwaybe be true.)

As a bonus optimization, this means that child processes don't waste time needlessly saving their profile to disk.

Pushed by gsquelart@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/ffdf803f8f2c
Empty MOZ_PROFILER_SHUTDOWN in child processes, so they don't needlessly and dangerously write their profile to the same file - r=canaltinova
Status: NEW → RESOLVED
Closed: 3 months ago
Resolution: --- → FIXED
Target Milestone: --- → 95 Branch
You need to log in before you can comment on or make changes to this bug.