1613798 - Crash in [@ IPCError-browser | ShutDownKill | nsThread::Shutdown | mozilla::ChildProfilerController::ShutdownAndMaybeGrabShutdownProfileFirst]

Status: RESOLVED FIXED

(Core :: Gecko Profiler, defect, P1)

Description

[Andrew McCreight [:mccr8]]

This bug is for crash report bp-d9367f2d-b3b3-4990-bdab-1db030200206.

Top 10 frames of crashing thread:

0 ntdll.dll KiFastSystemCallRet 
1 ntdll.dll NtWaitForKeyedEvent 
2 ntdll.dll RtlSleepConditionVariableSRW 
3 kernel32.dll SleepConditionVariableSRW 
4 mozglue.dll mozilla::detail::ConditionVariableImpl::wait mozglue/misc/ConditionVariable_windows.cpp:50
5 xul.dll mozilla::ThreadEventQueue<mozilla::PrioritizedEventQueue>::GetEvent xpcom/threads/ThreadEventQueue.cpp:208
6 xul.dll nsThread::ProcessNextEvent xpcom/threads/nsThread.cpp:1140
7 xul.dll NS_ProcessNextEvent xpcom/threads/nsThreadUtils.cpp:486
8 xul.dll nsThread::Shutdown xpcom/threads/nsThread.cpp:909
9 xul.dll mozilla::ChildProfilerController::ShutdownAndMaybeGrabShutdownProfileFirst tools/profiler/gecko/ChildProfilerController.cpp:62

This is a pretty common shutdown hang on the Nightly I looked at. It looks like the profiler is trying to grab a profile during shutdown, but it takes too long and then we hang.

Comment 1

[Gabriele Svelto [:gsvelto]]

This is happening on Windows 10 too.

Comment 3

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

I'll need to have a deeper look, but some initial thoughts:
The main operation that could take a long time is ChildProfilerController::ShutdownProfilerChild, and especially profiler_get_profile under it, which would run in another thread (and the main thread waits for that thread to empty its queue and shutdown)... But these functions is not visible in these reports!?

Comment 4

[Gabriele Svelto [:gsvelto]]

None of the other threads is doing any profiler-related work but your comment gave me an idea of why this might be happening. While triaging these crashes I stumbled upon more than one crash when the main thread was waiting on an event-queue - potentially after posting a runnable - but no other thread was doing any work. My gut feeling is that during the shutdown procedure we're killing the runnables in the event queues (or just stopping them) so the main thread will be waiting on something that never happens.

Comment 5

[Nathan Froyd [:froydnj]]

Do we really need to synchronously shutdown the thread there? Is there any reason that we couldn't use AsyncShutdown()?

Comment 6

[Ryan VanderMeulen [:RyanVM]]

This is one of the top overall Nightly crashes. It would be nice if we could do something to mitigate it.

Comment 7

[Gabriele Svelto [:gsvelto]]

This is not a real crash, it's just us being forced to kill a content process that's not shutting down within 5 seconds. It's not directly visible by users but it warns us that there's something slow (or stuck) in the content process shutdown procedure.

Comment 8

[Markus Stange [:mstange]]

It should also only occur while the profiler is running, unless there's a bug. The profiler isn't used by a significant share of our users, so I'm surprised this crash shows up that highly.

Comment 10

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

Another signature for the same crash.

Comment 12

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

Coming back here because of bug 1638753, which sounded the alarm (again).

(In reply to Gabriele Svelto [:gsvelto] from comment #7)

This is not a real crash, it's just us being forced to kill a content process that's not shutting down within 5 seconds. It's not directly visible by users but it warns us that there's something slow (or stuck) in the content process shutdown procedure.

Thank you for this information!

Looking at a couple of reports, they do have the ProfilerChild thread doing a ChildProfilerController::ShutdownProfilerChild() (which is the last task sent to the ProfilerChild thread, and now the main thread is waiting for that ProfilerChild thread to shutdown).
And that task on the ProfilerChild thread seems to be waiting for a MessageChannel::SynchronouslyClose().
Could there be a deadlock between that channel sync-close and the main thread's ContentChild currently processing a message and waiting for the ProfilerChild thread to shutdown?

I'll investigate further... But other ideas are always welcome!

Comment 13

[BugBot [:suhaib / :marco/ :calixte]]

Since the status are different for nightly and release, what's the status for beta?
For more information, please visit auto_nag documentation.

Comment 14

[Gabriele Svelto [:gsvelto]]

After bug 1637048 the volume here dropped almost to zero, confirming that this was a case of content processes being slow to shut down in this particular phase. Given the above I'd say we can lower the priority of this bug but it would still be nice to speed up that particular shutdown phase if possible.

Comment 15

[alex_mayorga]

¡Hola y'all!

Crashed like https://crash-stats.mozilla.org/report/index/989c18c4-df56-40d3-a16e-eba260201016#tab-details today.

Updating flags per https://crash-stats.mozilla.org/signature/?product=Firefox&signature=IPCError-browser%20%7C%20ShutDownKill%20%7C%20mozilla%3A%3ATaskController%3A%3AGetRunnableForMTTask%20%7C%20nsThread%3A%3AShutdown%20%7C%20mozilla%3A%3AChildProfilerController%3A%3AGrabShutdownProfileAndShutdown&date=%3E%3D2020-09-16T22%3A40%3A00.000Z&date=%3C2020-10-16T22%3A40%3A00.000Z

¡Gracias!
Alex

Comment 16

[alex_mayorga]

¡Hola y'all!

Crashed like https://crash-stats.mozilla.org/report/index/bdf2ab51-4592-4c10-a2c9-cedca0210204 today.

Version 87.0a1
Build ID 20210202214809 (2021-02-02)

Updating flags per https://crash-stats.mozilla.org/signature/?product=Firefox&signature=IPCError-browser%20%7C%20ShutDownKill%20%7C%20js%3A%3ANativeObject%3A%3AaddEnumerableDataProperty&date=%3E%3D2021-01-04T03%3A29%3A00.000Z&date=%3C2021-02-04T03%3A29%3A00.000Z

¡Gracias!
Alex

Comment 17

[alex_mayorga]

¡Hola y'all!

Product Firefox
Release Channel nightly
Version 88.0a1
Build ID 20210310093927 (2021-03-10)
crashed like https://crash-stats.mozilla.org/report/index/fa4d7b66-1f77-49c2-95ed-84b720210311

Updating flags per https://crash-stats.mozilla.org/signature/?product=Firefox&signature=IPCError-browser%20%7C%20ShutDownKill%20%7C%20nsThread%3A%3AShutdown%20%7C%20mozilla%3A%3AChildProfilerController%3A%3AGrabShutdownProfileAndShutdown

Seems to be an uptick on 88.0a1 this week.

¡Gracias!
Alex

Comment 18

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

I need to look into this.

Comment 20

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

The candidate fix in bug 1707537 landed in 90.0a1 20210427095509, but I still see crash reports after that, so the hunt continues...

Comment 21

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

More signatures.
And a few reports on Mac (those with __psynch_cvwait) so it's not only Windows.

Comment 22

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

Too many signatures added in comment 21, which hid the graph.
I've restricted the list to those that were known previously, plus the missing ones that had at least 2 reports in the last month.

To see everything, do a search for "ChildProfilerController".

Comment 23

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

With bug 1710607 landed in build 20210512174859, it already looks good with zero crashes since then. I'll monitor for a few more days before declaring victory...

Comment 24

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

Zero crash reports since build 20210512174859, I'm declaring it:
Fixed by bug 1710607.

No need to uplift, this only happens on Nightly. (So technically speaking, previous versions that graduated to beta or release are no longer affected anyway, but there's no tracking flag that captures this subtlety.)