1929941 - Profiler hang in profiler_capture_backtrace_into when capture stack from AddTask

Status: NEW

(Core :: Gecko Profiler, defect, P2)

Description

[Jeff Muizelaar [:jrmuizel]]

I added a marker to TaskController::AddTask which captures the stack and that causes a deadlock during profiler_start.

We're deadlocking on the thread registration mutex.

  * frame #0: 0x000000019817ca9c libsystem_kernel.dylib`__psynch_mutexwait + 8
    frame #1: 0x00000001981b83f8 libsystem_pthread.dylib`_pthread_mutex_firstfit_lock_wait + 84
    frame #2: 0x00000001981b5dbc libsystem_pthread.dylib`_pthread_mutex_firstfit_lock_slow + 220
    frame #3: 0x00000001046e1934 libmozglue.dylib`mozilla::detail::MutexImpl::lock() at Mutex_posix.cpp:94:3 [opt]
    frame #4: 0x00000001046e1930 libmozglue.dylib`mozilla::detail::MutexImpl::lock(this=<unavailable>) at Mutex_posix.cpp:116:43 [opt]
    frame #5: 0x000000012b3e3bb0 XUL`profiler_capture_backtrace_into(mozilla::ProfileChunkedBuffer&, mozilla::StackCaptureOptions) [inlined] mozilla::baseprofiler::detail::BaseProfilerMutex::Lock(this=<unavailable>) at BaseProfilerDetail.h:57:35 [opt]
    frame #6: 0x000000012b3e3bac XUL`profiler_capture_backtrace_into(mozilla::ProfileChunkedBuffer&, mozilla::StackCaptureOptions) [inlined] mozilla::baseprofiler::detail::BaseProfilerAutoLock::BaseProfilerAutoLock(this=<unavailable>, aMutex=<unavailable>) at BaseProfilerDetail.h:104:12 [opt]
    frame #7: 0x000000012b3e3bac XUL`profiler_capture_backtrace_into(mozilla::ProfileChunkedBuffer&, mozilla::StackCaptureOptions) [inlined] mozilla::baseprofiler::detail::BaseProfilerAutoLock::BaseProfilerAutoLock(this=<unavailable>, aMutex=<unavailable>) at BaseProfilerDetail.h:103:77 [opt]
    frame #8: 0x000000012b3e3bac XUL`profiler_capture_backtrace_into(mozilla::ProfileChunkedBuffer&, mozilla::StackCaptureOptions) [inlined] mozilla::profiler::ThreadRegistration::OnThreadRef::ConstRWOnThreadWithLock::ConstRWOnThreadWithLock(this=<unavailable>, aLockedRWOnThread=0x0000000106bf9da0, aDataMutex=<unavailable>) at ProfilerThreadRegistration.h:174:51 [opt]
    frame #9: 0x000000012b3e3bac XUL`profiler_capture_backtrace_into(mozilla::ProfileChunkedBuffer&, mozilla::StackCaptureOptions) [inlined] mozilla::profiler::ThreadRegistration::OnThreadRef::ConstRWOnThreadWithLock::ConstRWOnThreadWithLock(this=<unavailable>, aLockedRWOnThread=0x0000000106bf9da0, aDataMutex=<unavailable>) at ProfilerThreadRegistration.h:174:73 [opt]
    frame #10: 0x000000012b3e3bac XUL`profiler_capture_backtrace_into(mozilla::ProfileChunkedBuffer&, mozilla::StackCaptureOptions) [inlined] mozilla::profiler::ThreadRegistration::OnThreadRef::ConstLockedRWOnThread(this=<unavailable>) const at ProfilerThreadRegistration.h:181:14 [opt]
    frame #11: 0x000000012b3e3ba0 XUL`profiler_capture_backtrace_into(mozilla::ProfileChunkedBuffer&, mozilla::StackCaptureOptions) [inlined] auto mozilla::profiler::ThreadRegistration::OnThreadRef::WithConstLockedRWOnThread<DoSyncSample(unsigned int, mozilla::profiler::ThreadRegistrationUnlockedReaderAndAtomicRWOnThread const&, mozilla::TimeStamp const&, Registers const&, ProfileBuffer&, mozilla::StackCaptureOptions)::$_0::operator()(mozilla::profiler::ThreadRegistration::OnThreadRef) const::'lambda'(mozilla::profiler::ThreadRegistrationLockedRWOnThread const&)>(this=<unavailable>, aF=<unavailable>) const at ProfilerThreadRegistration.h:187:44 [opt]
    frame #12: 0x000000012b3e3ba0 XUL`profiler_capture_backtrace_into(mozilla::ProfileChunkedBuffer&, mozilla::StackCaptureOptions) [inlined] DoSyncSample(unsigned int, mozilla::profiler::ThreadRegistrationUnlockedReaderAndAtomicRWOnThread const&, mozilla::TimeStamp const&, Registers const&, ProfileBuffer&, mozilla::StackCaptureOptions)::$_0::operator()(this=<unavailable>, aOnThreadRef=OnThreadRef @ x23) const at platform.cpp:3012:20 [opt]
    frame #13: 0x000000012b3e3ba0 XUL`profiler_capture_backtrace_into(mozilla::ProfileChunkedBuffer&, mozilla::StackCaptureOptions) at ProfilerThreadRegistration.h:285:9 [opt]
    frame #14: 0x000000012b3e3b98 XUL`profiler_capture_backtrace_into(mozilla::ProfileChunkedBuffer&, mozilla::StackCaptureOptions) [inlined] DoSyncSample(aFeatures=<unavailable>, aThreadData=0x0000000106bf9da0, aNow=<unavailable>, aRegs=0x000000016b842510, aBuffer=0x000000016b842558, aCaptureOptions=Full) at platform.cpp:3010:5 [opt]
    frame #15: 0x000000012b3e3b40 XUL`profiler_capture_backtrace_into(mozilla::ProfileChunkedBuffer&, mozilla::StackCaptureOptions) [inlined] profiler_capture_backtrace_into(mozilla::ProfileChunkedBuffer&, mozilla::StackCaptureOptions)::$_0::operator()(this=<unavailable>, aOnThreadRef=OnThreadRef @ x19) const at platform.cpp:7698:9 [opt]
    frame #16: 0x000000012b3e3b40 XUL`profiler_capture_backtrace_into(mozilla::ProfileChunkedBuffer&, mozilla::StackCaptureOptions) at ProfilerThreadRegistration.h:299:16 [opt]
    frame #17: 0x000000012b3e3b40 XUL`profiler_capture_backtrace_into(aChunkedBuffer=<unavailable>, aCaptureOptions=<unavailable>) at platform.cpp:7681:10 [opt]
    frame #18: 0x00000001274aadbc XUL`mozilla::ProfileBufferBlockIndex mozilla::base_profiler_markers_detail::AddMarkerToBuffer<mozilla::FlowMarker, Flow>(this=0x000000016b846760, aChunkedBuffer=0x00000003016cf100)(mozilla::ProfileChunkedBuffer&, mozilla::StackCaptureOptions), Flow const&)::'lambda'(mozilla::ProfileChunkedBuffer&)::operator()(mozilla::ProfileChunkedBuffer&) const at BaseProfilerMarkersDetail.h:303:11 [opt]
    frame #19: 0x00000001274aabdc XUL`mozilla::ProfileBufferBlockIndex mozilla::base_profiler_markers_detail::AddMarkerToBuffer<mozilla::FlowMarker, Flow>(aBuffer=0x0000000104712340, aName=0x000000016b846a50, aCategory=0x000000012d9d8dd0, aOptions=0x000000016b846a10, aOptionalBacktraceCaptureFunction=<unavailable>, aTs=0x000000016b8469f8) at BaseProfilerMarkersDetail.h:317:14 [opt]
    frame #20: 0x00000001274aaa4c XUL`mozilla::ProfileBufferBlockIndex AddMarkerToBuffer<mozilla::FlowMarker, Flow>(aBuffer=0x0000000104712340, aName=0x000000016b846a50, aCategory=0x000000012d9d8dd0, aOptions=0x000000016b846a10, aMarkerType=<unavailable>, aPayloadArguments=0x000000016b8469f8) at ProfilerMarkers.h:109:10 [opt]
    frame #21: 0x000000012749eba0 XUL`mozilla::ProfileBufferBlockIndex profiler_add_marker_impl<mozilla::FlowMarker, Flow>(aName=0x000000016b846a50, aCategory=0x000000012d9d8dd0, aOptions=0x000000016b846a10, aMarkerType=<unavailable>, aPayloadArguments=0x000000016b8469f8) at ProfilerMarkers.h:184:10 [opt]
    frame #22: 0x000000012749e898 XUL`mozilla::TaskController::AddTask(this=0x0000000106be1f20, aTask=<unavailable>) at TaskController.cpp:445:7 [opt]
    frame #23: 0x0000000127cc9410 XUL`DispatchOffThreadTask(aTask=0x000000013df4f0a0) at XPCJSContext.cpp:1146:26 [opt]
    frame #24: 0x000000012b90eb44 XUL`js::jit::JitRuntime::maybeStartIonFreeTask(bool) at HelperThreads.cpp:677:5 [opt]
    frame #25: 0x000000012b90eb24 XUL`js::jit::JitRuntime::maybeStartIonFreeTask(bool) [inlined] js::AutoHelperTaskQueue::~AutoHelperTaskQueue(this=0x000000016b846ae0) at HelperThreads.h:77:28 [opt]
    frame #26: 0x000000012b90eb24 XUL`js::jit::JitRuntime::maybeStartIonFreeTask(bool) [inlined] js::AutoLockHelperThreadState::~AutoLockHelperThreadState(this=0x000000016b846ae0) at HelperThreads.h:91:16 [opt]
    frame #27: 0x000000012b90eb1c XUL`js::jit::JitRuntime::maybeStartIonFreeTask(bool) [inlined] js::AutoLockHelperThreadState::~AutoLockHelperThreadState(this=0x000000016b846ae0) at HelperThreads.h:91:16 [opt]
    frame #28: 0x000000012b90eb1c XUL`js::jit::JitRuntime::maybeStartIonFreeTask(this=<unavailable>, force=<unavailable>) at HelperThreads.cpp:1045:1 [opt]
    frame #29: 0x000000012b90e664 XUL`js::GlobalHelperThreadState::cancelOffThreadIonCompile(mozilla::Variant<JSScript*, JS::Zone*, js::ZonesInState, JSRuntime*> const&) [inlined] js::AutoStartIonFreeTask::~AutoStartIonFreeTask(this=0x000000016b846b60) at HelperThreads.cpp:1066:16 [opt]
    frame #30: 0x000000012b90e658 XUL`js::GlobalHelperThreadState::cancelOffThreadIonCompile(mozilla::Variant<JSScript*, JS::Zone*, js::ZonesInState, JSRuntime*> const&) [inlined] js::AutoStartIonFreeTask::~AutoStartIonFreeTask(this=0x000000016b846b60) at HelperThreads.cpp:1065:51 [opt]
    frame #31: 0x000000012b90e658 XUL`js::GlobalHelperThreadState::cancelOffThreadIonCompile(this=<unavailable>, selector=<unavailable>) at HelperThreads.cpp:916:1 [opt]
    frame #32: 0x000000012b90e8e8 XUL`js::CancelOffThreadIonCompile(selector=<unavailable>) at HelperThreads.cpp:938:23 [opt] [artificial]
    frame #33: 0x000000012bc88928 XUL`js::ReleaseAllJITCode(JS::GCContext*) [inlined] js::CancelOffThreadIonCompile(runtime=<unavailable>) at HelperThreads.h:229:3 [opt]
    frame #34: 0x000000012bc88918 XUL`js::ReleaseAllJITCode(gcx=0x0000000114b48570) at GCAPI.cpp:97:3 [opt]
    frame #35: 0x000000012b906814 XUL`js::GeckoProfilerRuntime::enable(this=0x0000000114b48238, enabled=true) at GeckoProfiler.cpp:85:3 [opt]
    frame #36: 0x000000012b90768c XUL`js::EnableContextProfilingStack(cx=<unavailable>, enabled=<unavailable>) at GeckoProfiler.cpp:484:34 [opt] [artificial]
    frame #37: 0x000000012b3e5c68 XUL`mozilla::profiler::ThreadRegistrationLockedRWOnThread::PollJSSampling(this=0x0000000106bf9da0) at ProfilerThreadRegistrationData.cpp:239:7 [opt]
    frame #38: 0x000000012b3f0888 XUL`profiler_start(mozilla::PowerOfTwo<unsigned int>, double, unsigned int, char const**, unsigned int, unsigned long long, mozilla::Maybe<double> const&) [inlined] PollJSSamplingForCurrentThread(this=<unavailable>, aThreadData=0x0000000106bf9da0)::$_0::operator()(mozilla::profiler::ThreadRegistration::OnThreadRef) const::'lambda'(mozilla::profiler::ThreadRegistrationLockedRWOnThread&)::operator()(mozilla::profiler::ThreadRegistrationLockedRWOnThread&) const at platform.cpp:5870:27 [opt]
    frame #39: 0x000000012b3f0880 XUL`profiler_start(mozilla::PowerOfTwo<unsigned int>, double, unsigned int, char const**, unsigned int, unsigned long long, mozilla::Maybe<double> const&) [inlined] auto mozilla::profiler::ThreadRegistration::OnThreadRef::WithLockedRWOnThread<PollJSSamplingForCurrentThread()::$_0::operator()(mozilla::profiler::ThreadRegistration::OnThreadRef) const::'lambda'(mozilla::profiler::ThreadRegistrationLockedRWOnThread&)>(this=<unavailable>, aF=<unavailable>) at ProfilerThreadRegistration.h:225:14 [opt]
    frame #40: 0x000000012b3f086c XUL`profiler_start(mozilla::PowerOfTwo<unsigned int>, double, unsigned int, char const**, unsigned int, unsigned long long, mozilla::Maybe<double> const&) [inlined] PollJSSamplingForCurrentThread()::$_0::operator()(this=<unavailable>, aOnThreadRef=OnThreadRef @ x26) const at platform.cpp:5868:22 [opt]
    frame #41: 0x000000012b3f086c XUL`profiler_start(mozilla::PowerOfTwo<unsigned int>, double, unsigned int, char const**, unsigned int, unsigned long long, mozilla::Maybe<double> const&) at ProfilerThreadRegistration.h:285:9 [opt]
    frame #42: 0x000000012b3f0854 XUL`profiler_start(mozilla::PowerOfTwo<unsigned int>, double, unsigned int, char const**, unsigned int, unsigned long long, mozilla::Maybe<double> const&) [inlined] PollJSSamplingForCurrentThread() at platform.cpp:5866:3 [opt]
    frame #43: 0x000000012b3f0854 XUL`profiler_start(aCapacity=(mValue = 134217728), aInterval=1, aFeatures=17842434, aFilters=0x000000030baecc40, aFilterCount=6, aActiveTabID=3, aDuration=0x000000016b846e18) at platform.cpp:6734:3 [opt]

We seem to deadlocking on the Thread Registration mDataMutex. I verified that the main thread is the thread owns the lock when we try to relock it.

Comment 1

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

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

For more information, please visit BugBot documentation.

Comment 2

[Jeff Muizelaar [:jrmuizel]]

I have a work around for this locally

Comment 3

[Nazım Can Altınova [:canova][:canaltinova on phabricator]]

Jeff, this only happens with the new markers you are adding, right? As you have solved this with a work around already, probably you have a similar solution but I would add an if check that wraps the new marker like if(!profiler_is_locked_on_current_thread()) to make sure that we are not locked already. There isn't a super generic solution that I remember for it.