Add a new version of ContentionEnd event (#22487)

Add new contention event

- This new event contains the duration of the contention.
- Compute duration and emit contention events only when Contention keyword is activated

3 files changed, 53 insertions, 4 deletions

diff --git a/src/vm/ClrEtwAll.man b/src/vm/ClrEtwAll.man
index 18d2a6d82e..3c81d22c43 100644
--- a/src/vm/ClrEtwAll.man
+++ b/src/vm/ClrEtwAll.man
@@ -1412,6 +1412,19 @@
                         </UserData>
                     </template>
 
+                    <template tid="ContentionStop_V1">
+                        <data name="ContentionFlags" inType="win:UInt8" map="ContentionFlagsMap" />
+                        <data name="ClrInstanceID" inType="win:UInt16" />
+                        <data name="Duration" inType="win:Double" />
+                        <UserData>
+                            <Contention xmlns="myNs">
+                                <ContentionFlags> %1 </ContentionFlags>
+                                <ClrInstanceID> %2 </ClrInstanceID>
+                                <Duration> %3 </Duration>
+                            </Contention>
+                        </UserData>
+                    </template>
+
                     <template tid="DomainModuleLoadUnload">
                         <data name="ModuleID" inType="win:UInt64" outType="win:HexInt64" />
                         <data name="AssemblyID" inType="win:UInt64" outType="win:HexInt64" />
@@ -2898,6 +2911,11 @@
                            task="Contention"
                            symbol="ContentionStop" message="$(string.RuntimePublisher.ContentionStopEventMessage)"/>
 
+                    <event value="91" version="1" level="win:Informational"  template="ContentionStop_V1"
+                           keywords ="ContentionKeyword"  opcode="win:Stop"
+                           task="Contention"
+                           symbol="ContentionStop_V1" message="$(string.RuntimePublisher.ContentionStop_V1EventMessage)"/>
+
                     <!-- CLR Stack events -->
                     <event value="82" version="0" level="win:LogAlways"  template="ClrStackWalk"
                            keywords ="StackKeyword"  opcode="CLRStackWalk"
@@ -6408,6 +6426,7 @@
                 <string id="RuntimePublisher.ContentionStartEventMessage" value="NONE" />
                 <string id="RuntimePublisher.ContentionStart_V1EventMessage" value="ContentionFlags=%1;%nClrInstanceID=%2"/>
                 <string id="RuntimePublisher.ContentionStopEventMessage" value="ContentionFlags=%1;%nClrInstanceID=%2"/>
+                <string id="RuntimePublisher.ContentionStop_V1EventMessage" value="ContentionFlags=%1;%nClrInstanceID=%2;Duration=%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/vm/ClrEtwAllMeta.lst b/src/vm/ClrEtwAllMeta.lst
index c6decefe7a..ba4f892fcf 100644
--- a/src/vm/ClrEtwAllMeta.lst
+++ b/src/vm/ClrEtwAllMeta.lst
@@ -183,6 +183,8 @@ noclrinstanceid:Contention:::Contention
 nomac:Contention:::ContentionStart_V1
 nostack:Contention:::ContentionStop
 nomac:Contention:::ContentionStop
+nostack:Contention:::ContentionStop_V1
+nomac:Contention:::ContentionStop_V1
 
 ##################
 # StackWalk events
diff --git a/src/vm/syncblk.cpp b/src/vm/syncblk.cpp
index 7afdc167f2..c344b1bfc6 100644
--- a/src/vm/syncblk.cpp
+++ b/src/vm/syncblk.cpp
@@ -2554,6 +2554,17 @@ inline void LogContention()
 #define LogContention()
 #endif
 
+double ComputeElapsedTimeInNanosecond(LARGE_INTEGER startTicks, LARGE_INTEGER endTicks)
+{
+    static LARGE_INTEGER freq;
+    if (freq.QuadPart == 0)
+        QueryPerformanceFrequency(&freq);
+
+    const double NsPerSecond = 1000 * 1000 * 1000;
+    LONGLONG elapsedTicks = endTicks.QuadPart - startTicks.QuadPart;
+    return (elapsedTicks * NsPerSecond) / freq.QuadPart;
+}
+
 BOOL AwareLock::EnterEpilogHelper(Thread* pCurThread, INT32 timeOut)
 {
     STATIC_CONTRACT_THROWS;
@@ -2571,8 +2582,16 @@ BOOL AwareLock::EnterEpilogHelper(Thread* pCurThread, INT32 timeOut)
     // the object associated with this lock.
     _ASSERTE(pCurThread->PreemptiveGCDisabled());
 
-    // Fire a contention start event for a managed contention
-    FireEtwContentionStart_V1(ETW::ContentionLog::ContentionStructs::ManagedContention, GetClrInstanceId());
+    BOOLEAN IsContentionKeywordEnabled = ETW_TRACING_CATEGORY_ENABLED(MICROSOFT_WINDOWS_DOTNETRUNTIME_PROVIDER_Context, TRACE_LEVEL_INFORMATION, CLR_CONTENTION_KEYWORD);
+    LARGE_INTEGER startTicks = { {0} };
+
+    if (IsContentionKeywordEnabled)
+    {
+        QueryPerformanceCounter(&startTicks);
+
+        // Fire a contention start event for a managed contention
+        FireEtwContentionStart_V1(ETW::ContentionLog::ContentionStructs::ManagedContention, GetClrInstanceId());
+    }
 
     LogContention();
     Thread::IncrementMonitorLockContentionCount(pCurThread);
@@ -2704,8 +2723,17 @@ BOOL AwareLock::EnterEpilogHelper(Thread* pCurThread, INT32 timeOut)
     GCPROTECT_END();
     DecrementTransientPrecious();
 
-    // Fire a contention end event for a managed contention
-    FireEtwContentionStop(ETW::ContentionLog::ContentionStructs::ManagedContention, GetClrInstanceId());
+    if (IsContentionKeywordEnabled)
+    {
+        LARGE_INTEGER endTicks;
+        QueryPerformanceCounter(&endTicks);
+
+        double elapsedTimeInNanosecond = ComputeElapsedTimeInNanosecond(startTicks, endTicks);
+
+        // Fire a contention end event for a managed contention
+        FireEtwContentionStop_V1(ETW::ContentionLog::ContentionStructs::ManagedContention, GetClrInstanceId(), elapsedTimeInNanosecond);
+    }
+
 
     if (ret == WAIT_TIMEOUT)
     {