Add EventSource event for dropped async state machines (#14497)

One of the main bugs we've seen with async methods in production are cases where an async method awaits something that's never completed and is then just dropped.  This in turn allows the async state machine to be collected, such that subsequent dumps have no usable information to determine what hung and where.

To help diagnose such issues, this commit adds an EventSource event that fires when an async state machine is collected without having been completed.  When that happens, it dumps a textual representation of itself into a string and sends that to an event.

Doing this depends on the recent changes that were made to how we box async state machines to the heap.  Now that we do so with an explicit strongly-typed "box" instead of a normal runtime box, when the event source event is enabled, we can instead instantiate a derived and finalizable box, where the finalizer is responsible for firing the event, and we then suppress finalization when the async method completes.  The only async method state machines that are then finalized are those that are allowed to be collected before they're completed.

diff --git a/src/mscorlib/src/System/Runtime/CompilerServices/AsyncMethodBuilder.cs b/src/mscorlib/src/System/Runtime/CompilerServices/AsyncMethodBuilder.cs
index db4a71f..6f80529 100644 (file)
--- a/src/mscorlib/src/System/Runtime/CompilerServices/AsyncMethodBuilder.cs
+++ b/src/mscorlib/src/System/Runtime/CompilerServices/AsyncMethodBuilder.cs
@@ -11,12 +11,15 @@
 // =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-
 
 using System.Diagnostics;
+using System.Diagnostics.Tracing;
+using System.Reflection;
 using System.Runtime.ExceptionServices;
-using System.Threading;
-using System.Threading.Tasks;
 #if FEATURE_COMINTEROP
 using System.Runtime.InteropServices.WindowsRuntime;
 #endif // FEATURE_COMINTEROP
+using System.Threading;
+using System.Threading.Tasks;
+using System.Text;
 
 namespace System.Runtime.CompilerServices
 {
@@ -89,12 +92,14 @@ namespace System.Runtime.CompilerServices
                 AsyncCausalityTracer.TraceOperationCompletion(CausalityTraceLevel.Required, this.Task.Id, AsyncCausalityStatus.Completed);
             }
 
+            // Mark the builder as completed.  As this is a void-returning method, this mostly
+            // doesn't matter, but it can affect things like debug events related to finalization.
+            _builder.SetResult();
+
             if (_synchronizationContext != null)
             {
                 NotifySynchronizationContextOfCompletion();
             }
-
-            // No need to call _builder.SetResult, as no one pays attention to the task's completion.
         }
 
         /// <summary>Faults the method builder with an exception.</summary>
@@ -134,7 +139,8 @@ namespace System.Runtime.CompilerServices
                 AsyncMethodBuilderCore.ThrowAsync(exception, targetContext: null);
             }
 
-            // No need to call _builder.SetException, as no one pays attention to the task's completion.
+            // The exception was propagated already; we don't need or want to fault the builder, just mark it as completed.
+            _builder.SetResult();
         }
 
         /// <summary>Notifies the current synchronization context that the operation completed.</summary>
@@ -521,17 +527,40 @@ namespace System.Runtime.CompilerServices
             // cases is we lose the ability to properly step in the debugger, as the debugger uses that
             // object's identity to track this specific builder/state machine.  As such, we proceed to
             // overwrite whatever's there anyway, even if it's non-null.
-            var box = new AsyncStateMachineBox<TStateMachine>();
+            var box = AsyncMethodBuilderCore.TrackAsyncMethodCompletion ?
+                new DebugFinalizableAsyncStateMachineBox<TStateMachine>() :
+                new AsyncStateMachineBox<TStateMachine>();
             m_task = box; // important: this must be done before storing stateMachine into box.StateMachine!
             box.StateMachine = stateMachine;
             box.Context = currentContext;
             return box;
         }
 
+        /// <summary>
+        /// Provides an async state machine box with a finalizer that will fire an EventSource
+        /// event about the state machine if it's being finalized without having been completed.
+        /// </summary>
+        /// <typeparam name="TStateMachine">Specifies the type of the state machine.</typeparam>
+        private sealed class DebugFinalizableAsyncStateMachineBox<TStateMachine> :
+            AsyncStateMachineBox<TStateMachine>
+            where TStateMachine : IAsyncStateMachine
+        {
+            ~DebugFinalizableAsyncStateMachineBox()
+            {
+                // If the state machine is being finalized, something went wrong during its processing,
+                // e.g. it awaited something that got collected without itself having been completed.
+                // Fire an event with details about the state machine to help with debugging.
+                if (!IsCompleted) // double-check it's not completed, just to help minimize false positives
+                {
+                    TplEtwProvider.Log.IncompleteAsyncMethod(this);
+                }
+            }
+        }
+
         /// <summary>A strongly-typed box for Task-based async state machines.</summary>
         /// <typeparam name="TStateMachine">Specifies the type of the state machine.</typeparam>
         /// <typeparam name="TResult">Specifies the type of the Task's result.</typeparam>
-        private sealed class AsyncStateMachineBox<TStateMachine> :
+        private class AsyncStateMachineBox<TStateMachine> :
             Task<TResult>, IAsyncStateMachineBox
             where TStateMachine : IAsyncStateMachine
         {
@@ -561,6 +590,14 @@ namespace System.Runtime.CompilerServices
                 {
                     ExecutionContext.Run(Context, s_callback, this);
                 }
+
+                // In case this is a state machine box with a finalizer, suppress its finalization
+                // if it's now complete.  We only need the finalizer to run if the box is collected
+                // without having been completed.
+                if (IsCompleted && AsyncMethodBuilderCore.TrackAsyncMethodCompletion)
+                {
+                    GC.SuppressFinalize(this);
+                }
             }
 
             /// <summary>
@@ -608,7 +645,9 @@ namespace System.Runtime.CompilerServices
         private Task<TResult> InitializeTaskAsStateMachineBox()
         {
             Debug.Assert(m_task == null);
-            return (m_task = new AsyncStateMachineBox<IAsyncStateMachine>());
+            return (m_task = AsyncMethodBuilderCore.TrackAsyncMethodCompletion ?
+                new DebugFinalizableAsyncStateMachineBox<IAsyncStateMachine>() :
+                new AsyncStateMachineBox<IAsyncStateMachine>());
         }
 
         /// <summary>
@@ -891,7 +930,7 @@ namespace System.Runtime.CompilerServices
     /// <summary>
     /// An interface implemented by all <see cref="AsyncStateMachineBox{TStateMachine, TResult}"/> instances, regardless of generics.
     /// </summary>
-    interface IAsyncStateMachineBox : ITaskCompletionAction
+    internal interface IAsyncStateMachineBox : ITaskCompletionAction
     {
         /// <summary>
         /// Gets an action for moving forward the contained state machine.
@@ -906,6 +945,32 @@ namespace System.Runtime.CompilerServices
     /// <summary>Shared helpers for manipulating state related to async state machines.</summary>
     internal static class AsyncMethodBuilderCore // debugger depends on this exact name
     {
+        /// <summary>Gets whether we should be tracking async method completions for eventing.</summary>
+        internal static bool TrackAsyncMethodCompletion
+        {
+            [MethodImpl(MethodImplOptions.AggressiveInlining)]
+            get => TplEtwProvider.Log.IsEnabled(EventLevel.Warning, TplEtwProvider.Keywords.AsyncMethod);
+        }
+
+        /// <summary>Gets a description of the state of the state machine object, suitable for debug purposes.</summary>
+        /// <param name="stateMachine">The state machine object.</param>
+        /// <returns>A description of the state machine.</returns>
+        internal static string GetAsyncStateMachineDescription(IAsyncStateMachine stateMachine)
+        {
+            Debug.Assert(stateMachine != null);
+
+            Type stateMachineType = stateMachine.GetType();
+            FieldInfo[] fields = stateMachineType.GetFields(BindingFlags.Instance | BindingFlags.Public | BindingFlags.NonPublic);
+
+            var sb = new StringBuilder();
+            sb.AppendLine(stateMachineType.FullName);
+            foreach (FieldInfo fi in fields)
+            {
+                sb.AppendLine($"    {fi.Name}: {fi.GetValue(stateMachine)}");
+            }
+            return sb.ToString();
+        }
+
         internal static Action OutputAsyncCausalityEvents(Task task, Action continuation) =>
             CreateContinuationWrapper(continuation, (innerContinuation, innerTask) =>
             {

diff --git a/src/mscorlib/src/System/Threading/Tasks/TPLETWProvider.cs b/src/mscorlib/src/System/Threading/Tasks/TPLETWProvider.cs
index bdfe8ee..b666d2b 100644 (file)
--- a/src/mscorlib/src/System/Threading/Tasks/TPLETWProvider.cs
+++ b/src/mscorlib/src/System/Threading/Tasks/TPLETWProvider.cs
@@ -56,7 +56,8 @@ namespace System.Threading.Tasks
         /// Defines the singleton instance for the TPL ETW provider.
         /// The TPL Event provider GUID is {2e5dba47-a3d2-4d16-8ee0-6671ffdcd7b5}.
         /// </summary>
-        public static TplEtwProvider Log = new TplEtwProvider();
+        public static readonly TplEtwProvider Log = new TplEtwProvider();
+
         /// <summary>Prevent external instantiation.  All logging should go through the Log instance.</summary>
         private TplEtwProvider() { }
 
@@ -128,6 +129,11 @@ namespace System.Threading.Tasks
             public const EventKeywords TasksFlowActivityIds = (EventKeywords)0x80;
 
             /// <summary>
+            /// Events related to the happenings of async methods.
+            /// </summary>
+            public const EventKeywords AsyncMethod = (EventKeywords)0x100;
+
+            /// <summary>
             /// TasksSetActivityIds will cause the task operations to set Activity Ids 
             /// This option is incompatible with TasksFlowActivityIds flow is ignored
             /// if that keyword is set.   This option is likely to be removed in the future
@@ -528,6 +534,25 @@ namespace System.Threading.Tasks
                 WriteEvent(26, TaskID);
         }
 
+        [NonEvent]
+        public void IncompleteAsyncMethod(IAsyncStateMachineBox stateMachineBox)
+        {
+            System.Diagnostics.Debug.Assert(stateMachineBox != null);
+            if (IsEnabled(EventLevel.Warning, Keywords.AsyncMethod))
+            {
+                IAsyncStateMachine stateMachine = stateMachineBox.GetStateMachineObject();
+                if (stateMachine != null)
+                {
+                    string description = AsyncMethodBuilderCore.GetAsyncStateMachineDescription(stateMachine);
+                    IncompleteAsyncMethod(description);
+                }
+            }
+        }
+
+        [Event(27, Level = EventLevel.Warning, Keywords = Keywords.AsyncMethod)]
+        private void IncompleteAsyncMethod(string stateMachineDescription) =>
+            WriteEvent(27, stateMachineDescription);
+
         /// <summary>
         /// Activity IDs are GUIDS but task IDS are integers (and are not unique across appdomains
         /// This routine creates a process wide unique GUID given a task ID