Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add new version of the ContentionStart event #72627

Merged
merged 9 commits into from
Oct 20, 2022
Merged

Add new version of the ContentionStart event #72627

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
9 commits
Select commit Hold shift + click to select a range
1988694
Add new version of the ContentionStart event
gleocadie Jul 21, 2022
5fb79fd
Change type of LockOjectID and LockOwnerThreadID
gleocadie Jul 21, 2022
d6d6398
Add AwareLockCreated event
gleocadie Aug 4, 2022
d214618
Create stack for AwaredLockCreated event
gleocadie Aug 5, 2022
4550dc5
Address PR comment
gleocadie Aug 5, 2022
1559e3d
Address PR comment
gleocadie Aug 17, 2022
ba3cca1
Fix a couple of issues
kouvel Aug 23, 2022
292656e
Store and send the lock-holding OS thread ID
kouvel Aug 29, 2022
4d529a5
Emit lock created event lazily, include managed object in events
kouvel Oct 19, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
2 changes: 2 additions & 0 deletions src/coreclr/gc/env/etmdummy.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
44 changes: 44 additions & 0 deletions src/coreclr/vm/ClrEtwAll.man
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1742,6 +1742,23 @@
</UserData>
</template>

<template tid="ContentionStart_V2">
Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I wonder if putting the LockId and OwnerId wouldn't be better on the Stop event, WDYT?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it makes more sense on the start event, since you want to know what was holding it that triggered the contention

<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" />
Expand Down Expand Up @@ -3094,6 +3111,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>
Expand Down Expand Up @@ -3642,6 +3673,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"
Expand All @@ -3652,6 +3688,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"
Expand Down Expand Up @@ -8432,8 +8474,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" />
Expand Down
4 changes: 3 additions & 1 deletion src/coreclr/vm/ClrEtwAllMeta.lst
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down Expand Up @@ -698,4 +700,4 @@ nostack:MonoProfiler:::MonoProfilerThreadStopped
nostack:MonoProfiler:::MonoProfilerThreadExited
nostack:MonoProfiler:::MonoProfilerThreadName
nostack:MonoProfiler:::MonoProfilerJitDoneVerbose
nostack:MonoProfiler:::MonoProfilerGCHeapDumpVTableClassReference
nostack:MonoProfiler:::MonoProfilerGCHeapDumpVTableClassReference
43 changes: 31 additions & 12 deletions src/coreclr/vm/syncblk.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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)
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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)
Expand Down Expand Up @@ -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)
Expand Down Expand Up @@ -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();

Expand Down Expand Up @@ -2684,7 +2703,7 @@ BOOL AwareLock::EnterEpilogHelper(Thread* pCurThread, INT32 timeOut)
GCPROTECT_END();
DecrementTransientPrecious();

if (IsContentionKeywordEnabled)
if (isContentionKeywordEnabled)
{
LARGE_INTEGER endTicks;
QueryPerformanceCounter(&endTicks);
Expand All @@ -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)
Expand Down Expand Up @@ -2765,7 +2785,6 @@ BOOL AwareLock::OwnedByCurrentThread()
return (GetThread() == m_HoldingThread);
}


// ***************************************************************************
//
// SyncBlock class implementation
Expand Down
13 changes: 9 additions & 4 deletions src/coreclr/vm/syncblk.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -440,6 +440,7 @@ class AwareLock

ULONG m_Recursion;
PTR_Thread m_HoldingThread;
SIZE_T m_HoldingOSThreadId;

LONG m_TransientPrecious;

Expand All @@ -451,6 +452,7 @@ class AwareLock
CLREvent m_SemEvent;

DWORD m_waiterStarvationStartTimeMs;
int m_emittedLockCreatedEvent;

static const DWORD WaiterStarvationDurationMsBeforeStoppingPreemptingWaiters = 100;

Expand All @@ -461,9 +463,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;
}
Expand Down Expand Up @@ -529,13 +533,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:
Expand Down Expand Up @@ -1232,10 +1237,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)
Expand Down
5 changes: 5 additions & 0 deletions src/coreclr/vm/syncblk.inl
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
Expand Down Expand Up @@ -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;
}
Expand Down Expand Up @@ -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;
}
Expand All @@ -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;
}
Expand Down Expand Up @@ -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())
Expand Down