Add EventSource event for WaitHandle waits (#94737)

Add start/stop events for WaitHandle waits Context: #94264
dotnet · Dec 7, 2023 · 7bbfcc4 · 7bbfcc4
1 parent f1d2587
commit 7bbfcc4
Show file tree

Hide file tree

Showing 35 changed files with 648 additions and 27 deletions.
diff --git a/...src/System/Diagnostics/Eventing/NativeRuntimeEventSource.Threading.NativeSinks.CoreCLR.cs b/...src/System/Diagnostics/Eventing/NativeRuntimeEventSource.Threading.NativeSinks.CoreCLR.cs
@@ -97,5 +97,18 @@ private static partial void LogThreadPoolIOPack(
             IntPtr NativeOverlapped,
             IntPtr Overlapped,
             ushort ClrInstanceID);
+
+#pragma warning disable IDE0060 // Remove unused parameter
+        [NonEvent]
+        private static void LogWaitHandleWaitStart(
+            WaitHandleWaitSourceMap WaitSource,
+            IntPtr AssociatedObjectID,
+            ushort ClrInstanceID) =>
+            Debug.Fail("This event is currently not expected to be raised by managed code in CoreCLR.");
+
+        [NonEvent]
+        private static void LogWaitHandleWaitStop(ushort ClrInstanceID) =>
+            Debug.Fail("This event is currently not expected to be raised by managed code in CoreCLR.");
+#pragma warning restore IDE0060
     }
 }
diff --git a/src/coreclr/System.Private.CoreLib/src/System/Threading/WaitHandle.CoreCLR.cs b/src/coreclr/System.Private.CoreLib/src/System/Threading/WaitHandle.CoreCLR.cs
@@ -11,7 +11,7 @@ public abstract partial class WaitHandle
         [MethodImpl(MethodImplOptions.InternalCall)]
         private static extern int WaitOneCore(IntPtr waitHandle, int millisecondsTimeout);
 
-        internal static unsafe int WaitMultipleIgnoringSyncContext(Span<IntPtr> waitHandles, bool waitAll, int millisecondsTimeout)
+        private static unsafe int WaitMultipleIgnoringSyncContextCore(Span<IntPtr> waitHandles, bool waitAll, int millisecondsTimeout)
         {
             fixed (IntPtr* pWaitHandles = &MemoryMarshal.GetReference(waitHandles))
             {

diff --git a/src/coreclr/gc/env/etmdummy.h b/src/coreclr/gc/env/etmdummy.h
@@ -417,3 +417,5 @@
 #define FireEtwAppDomainAssemblyResolveHandlerInvoked(ClrInstanceId, assemblyName, handlerName, resultAssemblyName, resultAssemblyPath) 0
 #define FireEtwAssemblyLoadFromResolveHandlerInvoked(ClrInstanceId, assemblyName, isTrackedAssembly, requestingAssemblyPath, requestedAssemblyPath) 0
 #define FireEtwEventSource(eventID, eventName, eventSourceName, payload) 0
+#define FireEtwWaitHandleWaitStart(WaitSource, AssociatedObjectID, ClrInstanceID) 0
+#define FireEtwWaitHandleWaitStop(ClrInstanceID) 0
diff --git a/src/coreclr/inc/eventtracebase.h b/src/coreclr/inc/eventtracebase.h
@@ -1153,6 +1153,19 @@ namespace ETW
             } ContentionFlags;
         } ContentionStructs;
     };
+
+    class WaitHandleLog
+    {
+    public:
+        typedef union _WaitHandleStructs
+        {
+            typedef  enum _WaitSource {
+                Unknown=0,
+                MonitorWait=1
+            } WaitSource;
+        } WaitHandleStructs;
+    };
+
     // Class to wrap all Interop logic for ETW
     class InteropLog
     {

diff --git a/src/coreclr/nativeaot/Runtime/disabledruntimeeventinternal.cpp b/src/coreclr/nativeaot/Runtime/disabledruntimeeventinternal.cpp
@@ -84,4 +84,12 @@ EXTERN_C NATIVEAOT_API void __cdecl NativeRuntimeEventSource_LogExceptionThrown(
 {
 }
 
+EXTERN_C NATIVEAOT_API void __cdecl NativeRuntimeEventSource_LogWaitHandleWaitStart(uint8_t WaitSource, intptr_t AssociatedObjectID, uint16_t ClrInstanceID)
+{
+}
+
+EXTERN_C NATIVEAOT_API void __cdecl NativeRuntimeEventSource_LogWaitHandleWaitStop(uint16_t ClrInstanceID)
+{
+}
+
 #endif // FEATURE_PERFTRACING
diff --git a/src/coreclr/nativeaot/Runtime/eventpipe/gen-eventing-event-inc.lst b/src/coreclr/nativeaot/Runtime/eventpipe/gen-eventing-event-inc.lst
@@ -110,3 +110,5 @@ ThreadPoolWorkerThreadStop
 ThreadPoolWorkerThreadWait
 ThreadPoolWorkingThreadCount
 ThreadRunning
+WaitHandleWaitStart
+WaitHandleWaitStop
diff --git a/src/coreclr/nativeaot/Runtime/runtimeeventinternal.cpp b/src/coreclr/nativeaot/Runtime/runtimeeventinternal.cpp
@@ -100,4 +100,14 @@ EXTERN_C NATIVEAOT_API void __cdecl NativeRuntimeEventSource_LogExceptionThrown(
         GetClrInstanceId());
 }
 
+EXTERN_C NATIVEAOT_API void __cdecl NativeRuntimeEventSource_LogWaitHandleWaitStart(uint8_t WaitSource, intptr_t AssociatedObjectID, uint16_t ClrInstanceID)
+{
+    FireEtwWaitHandleWaitStart(WaitSource, reinterpret_cast<const void*>(AssociatedObjectID), ClrInstanceID);
+}
+
+EXTERN_C NATIVEAOT_API void __cdecl NativeRuntimeEventSource_LogWaitHandleWaitStop(uint16_t ClrInstanceID)
+{
+    FireEtwWaitHandleWaitStop(ClrInstanceID);
+}
+
 #endif // FEATURE_PERFTRACING
diff --git a/...c/System/Diagnostics/Eventing/NativeRuntimeEventSource.Threading.NativeSinks.NativeAot.cs b/...c/System/Diagnostics/Eventing/NativeRuntimeEventSource.Threading.NativeSinks.NativeAot.cs
@@ -22,6 +22,7 @@ public static partial class Keywords
             public const EventKeywords ContentionKeyword = (EventKeywords)0x4000;
             public const EventKeywords ThreadingKeyword = (EventKeywords)0x10000;
             public const EventKeywords ThreadTransferKeyword = (EventKeywords)0x80000000;
+            public const EventKeywords WaitHandleKeyword = (EventKeywords)0x40000000000;
         }
 
         [NonEvent]
@@ -132,5 +133,20 @@ internal static void LogThreadPoolIOPack(
         {
             RuntimeImports.NativeRuntimeEventSource_LogThreadPoolIOPack(NativeOverlapped, Overlapped, ClrInstanceID);
         }
+
+        [NonEvent]
+        internal static void LogWaitHandleWaitStart(
+            WaitHandleWaitSourceMap WaitSource,
+            IntPtr AssociatedObjectID,
+            ushort ClrInstanceID)
+        {
+            RuntimeImports.NativeRuntimeEventSource_LogWaitHandleWaitStart((byte)WaitSource, AssociatedObjectID, ClrInstanceID);
+        }
+
+        [NonEvent]
+        internal static void LogWaitHandleWaitStop(ushort ClrInstanceID)
+        {
+            RuntimeImports.NativeRuntimeEventSource_LogWaitHandleWaitStop(ClrInstanceID);
+        }
     }
 }
diff --git a/src/coreclr/nativeaot/System.Private.CoreLib/src/System/Runtime/RuntimeImports.cs b/src/coreclr/nativeaot/System.Private.CoreLib/src/System/Runtime/RuntimeImports.cs
@@ -826,6 +826,17 @@ internal static partial void NativeRuntimeEventSource_LogThreadPoolIOPack(
         [LibraryImport(RuntimeLibrary)]
         [UnmanagedCallConv(CallConvs = new Type[] { typeof(CallConvCdecl) })]
         internal static unsafe partial void NativeRuntimeEventSource_LogExceptionThrown(char* exceptionTypeName, char* exceptionMessage, IntPtr faultingIP, long hresult);
+
+        [LibraryImport(RuntimeLibrary)]
+        [UnmanagedCallConv(CallConvs = new Type[] { typeof(CallConvCdecl) })]
+        internal static partial void NativeRuntimeEventSource_LogWaitHandleWaitStart(
+            byte WaitSource,
+            IntPtr AssociatedObjectID,
+            ushort ClrInstanceID);
+
+        [LibraryImport(RuntimeLibrary)]
+        [UnmanagedCallConv(CallConvs = new Type[] { typeof(CallConvCdecl) })]
+        internal static partial void NativeRuntimeEventSource_LogWaitHandleWaitStop(ushort ClrInstanceID);
 #endif // FEATURE_PERFTRACING
 
         //

diff --git a/src/coreclr/nativeaot/System.Private.CoreLib/src/System/Threading/Condition.cs b/src/coreclr/nativeaot/System.Private.CoreLib/src/System/Threading/Condition.cs
@@ -3,8 +3,8 @@
 
 #pragma warning disable 0420 //passing volatile fields by ref
 
-
 using System.Diagnostics;
+using System.Diagnostics.Tracing;
 
 namespace System.Threading
 {
@@ -97,7 +97,7 @@ public Condition(Lock @lock)
 
         public bool Wait(TimeSpan timeout) => Wait(WaitHandle.ToTimeoutMilliseconds(timeout));
 
-        public unsafe bool Wait(int millisecondsTimeout)
+        public unsafe bool Wait(int millisecondsTimeout, object? associatedObjectForMonitorWait = null)
         {
             ArgumentOutOfRangeException.ThrowIfLessThan(millisecondsTimeout, -1);
 
@@ -111,7 +111,13 @@ public unsafe bool Wait(int millisecondsTimeout)
             bool success = false;
             try
             {
-                success = waiter.ev.WaitOne(millisecondsTimeout);
+                success =
+                    waiter.ev.WaitOneNoCheck(
+                        millisecondsTimeout,
+                        associatedObjectForMonitorWait,
+                        associatedObjectForMonitorWait != null
+                            ? NativeRuntimeEventSource.WaitHandleWaitSourceMap.MonitorWait
+                            : NativeRuntimeEventSource.WaitHandleWaitSourceMap.Unknown);
             }
             finally
             {

diff --git a/src/coreclr/nativeaot/System.Private.CoreLib/src/System/Threading/Monitor.NativeAot.cs b/src/coreclr/nativeaot/System.Private.CoreLib/src/System/Threading/Monitor.NativeAot.cs
@@ -146,7 +146,7 @@ public static bool IsEntered(object obj)
         [UnsupportedOSPlatform("browser")]
         public static bool Wait(object obj, int millisecondsTimeout)
         {
-            return GetCondition(obj).Wait(millisecondsTimeout);
+            return GetCondition(obj).Wait(millisecondsTimeout, obj);
         }
 
         public static void Pulse(object obj)

diff --git a/src/coreclr/scripts/genRuntimeEventSources.py b/src/coreclr/scripts/genRuntimeEventSources.py
@@ -85,11 +85,9 @@ def getManifestsToGenerate(runtimeFlavor):
 
 def generateEvent(eventNode, providerNode, outputFile, stringTable):
 
-    # ThreadPool and Contention events are defined manually in NativeRuntimeEventSource.Threading.cs
+    # Some threading events are defined manually in NativeRuntimeEventSource.Threading.cs
     symbol = eventNode.getAttribute("symbol")
-    if "ThreadPool" in symbol:
-        return
-    if "Contention" in symbol:
+    if any(s in symbol for s in ["ThreadPool", "Contention", "WaitHandle"]):
         return
 
     evtLevel = eventNode.getAttribute("level")[4:]

diff --git a/src/coreclr/vm/ClrEtwAll.man b/src/coreclr/vm/ClrEtwAll.man
@@ -89,6 +89,8 @@
                              message="$(string.RuntimePublisher.JitInstrumentationDataKeywordMessage)" symbol="CLR_JITINSTRUMENTEDDATA_KEYWORD" />
                     <keyword name="ProfilerKeyword" mask="0x20000000000"
                              message="$(string.RuntimePublisher.ProfilerKeywordMessage)" symbol="CLR_PROFILER_KEYWORD" />
+                    <keyword name="WaitHandleKeyword" mask="0x40000000000"
+                             message="$(string.RuntimePublisher.WaitHandleKeywordMessage)" symbol="CLR_WAITHANDLE_KEYWORD"/>
                 </keywords>
                 <!--Tasks-->
                 <tasks>
@@ -453,7 +455,13 @@
                         <opcodes>
                         </opcodes>
                     </task>
-                <!--Next available ID is 39-->
+                    <task name="WaitHandleWait" symbol="CLR_WAITHANDLEWAIT_TASK"
+                          value="39" eventGUID="{E90049D8-8AB8-4799-B072-EEF41265BCA4}"
+                          message="$(string.RuntimePublisher.WaitHandleWaitTaskMessage)">
+                        <opcodes>
+                        </opcodes>
+                    </task>
+                <!--Next available ID is 40-->
                 </tasks>
                 <!--Maps-->
                 <maps>
@@ -504,6 +512,10 @@
                         <map value="0x0" message="$(string.RuntimePublisher.Contention.ManagedMapMessage)"/>
                         <map value="0x1" message="$(string.RuntimePublisher.Contention.NativeMapMessage)"/>
                     </valueMap>
+                    <valueMap name="WaitHandleWaitSourceMap">
+                        <map value="0x0" message="$(string.RuntimePublisher.WaitHandleWaitSource.UnknownMapMessage)"/>
+                        <map value="0x1" message="$(string.RuntimePublisher.WaitHandleWaitSource.MonitorWaitMapMessage)"/>
+                    </valueMap>
                     <valueMap name="TailCallTypeMap">
                         <map value="0x0" message="$(string.RuntimePublisher.TailCallType.OptimizedMapMessage)"/>
                         <map value="0x1" message="$(string.RuntimePublisher.TailCallType.RecursiveMapMessage)"/>
@@ -1775,6 +1787,30 @@
                         </UserData>
                     </template>
 
+                    <template tid="WaitHandleWaitStart">
+                        <data name="WaitSource" inType="win:UInt8" map="WaitHandleWaitSourceMap" />
+                        <data name="AssociatedObjectID" inType="win:Pointer" />
+                        <data name="ClrInstanceID" inType="win:UInt16" />
+
+                        <UserData>
+                            <WaitHandleWaitStart xmlns="myNs">
+                                <WaitSource> %1 </WaitSource>
+                                <AssociatedObjectID> %2 </AssociatedObjectID>
+                                <ClrInstanceID> %3 </ClrInstanceID>
+                            </WaitHandleWaitStart>
+                        </UserData>
+                    </template>
+
+                    <template tid="WaitHandleWaitStop">
+                        <data name="ClrInstanceID" inType="win:UInt16" />
+
+                        <UserData>
+                            <WaitHandleWaitStop xmlns="myNs">
+                                <ClrInstanceID> %1 </ClrInstanceID>
+                            </WaitHandleWaitStop>
+                        </UserData>
+                    </template>
+
                     <template tid="DomainModuleLoadUnload">
                         <data name="ModuleID" inType="win:UInt64" outType="win:HexInt64" />
                         <data name="AssemblyID" inType="win:UInt64" outType="win:HexInt64" />
@@ -3696,7 +3732,6 @@
                            task="Contention"
                            symbol="ContentionLockCreated" message="$(string.RuntimePublisher.ContentionLockCreatedEventMessage)"/>
 
-
                     <!-- CLR Stack events -->
                     <event value="82" version="0" level="win:LogAlways"  template="ClrStackWalk"
                            keywords ="StackKeyword"  opcode="CLRStackWalk"
@@ -4211,6 +4246,17 @@
                            keywords ="PerfTrackKeyword" opcode="ExecutionCheckpoint" task="ExecutionCheckpoint" symbol="ExecutionCheckpoint"
                            message="$(string.RuntimePublisher.ExecutionCheckpointEventMessage)"/>
 
+                    <!-- Wait Handle events -->
+                    <event value="301" version="0" level="win:Verbose" template="WaitHandleWaitStart"
+                           keywords="WaitHandleKeyword" opcode="win:Start"
+                           task="WaitHandleWait"
+                           symbol="WaitHandleWaitStart" message="$(string.RuntimePublisher.WaitHandleWaitStartEventMessage)"/>
+
+                    <event value="302" version="0" level="win:Verbose" template="WaitHandleWaitStop"
+                           keywords="WaitHandleKeyword" opcode="win:Stop"
+                           task="WaitHandleWait"
+                           symbol="WaitHandleWaitStop" message="$(string.RuntimePublisher.WaitHandleWaitStopEventMessage)"/>
+
                 </events>
             </provider>
 
@@ -8568,6 +8614,8 @@
                 <string id="RuntimePublisher.TieredCompilationBackgroundJitStartEventMessage" value="ClrInstanceID=%1;%nPendingMethodCount=%2" />
                 <string id="RuntimePublisher.TieredCompilationBackgroundJitStopEventMessage" value="ClrInstanceID=%1;%nPendingMethodCount=%2;%nJittedMethodCount=%3" />
                 <string id="RuntimePublisher.ExecutionCheckpointEventMessage" value="ClrInstanceID=%1;Checkpoint=%2;Timestamp=%3"/>
+                <string id="RuntimePublisher.WaitHandleWaitStartEventMessage" value="WaitSource=%1;%nAssociatedObjectID=%2;%nClrInstanceID=%3"/>
+                <string id="RuntimePublisher.WaitHandleWaitStopEventMessage" value="ClrInstanceID=%1"/>
 
                 <string id="RundownPublisher.MethodDCStartEventMessage" value="MethodID=%1;%nModuleID=%2;%nMethodStartAddress=%3;%nMethodSize=%4;%nMethodToken=%5;%nMethodFlags=%6" />
                 <string id="RundownPublisher.MethodDCStart_V1EventMessage" value="MethodID=%1;%nModuleID=%2;%nMethodStartAddress=%3;%nMethodSize=%4;%nMethodToken=%5;%nMethodFlags=%6;%nClrInstanceID=%7" />
@@ -8742,6 +8790,7 @@
                 <string id="RuntimePublisher.ExecutionCheckpointTaskMessage" value="ExecutionCheckpoint" />
                 <string id="RuntimePublisher.ProfilerTaskMessage" value="Profiler" />
                 <string id="RuntimePublisher.YieldProcessorMeasurementTaskMessage" value="YieldProcessorMeasurement" />
+                <string id="RuntimePublisher.WaitHandleWaitTaskMessage" value="WaitHandleWait" />
 
                 <string id="RundownPublisher.GCTaskMessage" value="GC" />
                 <string id="RundownPublisher.EEStartupTaskMessage" value="Runtime" />
@@ -8934,6 +8983,8 @@
                 <string id="RuntimePublisher.ResolutionAttempted.IncompatibleVersion" value="IncompatibleVersion" />
                 <string id="RuntimePublisher.ResolutionAttempted.Failure" value="Failure" />
                 <string id="RuntimePublisher.ResolutionAttempted.Exception" value="Exception" />
+                <string id="RuntimePublisher.WaitHandleWaitSource.UnknownMapMessage" value="Unknown" />
+                <string id="RuntimePublisher.WaitHandleWaitSource.MonitorWaitMapMessage" value="MonitorWait" />
 
                 <string id="RundownPublisher.AppDomain.ExecutableMapMessage" value="Executable" />
                 <string id="RundownPublisher.AppDomain.SharedMapMessage" value="Shared" />
@@ -9103,6 +9154,7 @@
                 <string id="RundownPublisher.PerfTrackRundownKeywordMessage" value="PerfTrack" />
                 <string id="RundownPublisher.StackKeywordMessage" value="Stack" />
                 <string id="RundownPublisher.CompilationKeywordMessage" value="Compilation" />
+                <string id="RuntimePublisher.WaitHandleKeywordMessage" value="WaitHandle" />
 
                 <string id="PrivatePublisher.GCPrivateKeywordMessage" value="GC" />
                 <string id="PrivatePublisher.StartupKeywordMessage" value="Startup" />

diff --git a/src/coreclr/vm/ClrEtwAllMeta.lst b/src/coreclr/vm/ClrEtwAllMeta.lst
@@ -192,6 +192,13 @@ nostack:Contention:::ContentionStop_V1
 nomac:Contention:::ContentionStop_V1
 nomac:Contention:::ContentionLockCreated
 
+###################
+# WaitHandle events
+###################
+nomac:WaitHandle:::WaitHandleWaitStart
+nostack:WaitHandle:::WaitHandleWaitStop
+nomac:WaitHandle:::WaitHandleWaitStop
+
 ##################
 # StackWalk events
 ##################

diff --git a/src/coreclr/vm/syncblk.cpp b/src/coreclr/vm/syncblk.cpp
@@ -2850,6 +2850,7 @@ BOOL SyncBlock::Wait(INT32 timeOut)
     PendingSync   syncState(walk);
 
     OBJECTREF     obj = m_Monitor.GetOwningObject();
+    syncState.m_Object = OBJECTREFToObject(obj);
 
     m_Monitor.IncrementTransientPrecious();