Add new version of the ContentionStart event (#72627)

* Add new version of the ContentionStart event and a LockCreated event The new ContentionStart includes a lock ID, associated object ID, and the holding thread ID. The LockCreated event includes a lock ID and associated object ID. Co-authored-by: Koundinya Veluri <kouvel@microsoft.com>
dotnet · Oct 20, 2022 · 69a1da6 · 69a1da6
1 parent ddebaf5
commit 69a1da6
Show file tree

Hide file tree

Showing 6 changed files with 94 additions and 17 deletions.
diff --git a/src/coreclr/gc/env/etmdummy.h b/src/coreclr/gc/env/etmdummy.h
@@ -98,7 +98,9 @@
 #define FireEtwExceptionThrownStop() 0
 #define FireEtwContention() 0
 #define FireEtwContentionStart_V1(ContentionFlags, ClrInstanceID) 0
+#define FireEtwContentionStart_V2(ContentionFlags, ClrInstanceID, LockID, AssociatedObjectID, LockOwnerThreadID) 0
 #define FireEtwContentionStop(ContentionFlags, ClrInstanceID) 0
+#define FireEtwLockCreated(LockID, AssociatedObjectID, ClrInstanceID) 0
 #define FireEtwCLRStackWalk(ClrInstanceID, Reserved1, Reserved2, FrameCount, Stack) 0
 #define FireEtwAppDomainMemAllocated(AppDomainID, Allocated, ClrInstanceID) 0
 #define FireEtwAppDomainMemSurvived(AppDomainID, Survived, ProcessSurvived, ClrInstanceID) 0

diff --git a/src/coreclr/vm/ClrEtwAll.man b/src/coreclr/vm/ClrEtwAll.man
@@ -1744,6 +1744,23 @@
                         </UserData>
                     </template>
 
+                    <template tid="ContentionStart_V2">
+                        <data name="ContentionFlags" inType="win:UInt8" map="ContentionFlagsMap" />
+                        <data name="ClrInstanceID" inType="win:UInt16" />
+                        <data name="LockID" inType="win:Pointer" />
+                        <data name="AssociatedObjectID" inType="win:Pointer" />
+                        <data name="LockOwnerThreadID" inType="win:UInt64" />
+                        <UserData>
+                            <Contention xmlns="myNs">
+                                <ContentionFlags> %1 </ContentionFlags>
+                                <ClrInstanceID> %2 </ClrInstanceID>
+                                <LockID> %3 </LockID>
+                                <AssociatedObjectID> %4 </AssociatedObjectID>
+                                <LockOwnerThreadID> %5 </LockOwnerThreadID>
+                            </Contention>
+                        </UserData>
+                    </template>
+
                     <template tid="ContentionStop_V1">
                         <data name="ContentionFlags" inType="win:UInt8" map="ContentionFlagsMap" />
                         <data name="ClrInstanceID" inType="win:UInt16" />
@@ -3096,6 +3113,20 @@
                         </Settings>
                       </UserData>
                     </template>
+
+                    <template tid="LockCreated">
+                        <data name="LockID" inType="win:Pointer" />
+                        <data name="AssociatedObjectID" inType="win:Pointer" />
+                        <data name="ClrInstanceID" inType="win:UInt16" />
+                        <UserData>
+                            <LockCreated xmlns="myNs">
+                                <LockID> %1 </LockID>
+                                <AssociatedObjectID> %2 </AssociatedObjectID>
+                                <ClrInstanceID> %3 </ClrInstanceID>
+                            </LockCreated>
+                        </UserData>
+                    </template>
+
                 </templates>
 
                 <events>
@@ -3644,6 +3675,11 @@
                            task="Contention"
                            symbol="ContentionStart_V1" message="$(string.RuntimePublisher.ContentionStart_V1EventMessage)"/>
 
+                    <event value="81" version="2" level="win:Informational"  template="ContentionStart_V2"
+                           keywords ="ContentionKeyword"  opcode="win:Start"
+                           task="Contention"
+                           symbol="ContentionStart_V2" message="$(string.RuntimePublisher.ContentionStart_V2EventMessage)"/>
+
                     <event value="91" version="0" level="win:Informational"  template="Contention"
                            keywords ="ContentionKeyword"  opcode="win:Stop"
                            task="Contention"
@@ -3654,6 +3690,12 @@
                            task="Contention"
                            symbol="ContentionStop_V1" message="$(string.RuntimePublisher.ContentionStop_V1EventMessage)"/>
 
+                    <event value="90" version="0" level="win:Informational"  template="LockCreated"
+                           keywords ="ContentionKeyword"  opcode="win:Info"
+                           task="Contention"
+                           symbol="LockCreated" message="$(string.RuntimePublisher.LockCreatedEventMessage)"/>
+
+
                     <!-- CLR Stack events -->
                     <event value="82" version="0" level="win:LogAlways"  template="ClrStackWalk"
                            keywords ="StackKeyword"  opcode="CLRStackWalk"
@@ -8436,8 +8478,10 @@
                 <string id="RuntimePublisher.ExceptionExceptionHandlingNoneEventMessage" value="NONE" />
                 <string id="RuntimePublisher.ContentionStartEventMessage" value="NONE" />
                 <string id="RuntimePublisher.ContentionStart_V1EventMessage" value="ContentionFlags=%1;%nClrInstanceID=%2"/>
+                <string id="RuntimePublisher.ContentionStart_V2EventMessage" value="ContentionFlags=%1;%nClrInstanceID=%2;%nLockID=%3;%nAssociatedObjectID=%4;%nLockOwnerThreadID=%5"/>
                 <string id="RuntimePublisher.ContentionStopEventMessage" value="ContentionFlags=%1;%nClrInstanceID=%2"/>
                 <string id="RuntimePublisher.ContentionStop_V1EventMessage" value="ContentionFlags=%1;%nClrInstanceID=%2;DurationNs=%3"/>
+                <string id="RuntimePublisher.LockCreatedEventMessage" value="LockID=%1;%nAssociatedObjectID=%2;%nClrInstanceID=%3"/>
                 <string id="RuntimePublisher.DCStartCompleteEventMessage" value="NONE" />
                 <string id="RuntimePublisher.DCEndCompleteEventMessage" value="NONE" />
                 <string id="RuntimePublisher.MethodDCStartEventMessage" value="MethodID=%1;%nModuleID=%2;%nMethodStartAddress=%3;%nMethodSize=%4;%nMethodToken=%5;%nMethodFlags=%6" />

diff --git a/src/coreclr/vm/ClrEtwAllMeta.lst b/src/coreclr/vm/ClrEtwAllMeta.lst
@@ -185,10 +185,12 @@ noclrinstanceid:Exception:::ExceptionThrown
 nomac:Contention:::Contention
 noclrinstanceid:Contention:::Contention
 nomac:Contention:::ContentionStart_V1
+nomac:Contention:::ContentionStart_V2
 nostack:Contention:::ContentionStop
 nomac:Contention:::ContentionStop
 nostack:Contention:::ContentionStop_V1
 nomac:Contention:::ContentionStop_V1
+nomac:Contention:::LockCreated
 
 ##################
 # StackWalk events
@@ -698,4 +700,4 @@ nostack:MonoProfiler:::MonoProfilerThreadStopped
 nostack:MonoProfiler:::MonoProfilerThreadExited
 nostack:MonoProfiler:::MonoProfilerThreadName
 nostack:MonoProfiler:::MonoProfilerJitDoneVerbose
-nostack:MonoProfiler:::MonoProfilerGCHeapDumpVTableClassReference
+nostack:MonoProfiler:::MonoProfilerGCHeapDumpVTableClassReference
diff --git a/src/coreclr/vm/syncblk.cpp b/src/coreclr/vm/syncblk.cpp
@@ -2202,13 +2202,20 @@ SyncBlock *ObjHeader::GetSyncBlock()
                             _ASSERTE(lockThreadId != 0);
 
                             Thread *pThread = g_pThinLockThreadIdDispenser->IdToThreadWithValidation(lockThreadId);
+                            SIZE_T osThreadId;
 
                             if (pThread == NULL)
                             {
                                 // The lock is orphaned.
                                 pThread = (Thread*) -1;
+                                osThreadId = (SIZE_T)-1;
                             }
-                            syncBlock->InitState(recursionLevel + 1, pThread);
+                            else
+                            {
+                                osThreadId = pThread->GetOSThreadId64();
+                            }
+
+                            syncBlock->InitState(recursionLevel + 1, pThread, osThreadId);
                         }
                     }
                     else if ((bits & BIT_SBLK_IS_HASHCODE) != 0)
@@ -2237,8 +2244,8 @@ SyncBlock *ObjHeader::GetSyncBlock()
 
                 LEAVE_SPIN_LOCK(this);
             }
-            // SyncBlockCache::LockHolder goes out of scope here
         }
+        // SyncBlockCache::LockHolder goes out of scope here
     }
 
     RETURN syncBlock;
@@ -2372,6 +2379,7 @@ void AwareLock::Enter()
         {
             // We get here if we successfully acquired the mutex.
             m_HoldingThread = pCurThread;
+            m_HoldingOSThreadId = pCurThread->GetOSThreadId64();
             m_Recursion = 1;
 
 #if defined(_DEBUG) && defined(TRACK_SYNC)
@@ -2434,6 +2442,7 @@ BOOL AwareLock::TryEnter(INT32 timeOut)
         {
             // We get here if we successfully acquired the mutex.
             m_HoldingThread = pCurThread;
+            m_HoldingOSThreadId = pCurThread->GetOSThreadId64();
             m_Recursion = 1;
 
 #if defined(_DEBUG) && defined(TRACK_SYNC)
@@ -2541,22 +2550,32 @@ BOOL AwareLock::EnterEpilogHelper(Thread* pCurThread, INT32 timeOut)
     // the object associated with this lock.
     _ASSERTE(pCurThread->PreemptiveGCDisabled());
 
-    BOOLEAN IsContentionKeywordEnabled = ETW_TRACING_CATEGORY_ENABLED(MICROSOFT_WINDOWS_DOTNETRUNTIME_PROVIDER_DOTNET_Context, TRACE_LEVEL_INFORMATION, CLR_CONTENTION_KEYWORD);
+    LogContention();
+    Thread::IncrementMonitorLockContentionCount(pCurThread);
+
+    OBJECTREF obj = GetOwningObject();
+
     LARGE_INTEGER startTicks = { {0} };
+    bool isContentionKeywordEnabled = ETW_TRACING_CATEGORY_ENABLED(MICROSOFT_WINDOWS_DOTNETRUNTIME_PROVIDER_DOTNET_Context, TRACE_LEVEL_INFORMATION, CLR_CONTENTION_KEYWORD);
 
-    if (IsContentionKeywordEnabled)
+    if (isContentionKeywordEnabled)
     {
         QueryPerformanceCounter(&startTicks);
 
+        if (InterlockedCompareExchangeT(&m_emittedLockCreatedEvent, 1, 0) == 0)
+        {
+            FireEtwLockCreated(this, OBJECTREFToObject(obj), GetClrInstanceId());
+        }
+
         // Fire a contention start event for a managed contention
-        FireEtwContentionStart_V1(ETW::ContentionLog::ContentionStructs::ManagedContention, GetClrInstanceId());
+        FireEtwContentionStart_V2(
+            ETW::ContentionLog::ContentionStructs::ManagedContention,
+            GetClrInstanceId(),
+            this,
+            OBJECTREFToObject(obj),
+            m_HoldingOSThreadId);
     }
 
-    LogContention();
-    Thread::IncrementMonitorLockContentionCount(pCurThread);
-
-    OBJECTREF obj = GetOwningObject();
-
     // We cannot allow the AwareLock to be cleaned up underneath us by the GC.
     IncrementTransientPrecious();
 
@@ -2684,7 +2703,7 @@ BOOL AwareLock::EnterEpilogHelper(Thread* pCurThread, INT32 timeOut)
     GCPROTECT_END();
     DecrementTransientPrecious();
 
-    if (IsContentionKeywordEnabled)
+    if (isContentionKeywordEnabled)
     {
         LARGE_INTEGER endTicks;
         QueryPerformanceCounter(&endTicks);
@@ -2702,6 +2721,7 @@ BOOL AwareLock::EnterEpilogHelper(Thread* pCurThread, INT32 timeOut)
     }
 
     m_HoldingThread = pCurThread;
+    m_HoldingOSThreadId = pCurThread->GetOSThreadId64();
     m_Recursion = 1;
 
 #if defined(_DEBUG) && defined(TRACK_SYNC)
@@ -2765,7 +2785,6 @@ BOOL AwareLock::OwnedByCurrentThread()
     return (GetThread() == m_HoldingThread);
 }
 
-
 // ***************************************************************************
 //
 //              SyncBlock class implementation

diff --git a/src/coreclr/vm/syncblk.h b/src/coreclr/vm/syncblk.h
@@ -436,6 +436,7 @@ class AwareLock
 
     ULONG           m_Recursion;
     PTR_Thread      m_HoldingThread;
+    SIZE_T          m_HoldingOSThreadId;
 
     LONG            m_TransientPrecious;
 
@@ -447,6 +448,7 @@ class AwareLock
     CLREvent        m_SemEvent;
 
     DWORD m_waiterStarvationStartTimeMs;
+    int m_emittedLockCreatedEvent;
 
     static const DWORD WaiterStarvationDurationMsBeforeStoppingPreemptingWaiters = 100;
 
@@ -457,9 +459,11 @@ class AwareLock
 // PreFAST has trouble with initializing a NULL PTR_Thread.
           m_HoldingThread(NULL),
 #endif // DACCESS_COMPILE
+          m_HoldingOSThreadId(0),
           m_TransientPrecious(0),
           m_dwSyncIndex(indx),
-          m_waiterStarvationStartTimeMs(0)
+          m_waiterStarvationStartTimeMs(0),
+          m_emittedLockCreatedEvent(0)
     {
         LIMITED_METHOD_CONTRACT;
     }
@@ -525,13 +529,14 @@ class AwareLock
     bool ShouldStopPreemptingWaiters() const;
 
 private: // friend access is required for this unsafe function
-    void InitializeToLockedWithNoWaiters(ULONG recursionLevel, PTR_Thread holdingThread)
+    void InitializeToLockedWithNoWaiters(ULONG recursionLevel, PTR_Thread holdingThread, SIZE_T holdingOSThreadId)
     {
         WRAPPER_NO_CONTRACT;
 
         m_lockState.InitializeToLockedWithNoWaiters();
         m_Recursion = recursionLevel;
         m_HoldingThread = holdingThread;
+        m_HoldingOSThreadId = holdingOSThreadId;
     }
 
 public:
@@ -1244,10 +1249,10 @@ class SyncBlock
     // This should ONLY be called when initializing a SyncBlock (i.e. ONLY from
     // ObjHeader::GetSyncBlock()), otherwise we'll have a race condition.
     // </NOTE>
-    void InitState(ULONG recursionLevel, PTR_Thread holdingThread)
+    void InitState(ULONG recursionLevel, PTR_Thread holdingThread, SIZE_T holdingOSThreadId)
     {
         WRAPPER_NO_CONTRACT;
-        m_Monitor.InitializeToLockedWithNoWaiters(recursionLevel, holdingThread);
+        m_Monitor.InitializeToLockedWithNoWaiters(recursionLevel, holdingThread, holdingOSThreadId);
     }
 
 #if defined(ENABLE_CONTRACTS_IMPL)

diff --git a/src/coreclr/vm/syncblk.inl b/src/coreclr/vm/syncblk.inl
@@ -478,6 +478,7 @@ FORCEINLINE bool AwareLock::TryEnterHelper(Thread* pCurThread)
     if (m_lockState.InterlockedTryLock())
     {
         m_HoldingThread = pCurThread;
+        m_HoldingOSThreadId = pCurThread->GetOSThreadId64();
         m_Recursion = 1;
         return true;
     }
@@ -523,6 +524,7 @@ FORCEINLINE AwareLock::EnterHelperResult AwareLock::TryEnterBeforeSpinLoopHelper
 
         // Lock was acquired and the spinner was not registered
         m_HoldingThread = pCurThread;
+        m_HoldingOSThreadId = pCurThread->GetOSThreadId64();
         m_Recursion = 1;
         return EnterHelperResult_Entered;
     }
@@ -554,6 +556,7 @@ FORCEINLINE AwareLock::EnterHelperResult AwareLock::TryEnterInsideSpinLoopHelper
 
     // Lock was acquired and spinner was unregistered
     m_HoldingThread = pCurThread;
+    m_HoldingOSThreadId = pCurThread->GetOSThreadId64();
     m_Recursion = 1;
     return EnterHelperResult_Entered;
 }
@@ -576,6 +579,7 @@ FORCEINLINE bool AwareLock::TryEnterAfterSpinLoopHelper(Thread *pCurThread)
 
     // Spinner was unregistered and the lock was acquired
     m_HoldingThread = pCurThread;
+    m_HoldingOSThreadId = pCurThread->GetOSThreadId64();
     m_Recursion = 1;
     return true;
 }
@@ -694,6 +698,7 @@ FORCEINLINE AwareLock::LeaveHelperAction AwareLock::LeaveHelper(Thread* pCurThre
     if (--m_Recursion == 0)
     {
         m_HoldingThread = NULL;
+        m_HoldingOSThreadId = 0;
 
         // Clear lock bit and determine whether we must signal a waiter to wake
         if (!m_lockState.InterlockedUnlock())