diagnostics icon indicating copy to clipboard operation
diagnostics copied to clipboard
verified publisher icon dotnet

NativeRuntimeEventSource behaving poorly in conjunction with other providers

Open stephentoub opened this issue 2 years ago • 4 comments

Consider this repro:

using System.Diagnostics.Tracing;

using var _ = new MyListener();
while (true)
{
    new List<int>();
}

internal class MyListener : EventListener
{
    protected override void OnEventSourceCreated(EventSource eventSource)
    {
        if (eventSource.Name is "Microsoft-Windows-DotNETRuntime"

                                // Uncomment either or both of these and everything still works fine
                             //or "System.Buffers.ArrayPoolEventSource"
                             //or "System.Diagnostics.Eventing.FrameworkEventSource"

                                // Uncomment this, and no events are output
                             //or "System.Runtime"

                                // Uncomment this, and the app stack overflows
                             //or "System.Threading.Tasks.TplEventSource"
                             )
        {
            EnableEvents(eventSource, EventLevel.Informational, EventKeywords.All);
        }
    }

    protected override void OnEventWritten(EventWrittenEventArgs eventData) =>
        Console.WriteLine(eventData.EventName);
}

Run it, and it correctly spews lots of GC-related events to the console.

Uncomment either or both of the ArrayPoolEventSource and/or FrameworkEventSource lines, and everything still outputs as expected.

But if you uncomment the System.Runtime line, no events get output at all.

And if you uncomment the TplEventSource line, the app crashes.

cc: @brianrob, @noahfalk

stephentoub avatar Jun 25 '23 00:06 stephentoub

Enabling Microsoft-Windows-DotNETRuntime and System.Runtime causes a deadlock because one thread is holding the AppContext lock and trying to call Console.Out.EnsureInitialized, and the other is in Console.Out.EnsureInitialized trying to get the AppContext lock

Thread 1

 	[Deadlocked, double-click or press enter to view all thread stacks]	
 	[Waiting on lock owned by Thread 39976, double-click or press enter to switch to thread]	
 	System.Private.CoreLib.dll!System.Threading.Monitor.Enter(object obj, ref bool lockTaken) Line 49	C#
 	System.Console.dll!System.Console.get_Out.__EnsureInitialized|26_0() Line 206	C#
 	System.Console.dll!System.Console.Out.get() Line 200	C#
 	System.Console.dll!System.Console.WriteLine(string value) Line 808	C#
 	ProviderTest.dll!MyListener.OnEventWritten(System.Diagnostics.Tracing.EventWrittenEventArgs eventData) Line 31	C#
 	System.Private.CoreLib.dll!System.Diagnostics.Tracing.EventSource.DispatchToAllListeners(System.Diagnostics.Tracing.EventWrittenEventArgs eventCallbackArgs) Line 2073	C#
 	System.Private.CoreLib.dll!System.Diagnostics.Tracing.EventSource.WriteToAllListeners(System.Diagnostics.Tracing.EventWrittenEventArgs eventCallbackArgs, int eventDataCount, System.Diagnostics.Tracing.EventSource.EventData* data) Line 2058	C#
 	System.Private.CoreLib.dll!System.Diagnostics.Tracing.EventSource.WriteEventWithRelatedActivityIdCore(int eventId, System.Guid* relatedActivityId, int eventDataCount, System.Diagnostics.Tracing.EventSource.EventData* data) Line 1341	C#
 	System.Private.CoreLib.dll!System.Diagnostics.Tracing.EventSource.WriteEventCore(int eventId, int eventDataCount, System.Diagnostics.Tracing.EventSource.EventData* data) Line 1237	C#
 	System.Private.CoreLib.dll!System.Diagnostics.Tracing.EventSource.WriteEvent(int eventId, string arg1, int arg2) Line 974	C#
 	System.Private.CoreLib.dll!System.Diagnostics.Tracing.RuntimeEventSource.LogAppContextSwitch(string switchName, int value) Line 70	C#
 	System.Private.CoreLib.dll!System.AppContext.LogSwitchValues.__LogDataStore|23_0(System.Diagnostics.Tracing.RuntimeEventSource ev, System.Collections.Generic.Dictionary<string, bool> switches) Line 73	C#
 	System.Private.CoreLib.dll!System.AppContext.LogSwitchValues(System.Diagnostics.Tracing.RuntimeEventSource ev) Line 83	C#
 	System.Private.CoreLib.dll!System.Diagnostics.Tracing.RuntimeEventSource.OnEventCommand(System.Diagnostics.Tracing.EventCommandEventArgs command) Line 121	C#
 	System.Private.CoreLib.dll!System.Diagnostics.Tracing.EventSource.DoCommand(System.Diagnostics.Tracing.EventCommandEventArgs commandArgs) Line 2681	C#
 	System.Private.CoreLib.dll!System.Diagnostics.Tracing.EventSource.SendCommand(System.Diagnostics.Tracing.EventListener listener, System.Diagnostics.Tracing.EventProviderType eventProviderType, int perEventSourceSessionId, int etwSessionId, System.Diagnostics.Tracing.EventCommand command, bool enable, System.Diagnostics.Tracing.EventLevel level, System.Diagnostics.Tracing.EventKeywords matchAnyKeyword, System.Collections.Generic.IDictionary<string, string> commandArguments) Line 2517	C#
 	System.Private.CoreLib.dll!System.Diagnostics.Tracing.EventListener.EnableEvents(System.Diagnostics.Tracing.EventSource eventSource, System.Diagnostics.Tracing.EventLevel level, System.Diagnostics.Tracing.EventKeywords matchAnyKeyword, System.Collections.Generic.IDictionary<string, string> arguments) Line 4071	C#
 	System.Private.CoreLib.dll!System.Diagnostics.Tracing.EventListener.EnableEvents(System.Diagnostics.Tracing.EventSource eventSource, System.Diagnostics.Tracing.EventLevel level, System.Diagnostics.Tracing.EventKeywords matchAnyKeyword) Line 4048	C#
 	ProviderTest.dll!MyListener.OnEventSourceCreated(System.Diagnostics.Tracing.EventSource eventSource) Line 26	C#
 	System.Private.CoreLib.dll!System.Diagnostics.Tracing.EventSource.AddListener(System.Diagnostics.Tracing.EventListener listener) Line 3521	C#
 	System.Private.CoreLib.dll!System.Diagnostics.Tracing.EventListener..ctor.AnonymousMethod__9_0(object obj, System.Diagnostics.Tracing.EventSourceCreatedEventArgs args) Line 3973	C#
 	System.Private.CoreLib.dll!System.Diagnostics.Tracing.EventListener.CallBackForExistingEventSources(bool addToListenersList, System.EventHandler<System.Diagnostics.Tracing.EventSourceCreatedEventArgs> callback) Line 4412	C#
 	System.Private.CoreLib.dll!System.Diagnostics.Tracing.EventListener.EventListener() Line 3974	C#
 	ProviderTest.dll!MyListener.MyListener()	Unknown
 	ProviderTest.dll!Program.<Main>$(string[] args) Line 3	C#

Thread 2

 	[Deadlocked, double-click or press enter to view all thread stacks]	
 	[Waiting on lock owned by Thread 38724, double-click or press enter to switch to thread]	
>	System.Private.CoreLib.dll!System.Threading.Monitor.Enter(object obj, ref bool lockTaken) Line 49	C#
 	System.Private.CoreLib.dll!System.AppContext.GetData(string name) Line 43	C#
 	System.Private.CoreLib.dll!System.AppContext.TryGetSwitch(string switchName, out bool isEnabled) Line 109	C#
 	System.Private.CoreLib.dll!System.LocalAppContextSwitches.GetCachedSwitchValueInternal(string switchName, ref int cachedSwitchValue) Line 30	C#
 	System.Private.CoreLib.dll!System.LocalAppContextSwitches.GetCachedSwitchValue(string switchName, ref int cachedSwitchValue) Line 25	C#
 	System.Private.CoreLib.dll!System.LocalAppContextSwitches.EnableUnsafeUTF7Encoding.get() Line 14	C#
 	System.Private.CoreLib.dll!System.Text.Encoding.FilterDisallowedEncodings(System.Text.Encoding encoding) Line 309	C#
 	System.Private.CoreLib.dll!System.Text.Encoding.GetEncoding(int codepage) Line 208	C#
 	System.Console.dll!System.Text.EncodingHelper.GetSupportedConsoleEncoding(int codepage) Line 34	C#
 	System.Console.dll!System.ConsolePal.OutputEncoding.get() Line 117	C#
 	System.Console.dll!System.Console.OutputEncoding.get() Line 118	C#
 	System.Console.dll!System.ConsolePal.OpenStandardOutput() Line 42	C#
 	System.Console.dll!System.Console.get_Out.__EnsureInitialized|26_0() Line 208	C#
 	System.Console.dll!System.Console.Out.get() Line 200	C#
 	System.Console.dll!System.Console.WriteLine(string value) Line 808	C#
 	ProviderTest.dll!MyListener.OnEventWritten(System.Diagnostics.Tracing.EventWrittenEventArgs eventData) Line 31	C#
 	System.Private.CoreLib.dll!System.Diagnostics.Tracing.EventSource.DispatchToAllListeners(System.Diagnostics.Tracing.EventWrittenEventArgs eventCallbackArgs) Line 2073	C#
 	System.Private.CoreLib.dll!System.Diagnostics.Tracing.NativeRuntimeEventSource.ProcessEvent(uint eventID, uint osThreadID, System.DateTime timeStamp, System.Guid activityId, System.Guid childActivityId, System.ReadOnlySpan<byte> payload) Line 65	C#
 	System.Private.CoreLib.dll!System.Diagnostics.Tracing.EventPipeEventDispatcher.DispatchEventsToEventListeners() Line 166	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.InnerInvoke() Line 2400	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task..cctor.AnonymousMethod__273_0(object obj) Line 2388	C#
 	System.Private.CoreLib.dll!System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext executionContext, System.Threading.ContextCallback callback, object state) Line 184	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.ExecuteWithThreadLocal(ref System.Threading.Tasks.Task currentTaskSlot, System.Threading.Thread threadPoolThread) Line 2345	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.Task.ExecuteEntryUnsafe(System.Threading.Thread threadPoolThread) Line 2283	C#
 	System.Private.CoreLib.dll!System.Threading.Tasks.ThreadPoolTaskScheduler..cctor.AnonymousMethod__10_0(object s) Line 36	C#
 	System.Private.CoreLib.dll!System.Threading.Thread.StartHelper.RunWorker() Line 92	C#
 	System.Private.CoreLib.dll!System.Threading.Thread.StartHelper.Run() Line 56	C#
 	System.Private.CoreLib.dll!System.Threading.Thread.StartCallback() Line 106	C#

This is a recurring theme for EventSource - we call out to user code at times that is hard to reason about and potentially dangerous. This particular example could be avoided by calling Console.Write before trying to initialize any EventSources, but we see this type of issue repeatedly.

I don't think we'll be able to address this in 8 but longer term we should consider anything we can do to avoid these types of deadlocks.

davmason avatar Aug 08 '23 23:08 davmason

The stack overflow for TPLEventSource is due to the jitting of a method in Console.EnsureInitialized triggering a jit, which triggers an ActivityID to be created and an event to be fired, then calls in to the eventsource and when it tries to log to the console it triggers a new jit for the same method because the previous jit is blocked waiting for the previous event

This stack is repeated until the overflow. The method we are trying to jit is System.Text.EncodingHelper.GetSupportedConsoleEncoding(Int32)

[0x5a]   System_Private_CoreLib!System.Runtime.Loader.AssemblyLoadContext.StartAssemblyLoad+0xab   0xcef468a740   0x7ffe995dfe83   
[0x5b]   coreclr!CallDescrWorkerInternal+0x83   0xcef468a7b0   0x7ffe994e0e68   
[0x5c]   coreclr!DispatchCallSimple+0x60   0xcef468a7f0   0x7ffe997ed494   
[0x5d]   coreclr!ActivityTracker::Start+0x80   0xcef468a880   0x7ffe997ec343   
[0x5e]   coreclr!`anonymous namespace'::FireAssemblyLoadStart+0x53   0xcef468a8f0   0x7ffe99621c7d   
[0x5f]   coreclr!BinderTracing::AssemblyBindOperation::AssemblyBindOperation+0x16299d   0xcef468a980   0x7ffe99504cc8   
[0x60]   coreclr!AppDomain::BindAssemblySpec+0xa8   0xcef468a9c0   0x7ffe99505988   
[0x61]   coreclr!PEAssembly::LoadAssembly+0xc8   0xcef468b0f0   0x7ffe99499ea0   
[0x62]   coreclr!Module::LoadAssemblyImpl+0x190   0xcef468b190   0x7ffe99596a3e   
[0x63]   coreclr!ModuleBase::LoadAssembly+0x13   0xcef468b2d0   0x7ffe994cc917   
[0x64]   coreclr!Assembly::FindModuleByTypeRef+0x1c2   0xcef468b2d0   0x7ffe994cc917   
[0x65]   coreclr!ClassLoader::LoadTypeDefOrRefThrowing+0x237   0xcef468b370   0x7ffe994ba176   
[0x66]   coreclr!MemberLoader::GetDescFromMemberRef+0x3a6   0xcef468b470   0x7ffe9953d87a   
[0x67]   coreclr!CEEInfo::resolveToken+0xc4a   0xcef468b700   0x7ffea1e4b5ef   
[0x68]   clrjit!Compiler::impImportBlockCode+0x2abf   0xcef468ba50   0x7ffea1de81c7   
[0x69]   clrjit!Compiler::impImportBlock+0xb7   0xcef468c1f0   0x7ffea1de7dd6   
[0x6a]   clrjit!Compiler::impImport+0x416   0xcef468c340   0x7ffea1de997e   
[0x6b]   clrjit!Compiler::fgImport+0xe   0xcef468c3b0   0x7ffea1e37a13   
[0x6c]   clrjit!Phase::Run+0x1b   0xcef468c3e0   0x7ffea1e46492   
[0x6d]   clrjit!DoPhase+0x4a   0xcef468c3e0   0x7ffea1e46492   
[0x6e]   clrjit!Compiler::compCompile+0x163   0xcef468c3e0   0x7ffea1e46492   
[0x6f]   clrjit!Compiler::compCompileHelper+0x9d2   0xcef468cbc0   0x7ffea1e47152   
[0x70]   clrjit!Compiler::compCompile+0x532   0xcef468cca0   0x7ffea1de75b5   
[0x71]   clrjit!jitNativeCode+0x265   0xcef468cd60   0x7ffea1e66743   
[0x72]   clrjit!CILJit::compileMethod+0x83   0xcef468cf00   0x7ffe99508675   
[0x73]   coreclr!invokeCompileMethodHelper+0x7e   0xcef468cf70   0x7ffe99507d45   
[0x74]   coreclr!invokeCompileMethod+0xb3   0xcef468cf70   0x7ffe99507d45   
[0x75]   coreclr!UnsafeJitFunction+0x785   0xcef468cf70   0x7ffe99507d45   
[0x76]   coreclr!MethodDesc::JitCompileCodeLocked+0x209   0xcef468d450   0x7ffe99507ab2   
[0x77]   coreclr!MethodDesc::JitCompileCodeLockedEventWrapper+0xbe   0xcef468d620   0x7ffe9950783c   
[0x78]   coreclr!MethodDesc::JitCompileCode+0x2ac   0xcef468d780   0x7ffe9949b19c   
[0x79]   coreclr!MethodDesc::PrepareILBasedCode+0x3bb   0xcef468d830   0x7ffe9949a540   
[0x7a]   coreclr!MethodDesc::PrepareCode+0x3bb   0xcef468d830   0x7ffe9949a540   
[0x7b]   coreclr!CodeVersionManager::PublishVersionableCodeIfNecessary+0x64c   0xcef468d830   0x7ffe9949a540   
[0x7c]   coreclr!MethodDesc::DoPrestub+0x170   0xcef468dc80   0x7ffe9949a29b   
[0x7d]   coreclr!PreStubWorker+0x21b   0xcef468dda0   0x7ffe995e11c5   
[0x7e]   coreclr!ThePreStub+0x55   0xcef468df40   0x7ffe39efe980   
[0x7f]   System_Console!System.ConsolePal.get_OutputEncoding+0x30   0xcef468dff0   0x7ffe39efe8ac   
[0x80]   System_Console!System.Console.get_OutputEncoding+0xbc   0xcef468e040   0x7ffe39efe757   
[0x81]   System_Console!System.ConsolePal.OpenStandardOutput+0x37   0xcef468e0b0   0x7ffe39efe66b   
[0x82]   System_Console!System.Console.<get_Out>g__EnsureInitialized|26_0+0x8b   0xcef468e120   0x7ffe39efe542   
[0x83]   System_Console!System.Console.get_Out+0x72   0xcef468e190   0x7ffe39efe489   
[0x84]   System_Console!System.Console.WriteLine+0x29   0xcef468e1e0   0x7ffe39efe280   
[0x85]   ProviderTest!MyListener.OnEventWritten+0x40   0xcef468e220   0x7ffe39efb796   
[0x86]   System_Private_CoreLib!System.Diagnostics.Tracing.EventSource.DispatchToAllListeners+0xc6   0xcef468e270   0x7ffe39effc0e   
[0x87]   System_Private_CoreLib!System.Diagnostics.Tracing.EventSource.WriteEventVarargs+0x6ae   0xcef468e320   0x7ffe39eff37b   
[0x88]   System_Private_CoreLib!System.Diagnostics.Tracing.EventSource.WriteEvent+0x3b   0xcef468e520   0x7ffe39ed3e61   
[0x89]   System_Private_CoreLib!System.Threading.Tasks.TplEventSource.SetActivityId+0xa1   0xcef468e560   0x7ffe39ef35d0   
[0x8a]   System_Private_CoreLib!System.Diagnostics.Tracing.EventSource.SetCurrentThreadActivityId+0x90   0xcef468e5c0   0x7ffe39efd0f7   
[0x8b]   System_Private_CoreLib!System.Diagnostics.Tracing.ActivityTracker.ActivityChanging+0x147   0xcef468e630   0x7ffe39efcf00   
[0x8c]   System_Private_CoreLib!System.Threading.AsyncLocal<ActivityInfo>.System.Threading.IAsyncLocal.OnValueChanged+0x190   0xcef468e710   0x7ffe39efc18f   
[0x8d]   System_Private_CoreLib!System.Threading.ExecutionContext.SetLocalValue+0x29f   0xcef468e7d0   0x7ffe39efbc10   
[0x8e]   System_Private_CoreLib!System.Threading.AsyncLocal<ActivityInfo>.set_Value+0x40   0xcef468e890   0x7ffe39ef9f64   
[0x8f]   System_Private_CoreLib!System.Diagnostics.Tracing.ActivityTracker.OnStart+0x3f4   0xcef468e8d0   0x7ffe39ef8dab   
[0x90]   System_Private_CoreLib!System.Runtime.Loader.AssemblyLoadContext.StartAssemblyLoad+0xab   0xcef468ea50   0x7ffe995dfe83

davmason avatar Aug 09 '23 00:08 davmason

Moving this to 9

davmason avatar Aug 09 '23 00:08 davmason

We plan to document this as the behavior can be controlled in the EventSource callbacks. The problem is re-entrant behavior triggering other callbacks which can cause undesired behavior.

tommcdon avatar Jul 30 '24 20:07 tommcdon