1817498 - Deadlock from BackgroundHangThread::NotifyActivity() creating a timer while holding mGraphMutex

Status: RESOLVED FIXED

(Core :: XPCOM, defect)

Description

[Andrew McCreight [:mccr8]]

Crash report: https://crash-stats.mozilla.org/report/index/b60f23b3-169d-4588-9fd6-476530230217

Reason: EXCEPTION_BREAKPOINT

Top 10 frames of crashing thread:

0  ntdll.dll  ZwWaitForAlertByThreadId  
1  ntdll.dll  RtlAcquireSRWLockExclusive  
2  xul.dll  mozilla::OffTheBooksMutex::Lock  xpcom/threads/Mutex.h:65
2  xul.dll  mozilla::Monitor::Lock  xpcom/threads/Monitor.h:31
2  xul.dll  mozilla::detail::BaseMonitorAutoLock<mozilla::Monitor>::BaseMonitorAutoLock  xpcom/threads/Monitor.h:129
2  xul.dll  TimerThread::RemoveTimer  xpcom/threads/TimerThread.cpp:780
2  xul.dll  TimerThreadWrapper::RemoveTimer  xpcom/threads/nsTimerImpl.cpp:109
2  xul.dll  nsTimerImpl::InitCommon  xpcom/threads/nsTimerImpl.cpp:395
3  xul.dll  nsTimerImpl::InitHighResolutionWithCallback  xpcom/threads/nsTimerImpl.cpp:446
3  xul.dll  nsTimer::InitHighResolutionWithCallback  xpcom/threads/nsTimerImpl.h:201

This appears to be a reasonably common source of hangs. In the main thread, BackgroundHangThread::NotifyActivity() is holding TaskController::mGraphMutex, then it tries to create a new timer, which requires acquiring TimerThread::mMonitor. Unfortunately, over on the timer thread, it is attempting to call NS_DispatchToMainThread (frequently from FOG_RegisterContentChildShutdown()) while holding TimerThread::mMonitor, which tries to acquire mGraphMutex.

On Element, Nika said: "We should definitely not be holding mGraphMutex when in NotifyActivity".

Comment 1

[Andrew McCreight [:mccr8]]

I think this timer usage was added in bug 965392.

Comment 2

[Andrew McCreight [:mccr8]]

Nika also said: "We probably need to unlock around those like we do in a bunch of places in ExecuteNextTaskOnlyMainThreadInternal."

Comment 3

[Andrew McCreight [:mccr8]]

BHR is Nightly only.

Comment 4

[Andrew McCreight [:mccr8]]

There are around 900 hangs in the last week with BackgroundHangThread::NotifyActivity() in the proto signature, but given that there are around 800 hangs with BackgroundHangManager::CollectCPUUsage() in the proto signature, I'm guessing at most 100 of them are this. That's still a decent amount given that this is only on Nightly. (Here's an example of a BackgroundHangManager::CollectCPUUsage() hang, which I assume is due to some OS function being slow: bp-0843cd24-eff9-48f1-9985-42aef0230217)

Comment 5

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

:florian, since you are the author of the regressor, bug 965392, could you take a look?

For more information, please visit auto_nag documentation.

Comment 6

[Jens Stutte [:jstutte]]

(In reply to Andrew McCreight [:mccr8] from comment #4)

... there are around 800 hangs with BackgroundHangManager::CollectCPUUsage() in the proto signature ... (Here's an example of a BackgroundHangManager::CollectCPUUsage() hang, which I assume is due to some OS function being slow: bp-0843cd24-eff9-48f1-9985-42aef0230217)

What is interesting about those is that we end up inside ZwQuerySystemInformation which seems to be deprecated since Windows 8 but we get there through the apparently non-deprecated GetSystemTimes function. Not sure if it would be worth exploring if there are alternatives for that one, too?

Edit: Errrh, the documentation says for SYSTEM_PROCESSOR_PERFORMANCE_INFORMATION: "Use GetSystemTimes instead to retrieve this information.". So probably nothing we can do here on our side?

Comment 7

[Jan Jaeschke [:jjaschke]]

FWIW, got the same crash or something awfully similar just now on MacOS.
This occurred on a Google Docs document which did not load after Nightly update and it crashed after I closed the tab. Can't reproduce unfortunately.

Comment 8

[Andrew Overholt [:overholt]]

I think I ran into this, too (https://crash-stats.mozilla.org/report/index/cb8f5d43-c925-468a-8cc8-ad85c0230228). I had to force kill the main Firefox process because I just got the beachball cursor and couldn't interact with anything. I actually got the macOS crash reporter so I mentioned it to Haik and he suggested I note that the Apple crash report included some details about what parent's main thread was doing:

15  mozilla::IdleTaskRunner::Run() + 232 (XUL + 4033988) [0x116964dc4] 1-15
  15  mozilla::CCGCScheduler::GCRunnerFired(mozilla::TimeStamp) + 224 (XUL + 11169404) [0x117032e7c] 1-15
    15  nsJSContext::RunIncrementalGCSlice(JS::GCReason, nsJSContext::IsShrinking, js::SliceBudget&) + 196 (XUL + 12264832) [0x11713e580] 1-15
      15  GarbageCollectImpl(JS::GCReason, nsJSContext::IsShrinking, js::SliceBudget const&) + 320 (XUL + 12264368) [0x11713e3b0] 1-15
        15  js::gc::GCRuntime::collect(bool, js::SliceBudget const&, JS::GCReason) + 392 (XUL + 28942644) [0x118126134] 1-15
          15  js::gc::GCRuntime::gcCycle(bool, js::SliceBudget const&, JS::GCReason) + 1228 (XUL + 28940944) [0x118125a90] 1-15
            15  js::gc::GCRuntime::incrementalSlice(js::SliceBudget&, JS::GCReason, bool) + 500 (XUL + 28924216) [0x118121938] 1-15
              15  js::gc::GCRuntime::performSweepActions(js::SliceBudget&) + 152 (XUL + 29151408) [0x1181590b0] 1-15
                15  sweepaction::SweepActionForEach<js::gc::SweepGroupsIter, JSRuntime*>::run(js::gc::SweepAction::Args&) + 120 (XUL + 29261328) [0x118173e10] 1-15
                  15  sweepaction::SweepActionSequence::run(js::gc::SweepAction::Args&) + 76 (XUL + 29264848) [0x118174bd0] 1-15
                    15  sweepaction::SweepActionForEach<js::gc::SweepGroupZonesIter, JSRuntime*>::run(js::gc::SweepAction::Args&) + 84 (XUL + 29262656) [0x118174340] 1-15
                      15  sweepaction::SweepActionSequence::run(js::gc::SweepAction::Args&) + 76 (XUL + 29264848) [0x118174bd0] 1-15
                        15  sweepaction::SweepActionForEach<ContainerIter<mozilla::EnumSet<js::gc::AllocKind, unsigned long long> >, mozilla::EnumSet<js::gc::AllocKind, unsigned long long> >::run(js::gc::SweepAction::Args&) + 144 (XUL + 29263032) [0x1181744b8] 1-15
                          15  js::gc::GCRuntime::finalizeAllocKind(JS::GCContext*, js::SliceBudget&) + 144 (XUL + 29147436) [0x11815812c] 1-15
                            15  FinalizeArenas(JS::GCContext*, js::gc::ArenaList&, js::gc::SortedArenaList&, js::gc::AllocKind, js::SliceBudget&) + 12844 (XUL + 29125412) [0x118152b24] 1-15
                             *15  ??? (kernel.release.t8103 + 781600) [0xfffffe00083fad20] (suspended) 1-15                                                                                                                   

If the entire text of the crash report would be useful, please let me know.

Comment 9

[Florian Quèze [:florian]]

(In reply to Andrew McCreight [:mccr8] from comment #0)

This appears to be a reasonably common source of hangs. In the main thread, BackgroundHangThread::NotifyActivity() is holding TaskController::mGraphMutex, then it tries to create a new timer, which requires acquiring TimerThread::mMonitor. Unfortunately, over on the timer thread, it is attempting to call NS_DispatchToMainThread (frequently from FOG_RegisterContentChildShutdown()) while holding TimerThread::mMonitor, which tries to acquire mGraphMutex.

Given this was filed 2 days after bug 1814718 landed, and that bug introduced the use of Glean in the timer thread, could this be a regression from bug 1814718 rather than bug 965392? Maybe it's a more actionable variation of bug 1818758?

Comment 10

[Andrew McCreight [:mccr8]]

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

Given this was filed 2 days after bug 1814718 landed, and that bug introduced the use of Glean in the timer thread, could this be a regression from bug 1814718 rather than bug 965392? Maybe it's a more actionable variation of bug 1818758?

That may have caused the deadlock to happen more often (Glean was the most frequent thing on the stack in the timer thread that I saw, but not the only one), but my understanding from discussion on the XPCOM channel is that it is okay to dispatch to the main thread from the timer thread, but it is not okay to create a timer while holding the TaskController mutex.

Comment 11

[Florian Quèze [:florian]]

Attachment: Bug 1817498 - Unlock the TaskController mGraphMutex mutex before calling into BackgroundHangThread APIs, r=Bas.

Comment 12

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

The severity field is not set for this bug.
:nika, could you have a look please?

For more information, please visit auto_nag documentation.

Comment 13

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/b74f3944f8dd
Unlock the TaskController mGraphMutex mutex before calling into BackgroundHangThread APIs, r=bas.

Comment 14

[Andrew McCreight [:mccr8]]

This is Nightly only, so I'll just mark it S3. There's a fix now so the rating is largely irrelevant.

Comment 15

[Sandor Molnar[:smolnar]]

https://hg.mozilla.org/mozilla-central/rev/b74f3944f8dd

Comment 18

[Andrew McCreight [:mccr8]]

The original issue does seem to have cleared up. There are still some hangs with NotifyActivity on the crashing stack, but it is the mozilla::GetGlobalCPUStats() version noted by jstutte in comment 6. That appears to account for a third of the crashes with this hang signature on Nightly 112 with NotifyActivity on the crashing stack.