Add EventSource event for WaitHandle waits (dotnet#94737)

Add start/stop events for WaitHandle waits

Context: dotnet#94264

src/coreclr/gc/env/etmdummy.h

@@ -414,3 +414,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

src/coreclr/inc/eventtracebase.h

@@ -1145,6 +1145,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
     {

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>
@@ -446,7 +448,13 @@
                         <opcodes>
                         </opcodes>
                     </task>
-                <!--Next available ID is 38-->
+                    <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>
@@ -497,6 +505,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)"/>
@@ -1730,6 +1742,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" />
@@ -4106,6 +4142,18 @@
                     <event value="300" version="0" level="win:Informational"  template="ExecutionCheckpoint"
                            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>
 
@@ -8389,6 +8437,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" />
@@ -8559,6 +8609,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" />
@@ -8747,6 +8798,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" />
@@ -8913,6 +8966,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" />

src/coreclr/vm/ClrEtwAllMeta.lst

@@ -190,6 +190,13 @@ nomac:Contention:::ContentionStop
 nostack:Contention:::ContentionStop_V1
 nomac:Contention:::ContentionStop_V1
 
+###################
+# WaitHandle events
+###################
+nomac:WaitHandle:::WaitHandleWaitStart
+nostack:WaitHandle:::WaitHandleWaitStop
+nomac:WaitHandle:::WaitHandleWaitStop
+
 ##################
 # StackWalk events
 ##################

src/coreclr/vm/syncblk.cpp

@@ -2843,6 +2843,7 @@ BOOL SyncBlock::Wait(INT32 timeOut)
     PendingSync   syncState(walk);
 
     OBJECTREF     obj = m_Monitor.GetOwningObject();
+    syncState.m_Object = OBJECTREFToObject(obj);
 
     m_Monitor.IncrementTransientPrecious();
 

src/coreclr/vm/threads.cpp

@@ -3229,6 +3229,7 @@ DWORD Thread::DoAppropriateWait(int countHandles, HANDLE *handles, BOOL waitAll,
         BOOL waitAll;
         DWORD millis;
         WaitMode mode;
+        void *associatedObjectForMonitorWait;
         DWORD dwRet;
     } param;
     param.pThis = this;
@@ -3237,10 +3238,11 @@ DWORD Thread::DoAppropriateWait(int countHandles, HANDLE *handles, BOOL waitAll,
     param.waitAll = waitAll;
     param.millis = millis;
     param.mode = mode;
+    param.associatedObjectForMonitorWait = syncState != NULL ? syncState->m_Object : NULL;
     param.dwRet = (DWORD) -1;
 
     EE_TRY_FOR_FINALLY(Param *, pParam, &param) {
-        pParam->dwRet = pParam->pThis->DoAppropriateWaitWorker(pParam->countHandles, pParam->handles, pParam->waitAll, pParam->millis, pParam->mode);
+        pParam->dwRet = pParam->pThis->DoAppropriateWaitWorker(pParam->countHandles, pParam->handles, pParam->waitAll, pParam->millis, pParam->mode, pParam->associatedObjectForMonitorWait);
     }
     EE_FINALLY {
         if (syncState) {
@@ -3443,7 +3445,7 @@ void UnMarkOSAlertableWait()
 // style of Wait.
 //--------------------------------------------------------------------
 DWORD Thread::DoAppropriateWaitWorker(int countHandles, HANDLE *handles, BOOL waitAll,
-                                      DWORD millis, WaitMode mode)
+                                      DWORD millis, WaitMode mode, void *associatedObjectForMonitorWait)
 {
     CONTRACTL {
         THROWS;
@@ -3516,14 +3518,63 @@ DWORD Thread::DoAppropriateWaitWorker(int countHandles, HANDLE *handles, BOOL wa
 
     ThreadStateHolder tsh(alertable, TS_Interruptible | TS_Interrupted);
 
+    bool sendWaitEvents =
+        millis != 0 &&
+        (mode & WaitMode_Alertable) != 0 &&
+        ETW_TRACING_CATEGORY_ENABLED(
+            MICROSOFT_WINDOWS_DOTNETRUNTIME_PROVIDER_DOTNET_Context,
+            TRACE_LEVEL_VERBOSE,
+            CLR_WAITHANDLE_KEYWORD);
+
+    // Monitor.Wait is typically a blocking wait. For other waits, when sending the wait events try a nonblocking wait first
+    // such that the events sent are more likely to represent blocking waits.
+    bool tryNonblockingWaitFirst = sendWaitEvents && associatedObjectForMonitorWait == NULL;
+    if (tryNonblockingWaitFirst)
+    {
+        ret = DoAppropriateAptStateWait(countHandles, handles, waitAll, 0 /* timeout */, mode);
+        if (ret == WAIT_TIMEOUT)
+        {
+            // Do a full wait and send the wait events
+            tryNonblockingWaitFirst = false;
+        }
+        else if (ret != WAIT_IO_COMPLETION && ret != WAIT_FAILED)
+        {
+            // The nonblocking wait was successful, don't send the wait events
+            sendWaitEvents = false;
+        }
+    }
+
+    if (sendWaitEvents)
+    {
+        if (associatedObjectForMonitorWait != NULL)
+        {
+            FireEtwWaitHandleWaitStart(
+                ETW::WaitHandleLog::WaitHandleStructs::MonitorWait,
+                associatedObjectForMonitorWait,
+                GetClrInstanceId());
+        }
+        else
+        {
+            FireEtwWaitHandleWaitStart(ETW::WaitHandleLog::WaitHandleStructs::Unknown, NULL, GetClrInstanceId());
+        }
+    }
+
     ULONGLONG dwStart = 0, dwEnd;
 retry:
     if (millis != INFINITE)
     {
         dwStart = CLRGetTickCount64();
     }
 
-    ret = DoAppropriateAptStateWait(countHandles, handles, waitAll, millis, mode);
+    if (tryNonblockingWaitFirst)
+    {
+        // We have a final wait result from the nonblocking wait above
+        tryNonblockingWaitFirst = false;
+    }
+    else
+    {
+        ret = DoAppropriateAptStateWait(countHandles, handles, waitAll, millis, mode);
+    }
 
     if (ret == WAIT_IO_COMPLETION)
     {
@@ -3539,7 +3590,7 @@ DWORD Thread::DoAppropriateWaitWorker(int countHandles, HANDLE *handles, BOOL wa
         if (millis != INFINITE)
         {
             dwEnd = CLRGetTickCount64();
-            if (dwEnd >= dwStart + millis)
+            if (dwEnd - dwStart >= millis)
             {
                 ret = WAIT_TIMEOUT;
                 goto WaitCompleted;
@@ -3624,7 +3675,7 @@ DWORD Thread::DoAppropriateWaitWorker(int countHandles, HANDLE *handles, BOOL wa
             dwEnd = CLRGetTickCount64();
             if (millis != INFINITE)
             {
-                if (dwEnd >= dwStart + millis)
+                if (dwEnd - dwStart >= millis)
                 {
                     ret = WAIT_TIMEOUT;
                     goto WaitCompleted;
@@ -3670,6 +3721,11 @@ DWORD Thread::DoAppropriateWaitWorker(int countHandles, HANDLE *handles, BOOL wa
 
     _ASSERTE((ret != WAIT_TIMEOUT) || (millis != INFINITE));
 
+    if (sendWaitEvents)
+    {
+        FireEtwWaitHandleWaitStop(GetClrInstanceId());
+    }
+
     return ret;
 }
 

src/coreclr/vm/threads.h

@@ -2942,7 +2942,7 @@ class Thread
 private:
     void           DoAppropriateWaitWorkerAlertableHelper(WaitMode mode);
     DWORD          DoAppropriateWaitWorker(int countHandles, HANDLE *handles, BOOL waitAll,
-                                           DWORD millis, WaitMode mode);
+                                           DWORD millis, WaitMode mode, void *associatedObjectForMonitorWait);
     DWORD          DoAppropriateWaitWorker(AppropriateWaitFunc func, void *args,
                                            DWORD millis, WaitMode mode);
     DWORD          DoSignalAndWaitWorker(HANDLE* pHandles, DWORD millis,BOOL alertable);
@@ -5247,6 +5247,7 @@ inline void Thread::DecrementTraceCallCount()
 // state to be correct.  So we carry it around in case we need to restore it.
 struct PendingSync
 {
+    void*           m_Object;
     LONG            m_EnterCount;
     WaitEventLink  *m_WaitEventLink;
 #ifdef _DEBUG

src/libraries/Common/tests/System/Diagnostics/Tracing/TestEventListener.cs

@@ -23,15 +23,20 @@ private class Settings
         private Action<EventWrittenEventArgs> _eventWritten;
         private readonly List<EventSource> _eventSourceList = new List<EventSource>();
 
-        public TestEventListener(string targetSourceName, EventLevel level, double? eventCounterInterval = null)
+        public TestEventListener(double? eventCounterInterval = null)
         {
             _eventCounterInterval = eventCounterInterval;
+        }
+
+        public TestEventListener(string targetSourceName, EventLevel level, double? eventCounterInterval = null)
+            : this(eventCounterInterval)
+        {
             AddSource(targetSourceName, level);
         }
 
         public TestEventListener(Guid targetSourceGuid, EventLevel level, double? eventCounterInterval = null)
+            : this(eventCounterInterval)
         {
-            _eventCounterInterval = eventCounterInterval;
             AddSource(targetSourceGuid, level);
         }