Open Bug 1960274 Opened 1 year ago Updated 1 year ago

All Parent Process threads stall during Process Immediate Launch - audio, video stuttering

Categories

(Core :: IPC, defect, P3)

Product:
Core
Component:
IPC
Version:
Firefox 137
Type:
defect

Tracking

()

Status:
ASSIGNED
Tracking Flags:
Tracking Status
firefox-esr128 --- unaffected
firefox137 --- wontfix
firefox138 --- fix-optional
firefox139 --- fix-optional

People

(Reporter: karlt, Assigned: karlt, NeedInfo)

References

(Regression)

Details

(Keywords: regression)

Attachments

(1 file, 3 external files)

Parent Process Memory usage
34.40 KB, text/plain
Details

https://share.firefox.dev/42jVktS is a profile from a long-running (2 months) Firefox 136.0b5 instance.

During the first two thirds of the Parent Process main thread Process Immediate Launch marker period starting at 20.851ms, all Parent Process threads are blocked.

These events were frequent enough to make listening to any music intolerable.

A similar launch aligns with stutters in two other profiles from the same browser process.

The Process Immediate Launch marker duration was 162ms, but profiler samples indicate that all threads were blocked for about 112ms.

Although the CONTENT_PROCESS_LAUNCH_TOTAL_MS histogram added is 166, CONTENT_PROCESS_LAUNCH_MAINTHREAD_MS is 5, which does not align with the duration for which Parent Process threads are out of action.
CONTENT_PROCESS_LAUNCH_IS_SYNC is 0.

Although the video was playing, no CPU cores were anywhere close to 100% busy.

The following is diagnosis that lead here, kind of irrelevant now that the Process Immediate Launch association is identified:

In Isolated Web Content 93/93, there is a seek from about 16.3 to 16.8s.
Stutter occurs at a time possibly matching a 81.5ms call to AudioStream::GetPositionInFramesUnlocked() on MediaDecoderStateMachine thread at 20.881s.
GetPositionInFramesUnlocked() calls usually occur approximately every 3 to 9 ms and takes less than 0.1 ms.
Each call includes a cubeb_stream_get_position() call and re-acquiring the AudioStream monitor.
The position logged with "Getting position from the Audio Sink" has advanced by 86 ms since the previous call, suggesting that the delay was not in acquiring the lock.
Shortly after there are multiple calls over 33 ms for which the logged position did not advance.
There are still over 7000 frames in the ring buffer.
AudioStream::DataCallback() calls (on the AudioIPC Client Callback thread) also pause during the delayed GetPosition() call, before two DataCallback() calls are received in quick succession.
"Output callback to be written buffer size" log messages pause in the Parent Process at the same time.
Profiler samples of all Parent Process threads also pause over this time.

Comment on attachment 9478830 [details]
Parent Process Memory usage

Heap usage of the parent process is only 6.7 GB,
though gfx is using close to 11 GB
and explicit allocations are almost 7 GB.

Attachment #9478830 - Attachment description: Explicit Allocations 7,122.59 MB (100.0%) -- explicit ├──2,057.66 MB (28.89%) ── heap-unclassified ├──2,010.11 MB (28.22%) -- window-objects │ ├────896.40 MB (12.59%) -- top(about:memory, id=80348)/active/window(about:memory) → Parent Process Memory usage

Perhaps a solution to bug 1609882 would help here.

Depends on: forkserver

Nika added the following helpful observations on #ipc:mozilla.org:

In the profiler, during a pthread_atfork a gSkipSampling function is run to suppress sampling in the pre-fork process while the fork is ongoing (https://searchfox.org/mozilla-central/rev/4d00b50c42a788c51ac4c5fe92b684569ba6c3a5/mozglue/baseprofiler/core/platform-linux-android.cpp#472-498). If the fork is taking a long time to do for some reason, we could end up not getting any profiler samples during that range because of this.

IIRC mozjemalloc locks are also held over a fork (https://searchfox.org/mozilla-central/rev/4d00b50c42a788c51ac4c5fe92b684569ba6c3a5/memory/build/mozjemalloc.cpp#6263-6322), which I imagine could easily lead to some audio jank if allocations are blocked for 100ms or so.

I do think the fork server might end up helping here, as it would mean we don't fork directly in the parent process for content processes anymore (though there are other places where we still need to such as launching child processes for extensions or external protocol handlers).

I had some difficulty capturing the fork with Linux's perf sampler, presumably because it samples at intervals on a counter that only advances with elapsed CPU time on each thread.

https://share.firefox.dev/3GkqWbH sampled some of the first 0.28 s of the forked process. I don't know why perf record -g -F 15900 -p 1887 did that, but that is useful to indicate when the parent process forked.

There is a 107ms period before the "Sandbox Forked" process is first sampled, during which no threads in the firefox-bin process are sampled.

The last sample in the parent process main thread before that is in nsAppShell's PollWrapper, which means we don't have any samples in the parent during the launch. Similarly, the first sample in the parent process main thread after "Sandbox Forked" is first sampled is in gfxPlatformGtk::GetPlatformCMSOutputProfileData(), which is similarly unhelpful.

Some parent threads resume almost immediately after "Sandbox Forked" is first sampled.

pthread_atfork() prepare handlers are called in reverse order of registration.
The gSkipSampling suppression would therefore run before most handlers.

Given that there's not much between running the prepare handlers and the fork, this seems most likely a regression from running the prepare handlers since https://hg-edge.mozilla.org/mozilla-central/rev/be4f135ac4257658b4178e9d65f55f622717799f#l4.31

If the gSkipSampling changes could be made after the other atfork changes, then we could get some profiling of what is causing the hold-up.

But, the atfork changes should not be necessary when the child will not touch any locks and just exec.

As the forkserver is single-threaded, I don't understand the problem described and addressed in bug 1917575.

Keywords: regression
Regressed by: 1917575

Set release status flags based on info from the regressing bug 1917575

:gerard-majax, since you are the author of the regressor, bug 1917575, could you take a look? Also, could you set the severity field?

For more information, please visit BugBot documentation.

status-firefox137: --- → affected
status-firefox138: --- → affected
status-firefox139: --- → affected
status-firefox-esr128: --- → unaffected
Flags: needinfo?(lissyx+mozillians)

(In reply to Karl Tomlinson (:karlt) from comment #8)

As the forkserver is single-threaded, I don't understand the problem described and addressed in bug 1917575.

malloc code needs to reset some states after the fork

Severity: -- → S4
Flags: needinfo?(lissyx+mozillians)
Priority: -- → P3

https://share.firefox.dev/3GoN8l2 is a profile from perf record -g -p 1887 -e cycles -e sched:sched_switch --switch-events --sample-cpu (Thank you mstange!). This identifies that the fork is performed on the IPC Launch thread.

Comment 6 was stracing the main thread and so the clone() syscalls there were not forks, but merely launching new threads.
Using strace -e '%process' -e 'signal=!SIGPROF' --relative-timestamps --syscall-times -p 2819 where 2819 the IPC Launch thread id, observes that the clone() takes around 125 to 138ms.

     0.000000 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=650157, si_uid=1000, si_status=0, si_utime=4 /* 0.04 s */, si_stime=30 /* 0.30 s */} ---
     0.621093 clone(child_stack=0x7fbd542bc1d0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 650300 <0.138672>
    38.121915 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=650300, si_uid=1000, si_status=0, si_utime=5 /* 0.05 s */, si_stime=27 /* 0.27 s */} ---
     0.415021 clone(child_stack=0x7fbd542bc1d0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 650376 <0.125319>
    30.533687 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=650376, si_uid=1000, si_status=0, si_utime=5 /* 0.05 s */, si_stime=25 /* 0.25 s */} ---
     0.455074 clone(child_stack=0x7fbd542bc1d0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 650455 <0.125497>
    30.445638 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=650455, si_uid=1000, si_status=0, si_utime=3 /* 0.03 s */, si_stime=28 /* 0.28 s */} ---
     0.591889 clone(child_stack=0x7fbd542bc1d0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 650539 <0.126191>
    30.439402 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=650539, si_uid=1000, si_status=0, si_utime=3 /* 0.03 s */, si_stime=26 /* 0.26 s */} ---
     0.982698 clone(child_stack=0x7fbd542bc1d0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 650621 <0.126374>
    30.536852 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=650621, si_uid=1000, si_status=0, si_utime=3 /* 0.03 s */, si_stime=29 /* 0.29 s */} ---
     0.454190 clone(child_stack=0x7fbd542bc1d0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 650710 <0.127295>
     7.992835 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=643113, si_uid=1000, si_status=0, si_utime=49 /* 0.49 s */, si_stime=37 /* 0.37 s */} ---
     0.469759 clone(child_stack=0x7fbd542bc1d0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 650816 <0.125320>

(In reply to Karl Tomlinson (:karlt) from comment #8)

Given that there's not much between running the prepare handlers and the fork, this seems most likely a regression from running the prepare handlers since https://hg-edge.mozilla.org/mozilla-central/rev/be4f135ac4257658b4178e9d65f55f622717799f#l4.31

This conclusion was based on the incorrect assumption from comment 6 that the syscall for the fork was taking little time. In fact, the fork syscall takes significant time.

jld suspected in #ipc "that fork would block all threads while it clears all the PTE write bits and flushes the TLBs".
If the kernel is blocking all threads during much of the syscall time, then the bug would exist even without running pthread_atfork() handlers, and so this would not be a regression from changes for bug 1917575.

If, however, the kernel is not blocking all threads for the majority of the system call time, then changes for bug 1917575 would likely be the cause of the thread stalls due to inability to allocate while jemalloc locks are held.

At least the Renderer thread, PulseAudio's threaded-ml thread, and the IPC I/O Parent thread are waiting for a jemalloc lock, in this profile from perf. The threaded-ml thread is doing so well after the IPC Launch thread samples in copy_page_range.

(In reply to Karl Tomlinson (:karlt) from comment #8)

But, the atfork changes should not be necessary when the child will not touch any locks and just exec.

As the forkserver is single-threaded, I don't understand the problem described and addressed in bug 1917575.

Bug 1917575 comment 14 explains this.

atfork hooks were blocking allocation on all threads in the process for the
duration of the fork, which has been observed as sometimes over 100ms on 2024
hardware.

This aligns the behavior of content process launch when the ForkServer is
disabled at run time with the behavior when the ForkServer is disabled at
build time.

Assignee: nobody → karlt
Status: NEW → ASSIGNED

This means that atfork hooks are not run except when the ForkServer process
forks.

Signals are now blocked during the fork, which will support a subsequent patch
to allow the profiler to sample other threads during the fork.

Signals are now blocked on the forking thread, so the pthread_atfork()
approach is no longer necessary.

I'm a little uneasy about this. ForkWithFlags running pthread_atfork hooks in all cases (not just the fork server) was intentional on my part; making it conditional on MOZ_ENABLE_FORKSERVER was not (bug 1925971, which I didn't know about until just now, is not what I would have done). It's true that, for a long time, it didn't support atfork and instead I tried to avoid malloc between clone and exec and mostly succeeded, but I recall at least one case where I accidentally added a heap allocation and caused an intermittent deadlock, and in general it was always a footgun.

(There are code comments about Android not supporting atfork as a reason for things; IIRC those go back to the B2G era, and while they were correct when written, I don't think they're relevant anymore — Bionic added support in Android 5 (from a quick look at the git history), and Android Firefox doesn't launch child processes directly as I understand it.)

See Also: → 1880496

Some options to reduce pthread_atfork's impact might be:

  • In single threaded apps the full pthread_atfork isn't needed, reset the locks in the new process and continue using malloc() like normal.

  • In multi-threaded apps IF you're going to call exec soon: Take only the most necessary locks before the fork, the arena locks can be eluded. Fork, reset those locks, create a new arena and make it the default arena. The new process can call malloc as normal but must not use any of the old arenas. Leaking the old arena doesn't matter because it'll all go away when you call fork().

I took some measurements with strace -e '%process' -e 'signal=!SIGPROF' --relative-timestamps --syscall-times -p 3350 and Firefox 139.0b3 of how the fork system call time changes over the lifetime of the process:

With the main process recently started and consuming only 1GB:

     0.000000 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=7863, si_uid=1000, si_status=0, si_utime=6 /* 0.06 s */, si_stime=9 /* 0.09 s */} ---
     1.266040 clone(child_stack=0x7f43321fd1c0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 8182 <0.019076>
    29.203306 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=7916, si_uid=1000, si_status=0, si_utime=6 /* 0.06 s */, si_stime=9 /* 0.09 s */} ---
     1.306764 clone(child_stack=0x7f43321fd1c0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 8287 <0.020911>
    50.390468 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=8060, si_uid=1000, si_status=0, si_utime=5 /* 0.05 s */, si_stime=7 /* 0.07 s */} ---
     2.068402 clone(child_stack=0x7f43321fd1c0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 8381 <0.022379>
    29.071354 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=8129, si_uid=1000, si_status=0, si_utime=5 /* 0.05 s */, si_stime=9 /* 0.09 s */} ---
     1.407269 clone(child_stack=0x7f43321fd1c0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 8444 <0.024785>

After one day:

    29.111449 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=95311, si_uid=1000, si_status=0, si_utime=4 /* 0.04 s */, si_stime=7 /* 0.07 s */} ---
     1.399052 clone(child_stack=0x7f43321fd1c0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 95591 <0.028019>
    52.492903 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=95395, si_uid=1000, si_status=0, si_utime=4 /* 0.04 s */, si_stime=9 /* 0.09 s */} ---
     1.168175 clone(child_stack=0x7f43321fd1c0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 95946 <0.032609>
    29.045279 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=95439, si_uid=1000, si_status=0, si_utime=7 /* 0.07 s */, si_stime=7 /* 0.07 s */} ---
     1.531896 clone(child_stack=0x7f43321fd1c0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 96023 <0.030347>

After 3 days, about:processes says 2GB:

strace: Process 3350 attached
     0.000000 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=348265, si_uid=1000, si_status=0, si_utime=10 /* 0.10 s */, si_stime=9 /* 0.09 s */} ---
     1.354459 clone(child_stack=0x7f43321fd1c0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 349004 <0.034120>
    33.097490 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=348360, si_uid=1000, si_status=0, si_utime=7 /* 0.07 s */, si_stime=9 /* 0.09 s */} ---
     1.543969 clone(child_stack=0x7f43321fd1c0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 349088 <0.034326>
    49.791180 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=348472, si_uid=1000, si_status=0, si_utime=6 /* 0.06 s */, si_stime=9 /* 0.09 s */} ---
     1.511451 clone(child_stack=0x7f43321fd1c0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 349195 <0.036495>

After 7 days:

     0.000000 clone(child_stack=0x7f43321fd1c0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 701457 <0.044371>
     7.412783 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=694343, si_uid=1000, si_status=0, si_utime=5 /* 0.05 s */, si_stime=14 /* 0.14 s */} ---
     1.574590 clone(child_stack=0x7f43321fd1c0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 701566 <0.045166>
    20.063072 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=694554, si_uid=1000, si_status=0, si_utime=7 /* 0.07 s */, si_stime=11 /* 0.11 s */} ---
     9.126205 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=694640, si_uid=1000, si_status=0, si_utime=6 /* 0.06 s */, si_stime=11 /* 0.11 s */} ---
     1.444409 clone(child_stack=0x7f43321fd1c0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 701696 <0.039854>

After 17 days:

    12.228420 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=2099520, si_uid=1000, si_status=0, si_utime=11 /* 0.11 s */, si_stime=18 /* 0.18 s */} ---
     1.141719 clone(child_stack=0x7f43321fd1c0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 2100400 <0.054214>
    29.206967 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=2100204, si_uid=1000, si_status=0, si_utime=4 /* 0.04 s */, si_stime=16 /* 0.16 s */} ---
     1.298486 clone(child_stack=0x7f43321fd1c0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 2100481 <0.053595>

After 31 days:

     0.000000 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=3774303, si_uid=1000, si_status=0, si_utime=7 /* 0.07 s */, si_stime=18 /* 0.18 s */} ---
     1.443782 clone(child_stack=0x7f43321fd1c0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 3775101 <0.074858>
    29.058909 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=3774452, si_uid=1000, si_status=0, si_utime=7 /* 0.07 s */, si_stime=25 /* 0.25 s */} ---
     1.393053 clone(child_stack=0x7f43321fd1c0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 3775186 <0.067571>
    29.107872 --- SIGCHLD {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=3774529, si_uid=1000, si_status=0, si_utime=6 /* 0.06 s */, si_stime=17 /* 0.17 s */} ---
     1.362697 clone(child_stack=0x7f43321fd1c0, flags=CLONE_NEWIPC|CLONE_NEWUSER|CLONE_NEWNET|SIGCHLD) = 3775284 <0.068696>

Jed, if we had a solution to bug 1880496 in place, would that mitigate your concerns?

Thank you for resolving bug 1609882, as that will address the frequent situations.

There are still situations where external processes are spawned, which I assume we do not have plans to handle with the forkserver.

Flags: needinfo?(jld)

Do we still need D247022 ?

Flags: needinfo?(karlt)

(In reply to :gerard-majax from comment #20)

Do we still need D247022 ?

Yes. Although the ForkServer addresses the common situations, it does not handle all situations (comment 5).

Unless there is some other change or factor you think might make D247022 unnecessary?

Flags: needinfo?(karlt)
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: