Make "MOZ_PROFILER_SHUTDOWN=filename-%p.json" output profiles from all processes
Categories
(Core :: Gecko Profiler, enhancement, P3)
Tracking
()
People
(Reporter: mozbugz, Assigned: florian)
References
Details
Attachments
(1 file, 1 obsolete file)
Currently MOZ_PROFILER_SHUTDOWN only ends up producing the profile for the main thread.
(In fact, it's producing all of them, but they use the same name, and the main thread goes last and overwrites previous sub-process files!)
I'm proposing to change the meaning of the MOZ_PROFILER_SHUTDOWN arguments, from a full filename to a prefix name, so that each process may output its own profile in a separate file.
E.g., MOZ_PROFILER_SHUTDOWN="prof-" will generate "prof-123.json", "prof-127.json", where the numbers are process IDs.
It's not ideal, but I think it would be a good & easy first step until we can implement a better (more complicated) solution.
Maybe a small external utility could be created to stitch multiple profiles together, if deemed useful?
I've got a WIP patch working, I'll submit it for review soon, but please give feedback/criticism if you think of anything.
|
||
Comment 1•6 years ago
|
||
Alternative suggestion: Ignore MOZ_PROFILER_SHUTDOWN in content processes (or forcefully unset that variable when launching subprocesses in GetProfilerEnvVarsForChildProcess), and make the profile from the parent process include all the subprocess profiles. The subprocesses should already be sending their "exit profile" to the parent process, those exit profiles just need to be included.
|
|
||
Comment 2•6 years ago
|
||
Oh, now I see bug 1509533 again which wants to implement the proper fix. I don't think the proper fix is hard to do.
|
Reporter | |
Comment 3•6 years ago
|
||
Thank you for the hint, I thought bug 1509533 would be more difficult (dealing with sending profiles across processes), I'll give it a try...
|
|
Reporter | |
Comment 4•6 years ago
|
||
Will resolve bug 1509533 instead.
|
|
Reporter | |
Comment 5•6 years ago
|
||
Reviving this bug, as it may still be needed to capture child processes (other than web content processes, which are captured thanks to bug 1509533).
Unless follow-up bug 1529131 can be fixed soon enough.
|
|
Reporter | |
Comment 6•5 years ago
|
||
I've got a WIP with an imperfect* but working MOZ_PROFILER_SHUTDOWN=filename-%p.json, which will produce one file per process, then running Firefox again with MOZ_PROFILER_SHUTDOWN_COMBINE=filename-%p.json (notice "_COMBINE") will stitch the files together, and the resulting filename-C.json can be fed to profiler.firefox.com.
It's not perfect: It relies on the textual formatting produced by JSONWriter, and some processes get duplicated (but thankfully the frontend only displays the later and better ones), albeit with strange numbering (I'll open an issue for the frontend to fix that, if time permits).
I'm still putting it up for review and landing, because MOZ_PROFILER_SHUTDOWN without "%p" will work exactly like before, and I would guess few people will use it, so we don't need something super robust and sparkling clean, but at least it's there for the few people who may have a good need for it.
Example:
Parent process only, as the plain MOZ_PROFILER_SHUTDOWN would have produced: https://share.firefox.dev/30mApqg
Combined profile: https://share.firefox.dev/2WwocOH
Notice the added GPU Process, and the other sub-processes show a bit more data at their ends.
|
Assignee | |
Comment 7•5 years ago
|
||
(In reply to Gerald Squelart [:gerald] (he/him) from comment #6)
Combined profile: https://share.firefox.dev/2WwocOH
Notice the added GPU Process, and the other sub-processes show a bit more data at their ends.
It's strange that the GPU Process starts during shutdown. I wonder what causes this process to start, and if it's something that happens frequently.
|
|
Reporter | |
Comment 8•5 years ago
|
||
(In reply to Florian Quèze [:florian] (PTO until July 20th) from comment #7)
It's strange that the GPU Process starts during shutdown. I wonder what causes this process to start, and if it's something that happens frequently.
Oh, that was a full startup-to-shutdown profile! (Start Firefox, open wikipedia and click a couple of links, quit.)
But yes, it seems to start late, so maybe it did crash during profiling -- I remember a flash and some graphicky assertions, that must have been it. So we're only seeing the last respawned GPU process.
Running it again now, I see those flashes, with a !TimeStamp::IsNull() in ImageComposite::SetImages, I think it's in the profiler marker code that computes time jitter. That's why it doesn't happen in non-profiled code. I'll file a bug...
|
|
Reporter | |
Comment 9•5 years ago
|
||
Upcoming GPU process fix in bug 1654106.
New profiles after fix:
- Parent only: https://share.firefox.dev/39ceDcQ
- Combined: https://share.firefox.dev/2CU6k9g
But landing the _COMBINE patch is delayed, I was using <filesystem> APIs that are only available on Windows. 😭
|
|
Assignee | |
Comment 10•5 years ago
|
||
(In reply to Gerald Squelart [:gerald] (he/him) from comment #9)
Upcoming GPU process fix in bug 1654106.
New profiles after fix:
- Parent only: https://share.firefox.dev/39ceDcQ
- Combined: https://share.firefox.dev/2CU6k9g
In this profile we spend a lot of time GC'ing after the last IPC, I don't think that's very useful (it takes 200 to 400ms per child process to cleanup after the last IPC), but this profile is from a debug build, so the behavior may be very different from what we would normally see.
|
|
||
Comment 11•5 years ago
|
||
These profiles are a demonstration of the fact that we can obtain the profiles and merge them, their content isn't all that relevant, there's not much need to analyze them (other than checking that the relevant processes are present).
|
|
Reporter | |
Comment 12•2 years ago
|
||
If the filename given to MOZ_PROFILER_SHUTDOWN contains "%p", all processes will write their own profile, and change "%p" in the filename to 'P'/'S' (Parent/Subprocess) and their process id.
|
|
Reporter | |
Comment 13•2 years ago
|
||
The filename given to MOZ_PROFILER_SHUTDOWN_COMBINE should be the exact same one as given to MOZ_PROFILER_SHUTDOWN (including "%p").
All files will be stitched together into one output file, the filename is the same as the others but with "%p" replaced with "C".
Note that the implementation is minimal and inflexible, it relies on the textual format output by MOZ_PROFILER_SHUTDOWN.
Also, some sub-process may actually be present multiple times (because they were both sent through IPCs and then saved to a shutdown file), but the frontend helpfully only keeps that later one, which is from the shutdown file and actually contains a bit more data (from after the IPC output) -- though these duplicated processes will manifest in strange numberings, e.g., "Content Process (2/2)" but no "Content Process (1/2)".
Depends on D157193
|
|
Reporter | |
Comment 14•2 years ago
|
||
Sadly I won't have time to finish this.
The first patch should work fine, and doesn't affect the normal use of MOZ_PROFILER_SHUTDOWN without "%p".
However I don't think it's really useful without the second patch that stitches the separate files together, but that patch is not ready to ship:
- It uses
<filesystem>, which I think is not available on all our platforms. - It relied on the old JSON generation with lots of spaces and lines! So it would probably have to be redone, maybe by using a real JSON parser to read the files, stitch them as JSON objects, and save the result. Maybe it would be better as a separate python or js program?
|
||
Updated•2 years ago
|
|
||
Updated•2 years ago
|
|
|
||
Updated•2 years ago
|
|
|
||
Updated•2 years ago
|
|
||
Comment 15•2 years ago
|
||
|
||
Comment 16•2 years ago
|
||
| bugherder | ||
|
||
Updated•2 years ago
|
Description
•