Deadlock in EventListener static constructor

[noahfalk]

Description

When an app calls EventSource.GetSources(), (or many other EventSource APIs that would trigger calling EventListener.cctor) it may deadlock. Thread A holds the implicit lock on the static constructor and blocks trying to acquire an internal ETW OS lock. Thread B runs a callback from the OS where the ETW lock is held and blocks trying to acquire the implicit .cctor lock.

Thread A

00 000000c2`4e78cb58 00007ff9`a121ee0d     ntdll!ZwWaitForAlertByThreadId+0x14 [minkernel\ntdll\daytona\objfre\amd64\usrstubs.asm @ 3987] 
01 000000c2`4e78cb60 00007ff9`a121a5df     ntdll!RtlAcquireSRWLockExclusive+0x13d [minkernel\ntos\rtl\srwlock.c @ 1296] 
02 (Inline Function) --------`--------     ntdll!EtwpLockRegistration+0x9 [minkernel\etw\ntdll\evntsup.c @ 85] 
03 000000c2`4e78cbd0 00007ff9`a121a550     ntdll!EtwpSetProviderTraits+0x67 [minkernel\etw\ntdll\evntapi.c @ 564] 
04 000000c2`4e78cce0 00007ff6`15c7aacd     ntdll!EtwEventSetInformation+0x30 [minkernel\etw\ntdll\evntapi.c @ 810] 
05 000000c2`4e78cd10 00007ff6`15d8e8f8     System_Private_CoreLib!ILStubClass.IL_STUB_PInvoke(Int64, EVENT_INFO_CLASS, Void*, UInt32)+0x7d
06 000000c2`4e78cd18 00007ff6`758ce6c5     0x00007ff6`15d8e8f8
07 000000c2`4e78cd20 00007ff6`15c7a46d     emitetw_exe!ThePreStub+0x55
08 000000c2`4e78cdd0 0000002e`000000f3     System_Private_CoreLib!System.Diagnostics.Tracing.EventProvider.SetInformation(EVENT_INFO_CLASS, Void*, UInt32)+0x4d
000000C24E78CD40 00007ff9a12b29c4 [InlinedCallFrame: 000000c24e78cd40] Interop+Advapi32.EventSetInformation(Int64, EVENT_INFO_CLASS, Void*, UInt32)
000000C24E78CD40 00007ff615c7aacd [InlinedCallFrame: 000000c24e78cd40] Interop+Advapi32.EventSetInformation(Int64, EVENT_INFO_CLASS, Void*, UInt32)
000000C24E78CD10 00007ff615c7aacd ILStubClass.IL_STUB_PInvoke(Int64, EVENT_INFO_CLASS, Void*, UInt32)
000000C24E78CDD0 00007ff615c7a46d System.Diagnostics.Tracing.EventProvider.SetInformation(EVENT_INFO_CLASS, Void*, UInt32)
000000C24E78CE20 00007ff615c790ea System.Diagnostics.Tracing.EventSource.Initialize(System.Guid, System.String, System.String[])
000000C24E78CEE0 00007ff615c7871f System.Diagnostics.Tracing.EventSource..ctor(System.Guid, System.String, System.Diagnostics.Tracing.EventSourceSettings, System.String[])
000000C24E78CF30 00007ff615c78652 System.Diagnostics.Tracing.EventSource..ctor(System.Guid, System.String)
000000C24E78CF80 00007ff615c7852c System.Diagnostics.Tracing.NativeRuntimeEventSource..ctor()
000000C24E78D020 00007ff615c7844c System.Diagnostics.Tracing.NativeRuntimeEventSource..cctor()
000000C24E78D8F8 00007ff6758cd693 [HelperMethodFrame: 000000c24e78d8f8] 
000000C24E78DA10 00007ff615c783ee System.Diagnostics.Tracing.EventListener..cctor()  // <----- implicit .cctor lock held
000000C24E78E2D8 00007ff6758cd693 [HelperMethodFrame: 000000c24e78e2d8] 
000000C24E78E3F0 00007ff615c77704 System.Diagnostics.Tracing.EventListener.get_EventListenersLock()
000000C24E78E430 00007ff615c77141 System.Diagnostics.Tracing.EventSource.GetSources()

Thread B

000000C24F5FE530 00007ff9a122aa29 ntdll!RtlpEnterCriticalSectionContended + 0x339 [minkernel\ntos\rtl\resource.c:2310], calling ntdll!ZwWaitForAlertByThreadId [minkernel\ntdll\daytona\objfre\amd64\usrstubs.asm:3987]
000000C24F5FE650 00007ff9a1227fe2 ntdll!RtlEnterCriticalSection + 0x42 [minkernel\ntos\rtl\resource.c:1923], calling ntdll!RtlpEnterCriticalSectionContended [minkernel\ntos\rtl\resource.c:1951]
000000C24F5FE680 00007ff675375adb emitetw_exe!CrstBase::Enter + 0x9b [D:\a\_work\1\s\src\coreclr\vm\crst.cpp:328], calling ntdll!RtlEnterCriticalSection [minkernel\ntos\rtl\resource.c:1860]
000000C24F5FE6B0 00007ff6753d6901 emitetw_exe!MethodTable::DoRunClassInitThrowing + 0x181 [D:\a\_work\1\s\src\coreclr\vm\methodtable.cpp:3344], calling emitetw_exe!CrstBase::Enter [D:\a\_work\1\s\src\coreclr\vm\crst.cpp:168]
000000C24F5FE780 00007ff9a122c09d ntdll!RtlpFreeHeapInternal + 0x7cd [minkernel\ntos\rtl\heap.c:2703], calling ntdll!RtlpHpStackLoggingEnabled [minkernel\ntos\rtl\heaplog.c:3430]
000000C24F5FE810 00007ff6753ed8ca emitetw_exe!MethodDesc::JitCompileCodeLockedEventWrapper + 0x51a [D:\a\_work\1\s\src\coreclr\vm\prestub.cpp:1027], calling emitetw_exe!DACNotifyCompilationFinished [D:\a\_work\1\s\src\coreclr\vm\prestub.cpp:283]
000000C24F5FE840 00007ff9a122b3e1 ntdll!RtlFreeHeap + 0x51 [minkernel\ntos\rtl\heappublic.c:357], calling ntdll!RtlpFreeHeapInternal [minkernel\ntos\rtl\heap.c:2533]
000000C24F5FE870 00007ff6753759d1 emitetw_exe!CrstBase::Destroy + 0x81 [D:\a\_work\1\s\src\coreclr\vm\crst.cpp:100], calling ntdll!RtlDeleteCriticalSection [minkernel\ntos\rtl\resource.c:3965]
000000C24F5FE880 00007ff6756053cb emitetw_exe!operator delete[] + 0x1b [D:\a\_work\1\s\src\coreclr\utilcode\clrhost_nodependencies.cpp:398], calling kernel32!HeapFreeStub [clientcore\base\win32\client\stub.c:2754]
000000C24F5FE8B0 00007ff675375b1f emitetw_exe!CrstBase::Leave + 0xf [D:\a\_work\1\s\src\coreclr\vm\crst.cpp:358], calling ntdll!RtlLeaveCriticalSection [minkernel\ntos\rtl\resource.c:2384]
000000C24F5FE8E0 00007ff6753f330a emitetw_exe!ListLockEntryBase<NativeCodeVersion>::Release + 0x9a [D:\a\_work\1\s\src\coreclr\vm\listlock.h:178], calling emitetw_exe!CrstBase::Leave [D:\a\_work\1\s\src\coreclr\vm\crst.cpp:340]
000000C24F5FE940 00007ff675585aa6 emitetw_exe!FixupPrecode::SetTargetInterlocked + 0x206 [D:\a\_work\1\s\src\coreclr\vm\i386\stublinkerx86.cpp:5397], calling emitetw_exe!ExecutableAllocator::MapRW [D:\a\_work\1\s\src\coreclr\utilcode\executableallocator.cpp:677]
000000C24F5FE9C0 00007ff6753ec26e emitetw_exe!Precode::SetTargetInterlocked + 0x15e [D:\a\_work\1\s\src\coreclr\vm\precode.cpp:452], calling emitetw_exe!FixupPrecode::SetTargetInterlocked [D:\a\_work\1\s\src\coreclr\vm\i386\stublinkerx86.cpp:5337]
000000C24F5FE9F0 00007ff6753cfd53 emitetw_exe!MethodDesc::TrySetInitialCodeEntryPointForVersionableMethod + 0x123 [D:\a\_work\1\s\src\coreclr\vm\method.cpp:4951], calling emitetw_exe!MethodDesc::GetOrCreatePrecode [D:\a\_work\1\s\src\coreclr\vm\method.cpp:4696]
000000C24F5FEA20 00007ff675371a96 emitetw_exe!CodeVersionManager::PublishVersionableCodeIfNecessary + 0x5e6 [D:\a\_work\1\s\src\coreclr\vm\codeversion.cpp:1877], calling emitetw_exe!__security_check_cookie [d:\a01\_work\12\s\src\vctools\crt\vcstartup\src\gs\amd64\amdsecgs.asm:45]
000000C24F5FEAB0 00007ff675371a96 emitetw_exe!CodeVersionManager::PublishVersionableCodeIfNecessary + 0x5e6 [D:\a\_work\1\s\src\coreclr\vm\codeversion.cpp:1877], calling emitetw_exe!__security_check_cookie [d:\a01\_work\12\s\src\vctools\crt\vcstartup\src\gs\amd64\amdsecgs.asm:45]
000000C24F5FEB40 00007ff6753cf6b5 emitetw_exe!MethodDesc::GetTemporaryEntryPoint + 0x55 [D:\a\_work\1\s\src\coreclr\vm\method.cpp:4599], calling emitetw_exe!MethodDescChunk::GetTemporaryEntryPoint [D:\a\_work\1\s\src\coreclr\vm\method.cpp:4550]
000000C24F5FEB70 00007ff6753ec64c emitetw_exe!MethodDesc::DoBackpatch + 0x9c [D:\a\_work\1\s\src\coreclr\vm\prestub.cpp:106], calling emitetw_exe!MethodDesc::GetTemporaryEntryPoint [D:\a\_work\1\s\src\coreclr\vm\method.cpp:4578]
000000C24F5FEB90 00007ff675375adb emitetw_exe!CrstBase::Enter + 0x9b [D:\a\_work\1\s\src\coreclr\vm\crst.cpp:328], calling ntdll!RtlEnterCriticalSection [minkernel\ntos\rtl\resource.c:1860]
000000C24F5FEC00 00007ff6753efd1e emitetw_exe!MethodDesc::DoPrestub + 0x1de [D:\a\_work\1\s\src\coreclr\vm\prestub.cpp:2217], calling emitetw_exe!MethodDesc::DoBackpatch [D:\a\_work\1\s\src\coreclr\vm\prestub.cpp:84]
000000C24F5FEC60 00007ff6753d703d emitetw_exe!MethodTable::CheckRunClassInitThrowing + 0x8d [D:\a\_work\1\s\src\coreclr\vm\methodtable.cpp:3508], calling emitetw_exe!DomainLocalModule::GetClassFlags [D:\a\_work\1\s\src\coreclr\vm\appdomain.cpp:4538]
000000C24F5FEC90 00007ff6754a0511 emitetw_exe!JIT_GetSharedNonGCStaticBase_Helper + 0x111 [D:\a\_work\1\s\src\coreclr\vm\jithelpers.cpp:1415], calling emitetw_exe!MethodTable::CheckRunClassInitThrowing [D:\a\_work\1\s\src\coreclr\vm\methodtable.cpp:3475]
000000C24F5FECB0 00007ff9a1262810 ntdll!RtlSetLastWin32Error + 0x40 [minkernel\ntos\rtl\error.c:316], calling ntdll!__security_check_cookie [onecore\private\minwin\priv_sdk\inc\gs\crt_amdsecgs.asm:54]
000000C24F5FECC0 00007ff615c7e3fb (MethodDesc 00007ff615da5610 + 0x16b ILStubClass.IL_STUB_PInvoke(Internal.Win32.SafeHandles.SafeRegistryHandle, System.String, Int32, Int32, Internal.Win32.SafeHandles.SafeRegistryHandle ByRef)), calling emitetw_exe!JIT_CheckedWriteBarrier
000000C24F5FED00 00007ff6753efb09 emitetw_exe!PreStubWorker + 0x2a9 [D:\a\_work\1\s\src\coreclr\vm\prestub.cpp:2059], calling kernel32!SetLastErrorStub [clientcore\base\win32\client\stub.c:1730]
000000C24F5FED90 00007ff6753efb09 emitetw_exe!PreStubWorker + 0x2a9 [D:\a\_work\1\s\src\coreclr\vm\prestub.cpp:2059], calling kernel32!SetLastErrorStub [clientcore\base\win32\client\stub.c:1730]
000000C24F5FEDB8 00007ff6754a0473 emitetw_exe!JIT_GetSharedNonGCStaticBase_Helper + 0x73 [D:\a\_work\1\s\src\coreclr\vm\jithelpers.cpp:1409], calling emitetw_exe!LazyMachStateCaptureState
000000C24F5FEE00 00007ff615c77704 (MethodDesc 00007ff615d8aba8 + 0x24 System.Diagnostics.Tracing.EventListener.get_EventListenersLock()), calling emitetw_exe!JIT_GetSharedNonGCStaticBase_SingleAppDomain
000000C24F5FEE40 00007ff615c7e9cc (MethodDesc 00007ff615d85c48 + 0x8c System.Diagnostics.Tracing.EventSource.SendCommand(System.Diagnostics.Tracing.EventListener, System.Diagnostics.Tracing.EventProviderType, Int32, Int32, System.Diagnostics.Tracing.EventCommand, Boolean, System.Diagnostics.Tracing.EventLevel, System.Diagnostics.Tracing.EventKeywords, System.Collections.Generic.IDictionary`2<System.String,System.String>)), calling 00007ff615db2c88
000000C24F5FEEC0 00007ff615c7e87f (MethodDesc 00007ff615d8efc0 + 0xaf System.Diagnostics.Tracing.EventSource+OverrideEventProvider.OnControllerCommand(System.Diagnostics.Tracing.ControllerCommand, System.Collections.Generic.IDictionary`2<System.String,System.String>, Int32, Int32)), calling (MethodDesc 00007ff615d85c48 + 0 System.Diagnostics.Tracing.EventSource.SendCommand(System.Diagnostics.Tracing.EventListener, System.Diagnostics.Tracing.EventProviderType, Int32, Int32, System.Diagnostics.Tracing.EventCommand, Boolean, System.Diagnostics.Tracing.EventLevel, System.Diagnostics.Tracing.EventKeywords, System.Collections.Generic.IDictionary`2<System.String,System.String>))
000000C24F5FEF50 00007ff615c7aed4 (MethodDesc 00007ff615d8eba8 + 0x3b4 System.Diagnostics.Tracing.EventProvider.EtwEnableCallBack(System.Guid ByRef, Int32, Byte, Int64, Int64, EVENT_FILTER_DESCRIPTOR*, Void*))
000000C24F5FF090 00007ff615c7a1da (MethodDesc 00007ff615da0a78 + 0x7a ILStubClass.IL_STUB_ReversePInvoke(IntPtr, Int32, Byte, Int64, Int64, Int64, Int64))
000000C24F5FF120 00007ff9a121a839 ntdll!EtwpEventApiCallback + 0xe9 [minkernel\etw\ntdll\evntapi.c:273], calling ntdll!LdrpDispatchUserCallTarget [minkernel\ntos\rtl\amd64\cfgcheck.asm:738]
000000C24F5FF1D0 00007ff9a121ab10 ntdll!EtwpUpdateEnableInfoAndCallback + 0xd8 [minkernel\etw\ntdll\evntsup.c:1571], calling ntdll!EtwpEventApiCallback [minkernel\etw\ntdll\evntapi.c:122]
000000C24F5FF1E0 00007ff9a1282462 ntdll!EtwpRegistrationCompare + 0x22 [minkernel\etw\ntdll\evntsup.c:208], calling ntdll!memcmp [minkernel\crts\crtw32\string\amd64\memcmp.asm:61]
000000C24F5FF220 00007ff9a1263d2b ntdll!EtwpProcessNotification + 0x53 [minkernel\etw\ntdll\evntsup.c:1016], calling ntdll!EtwpUpdateEnableInfoAndCallback [minkernel\etw\ntdll\evntsup.c:1401]
000000C24F5FF250 00007ff9a1263902 ntdll!EtwDeliverDataBlock + 0xb2 [minkernel\etw\ntdll\evntsup.c:1092], calling ntdll!EtwpProcessNotification [minkernel\etw\ntdll\evntsup.c:940]
000000C24F5FF2E0 00007ff9a126377d ntdll!EtwpNotificationThread + 0x6d [minkernel\etw\ntdll\notify.c:440], calling ntdll!EtwDeliverDataBlock [minkernel\etw\ntdll\evntsup.c:1041]
000000C24F5FF3A0 00007ff9a122d019 ntdll!RtlpAllocateHeapInternal + 0x6c9 [minkernel\ntos\rtl\heap.c:2399], calling ntdll!RtlpAllocateHeap [minkernel\ntos\rtl\heap.c:6748]
000000C24F5FF3E0 00007ff9a1219fe2 ntdll!TppCritSetThread + 0x7a [minkernel\threadpool\ntdll\tp.c:763], calling ntdll!__security_check_cookie [onecore\private\minwin\priv_sdk\inc\gs\crt_amdsecgs.asm:54]
000000C24F5FF460 00007ff9a1217972 ntdll!TppExecuteWaitCallback + 0xae [minkernel\threadpool\ntdll\wait.c:1611], calling ntdll!LdrpDispatchUserCallTarget [minkernel\ntos\rtl\amd64\cfgcheck.asm:738]
000000C24F5FF480 00007ff9a121785a ntdll!TppWaitCompletion + 0x8a [minkernel\threadpool\ntdll\wait.c:732], calling ntdll!RtlReleaseSRWLockExclusive [minkernel\ntos\rtl\srwlock.c:518]
000000C24F5FF4B0 00007ff9a121c408 ntdll!TppWorkerThread + 0x448 [minkernel\threadpool\ntdll\worker.c:1048], calling ntdll!LdrpDispatchUserCallTarget [minkernel\ntos\rtl\amd64\cfgcheck.asm:738]
000000C24F5FF7A0 00007ff99fc14ed0 kernel32!BaseThreadInitThunk + 0x10 [clientcore\base\win32\client\thread.c:75], calling kernel32!BaseThreadInitXfgThunk [clientcore\base\win32\client\amd64\thunk.asm:27]
000000C24F5FF7D0 00007ff9a128e39b ntdll!RtlUserThreadStart + 0x2b [minkernel\ntdll\rtlstrt.c:1152], calling ntdll!LdrpDispatchUserCallTarget [minkernel\ntos\rtl\amd64\cfgcheck.asm:738]

Probably we should fix this by removing the call to initialize the RuntimeEventSource from the EventListener .cctor and finding some other place to do that.

Reproduction Steps

We don't have deterministic repro, but it was observed from a small .NET 6 windows app that calls EventSource.GetSources() + lucky timing. Putting a Sleep() inside EventListener.cctor would probably make it much easier to hit.

Expected behavior

EventSource.GetSources() doesn't block

Actual behavior

EventSource.GetSources() blocks

Regression?

Uncertain at this point

Known Workarounds

No response

Configuration

Windows .NET 6 x64 (architecture probably doesn't matter)

Other information

No response