1673513 - Improve child profile gathering handling of unresponsive processes

Status: RESOLVED FIXED

(Core :: Gecko Profiler, enhancement, P2)

Description

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Spawned from bug 1673494 comment 4.

The current profile-gathering timeout is crude: 2x the parent's gathering time + 1s, reset each time we receive a child profile.

This should be improved to a more dialog-oriented scheme.

The main goal is to wait as long as needed for processes that are progressing through profile serialization, but be able to somehow detect when some process is really unresponsive and that we should stop waiting for it.

My thinking at the moment:
I'm assuming that processes can handle and respond to IPCs while they're serializing their profile -- if not, we'll need more work done to allow it, most likely bug 1601087.
The parent process would send "gather-profile" messages, and child processes should respond immediately with either the profile data, or with an update on their progress (e.g., number of bytes serialized so far).
If the child responds with a profile, all good, we're done with it.
If the child responds with an increased progress number, the parent knows it's still responsive, and can send another gather-profile message.
If the child doesn't respond in a timely manner (similar to the current timeout), or the progress number doesn't increase over that time, we can then have more confidence that the process may really be frozen, and give up at that point. It would be good to record this, for display in the front-end.

Comment 1

[Florian Quèze [:florian]]

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

The current profile-gathering timeout is crude: 2x the parent's gathering time + 1s, reset each time we receive a child profile.

This should be improved to a more dialog-oriented scheme.

An alternative approach to improve the timeouts might be to estimate the time a child process will take to send a profile based on how many buffer chunk it has (the parent has this information).

Comment 2

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

(In reply to Florian Quèze [:florian] from comment #1)

An alternative approach to improve the timeouts might be to estimate the time a child process will take to send a profile based on how many buffer chunk it has (the parent has this information).

I've just tried that, but unfortunately it's not working well:
For example, using the 5-second about::processes profiling, I could clearly see the selected child process using >10 chunks while others had not finished their first one!
But then the problem is that I cannot relate the parent's processing time (it was around 0.1s) to the buffer usage, since I don't know the exact amount of the one&only chunk it was using!
I tried adding 1 to all numbers, so the parent had 1 chunk, the selected child process had >10, and using that ratio to guess a total processing time, I only ended up with a timeout still below 2s; In the end the selected child process took more than 10s to do its work!

It was already a lot of plumbing to get all this information together. Code in Try, it outputs a lot of logging with MOZ_LOG=prof:5 if you'd like to test it yourself.

Getting the real buffer use (in bytes) in the parent would be even more intricate&ugly plumbing I'm afraid; and I still wouldn't be sure that trying to guess processing times from these buffer sizes would be reliable enough.

I'll sleep on it for now, and see if I could work on my initial solution instead...

Comment 3

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Note to self: While working on this, I should try to understand better how the profiler's whole IPC infrastructure works, especially with regards to threads -- are all the MOZ_ASSERT(NS_IsMainThread())s needed? This could help with bug 1744522.

Comment 4

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Working on it now.
This should help with a few more bugs.

Comment 5

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Attachment: Bug 1673513 - ProportionValue - r?florian

Class storing a value between 0 and 1, effectively 0% to 100%.

It will be used through a ProgressLogger object to track the progress of JSON profile generation (see following patches).

Comment 6

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Attachment: Bug 1673513 - ProgressLogger - r?florian

Class used to log the progress of long operations, and simplifying the use through nested function calls and loops.

Depends on D135477

Comment 7

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Attachment: Bug 1673513 - Use ProgressLogger in Gecko Profiler - r?florian

Add ProgressLogger parameter to most JSON-generating functions.
Each function can update the given ProgressLogger between 0% and 100%, and create sub-loggers when calling functions.

The main goal of this instrumentation is to notice when any progress is made by child processes (when the parent process is gathering profiles), so it needs to go deep enough so that it is not stuck on a progress value for "too long" -- During development, that meant progress was always happening when observed every 10ms; In later patches, the overall timeout for no-progress-made will be at least 1 second.

Depends on D135478

Comment 8

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Attachment: Bug 1673513 - Reserve the array space in advance in ProfilerParent::GatherProfiles - r?florian

A small optimization while working on nearby code, so avoid multiple allocations when we already know how much memory we really need.

Depends on D135479

Comment 9

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Attachment: Bug 1673513 - ProfilerParent::GatherProfiles() also returns the child pid - r?florian

This will be useful to tie profiles to the child process id that generated them. (At the moment, the parent waits for a number of profiles, but doesn't check where received profiles actually come from.)

Depends on D135480

Comment 10

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Attachment: Bug 1673513 - Maintain list of pending profiles, each with child pid - r?florian

Instead of just waiting for a certain number of profiles, the parent process now waits for profiles from a predetermined list of child process ids.
When receiving a profile, or when something goes wrong with a child process, the corresponding listed id can be removed, until the list is empty.
In a later patch, this list will be used to request progress updates from slow processes.

Depends on D135481

Comment 11

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Attachment: Bug 1673513 - profiler_get_profile_json(SpliceableChunkedJSONWriter&, ...) - r?florian

The main goal is to separate the profile generation (in a JSONWriter) from the final allocation needed to output the profile in one block.
This will be needed in the next patch, where the profile generation will be done in a new worker thread, but the shmem allocation must be done on the original "ProfilerChild" thread that handles IPC responses.

Depends on D135482

Comment 12

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Attachment: Bug 1673513 - Generate profile in new worker thread, and log its progress - r?florian

In order to keep the child process responsive to profile IPCs, the heavy work of generating the profile JSON is now done in a separate thread.
A ProgressLogger is used to keep track of the progress of this work, and the progress value is stored in a shared atomic ProportionValue.
When the JSON profile is ready, the final shmem allocation (used to send the profile to the parent process) is done on the original "ProfilerChild" IPC thread.

Depends on D135483

Comment 13

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Attachment: Bug 1673513 - GetGatherProfileProgress() IPC - r?florian

A new IPC function allows the parent process to request a progress update from any child process.
If a profile generation is in progress, the shared ProportionValue can be atomically read and sent back in response.

Depends on D135484

Comment 14

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Attachment: Bug 1673513 - ProfilerParent::RequestGatherProfileProgress(aChildPid) - r?florian

This helper function in ProfilerParent sends a progress request to a child process. If successfully sent, the response will resolve the returned promise.

Depends on D135485

Comment 15

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Attachment: Bug 1673513 - Factor out and improve nsProfiler::RestartGatheringTimer - r?florian

This code will be used again in the following patch.

Depends on D135486

Comment 16

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Attachment: Bug 1673513 - Use ProfilerParent::RequestGatherProfileProgress to wait for slow but responsive processes - r?florian

Instead of waiting a set time guessed from how long the parent process took to do its work, after a short time the parent process requests progress updates from all still-pending child processes, and restarts the timer if any progress was made.
If processes become unresponsive, they will be the last ones pending, and after one timer cycle without any progress anywhere, the parent process won't wait for children anymore, and will output all profiles successfully gathered so far.

Added MOZ_LOG=prof logging in nsProfiler.cpp, to monitor profile-gathering. (And removed a spurious 'd' character in the LOG macro.)

Depends on D135487

Comment 17

[Gerald Squelart (he/him) (not at Mozilla since 2022-09-15)]

Attachment: Bug 1673513 - Add tests for slow and too-slow child processes - r?florian

Depends on D135488

Comment 18

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/856f1a5fdba9
ProportionValue - r=florian
https://hg.mozilla.org/integration/autoland/rev/cad5aa6c0a01
ProgressLogger - r=florian
https://hg.mozilla.org/integration/autoland/rev/d452b703317f
Use ProgressLogger in Gecko Profiler - r=florian
https://hg.mozilla.org/integration/autoland/rev/e563d4636a46
Reserve the array space in advance in ProfilerParent::GatherProfiles - r=florian
https://hg.mozilla.org/integration/autoland/rev/d1e967e46f68
ProfilerParent::GatherProfiles() also returns the child pid - r=florian
https://hg.mozilla.org/integration/autoland/rev/92c79596b66a
Maintain list of pending profiles, each with child pid - r=florian
https://hg.mozilla.org/integration/autoland/rev/34dd3a624e0c
profiler_get_profile_json(SpliceableChunkedJSONWriter&, ...) - r=florian
https://hg.mozilla.org/integration/autoland/rev/8ebc963fd9e6
Generate profile in new worker thread, and log its progress - r=florian,KrisWright
https://hg.mozilla.org/integration/autoland/rev/a21293c3c5f6
GetGatherProfileProgress() IPC - r=florian
https://hg.mozilla.org/integration/autoland/rev/2952a4cd93c9
ProfilerParent::RequestGatherProfileProgress(aChildPid) - r=florian
https://hg.mozilla.org/integration/autoland/rev/473c600f2802
Factor out and improve nsProfiler::RestartGatheringTimer - r=florian
https://hg.mozilla.org/integration/autoland/rev/899b26a6d3b9
Use ProfilerParent::RequestGatherProfileProgress to wait for slow but responsive processes - r=florian
https://hg.mozilla.org/integration/autoland/rev/01e8e7b4512f
Add tests for slow and too-slow child processes - r=florian

Comment 19

[Cristian Tuns]

https://hg.mozilla.org/mozilla-central/rev/856f1a5fdba9
https://hg.mozilla.org/mozilla-central/rev/cad5aa6c0a01
https://hg.mozilla.org/mozilla-central/rev/d452b703317f
https://hg.mozilla.org/mozilla-central/rev/e563d4636a46
https://hg.mozilla.org/mozilla-central/rev/d1e967e46f68
https://hg.mozilla.org/mozilla-central/rev/92c79596b66a
https://hg.mozilla.org/mozilla-central/rev/34dd3a624e0c
https://hg.mozilla.org/mozilla-central/rev/8ebc963fd9e6
https://hg.mozilla.org/mozilla-central/rev/a21293c3c5f6
https://hg.mozilla.org/mozilla-central/rev/2952a4cd93c9
https://hg.mozilla.org/mozilla-central/rev/473c600f2802
https://hg.mozilla.org/mozilla-central/rev/899b26a6d3b9
https://hg.mozilla.org/mozilla-central/rev/01e8e7b4512f