Open Bug 1528859 Opened 4 years ago Updated 2 years ago

Make "MOZ_PROFILER_SHUTDOWN=filename-%p.json" output profiles from all processes

Categories

(Core :: Gecko Profiler, enhancement, P3)

enhancement

Tracking

()

REOPENED
Tracking Status
firefox67 --- affected

People

(Reporter: gerald, Assigned: gerald)

References

Details

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.

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.

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.

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

Will resolve bug 1509533 instead.

Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → WONTFIX

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.

Status: RESOLVED → REOPENED
Depends on: 1509533
Resolution: WONTFIX → ---
See Also: 15095331529131

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.

Summary: Make "MOZ_PROFILER_SHUTDOWN" output profiles from all processes → Make "MOZ_PROFILER_SHUTDOWN=filename-%p.json" output profiles from all processes

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

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

Upcoming GPU process fix in bug 1654106.

New profiles after fix:

But landing the _COMBINE patch is delayed, I was using <filesystem> APIs that are only available on Windows. 😭

(In reply to Gerald Squelart [:gerald] (he/him) from comment #9)

Upcoming GPU process fix in bug 1654106.

New profiles after fix:

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.

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

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