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 5 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, LockObjectID, LockOwnerThreadID) 0
#define FireEtwContentionStop(ContentionFlags, ClrInstanceID) 0
#define FireEtwAwareLockCreated(AwareLockID, 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
43 changes: 43 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 @@ -211,6 +211,7 @@
value="8" eventGUID="{561410f5-a138-4ab3-945e-516483cddfbc}"
message="$(string.RuntimePublisher.ContentionTaskMessage)">
<opcodes>
<opcode name="AwareLockCreated" message="$(string.RuntimePublisher.AwareLockCreatedOpcodeMessage)" symbol="CLR_AWARELOCK_CREATED_OPCODE" value="10"> </opcode>
Copy link
Member

Choose a reason for hiding this comment

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

Maybe a new opcode is not necessary, the win:Start opcode can be used instead

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 win:Info is a good choice here since we are not starting an action, and there won't be a corresponding stop.

</opcodes>
</task>

Expand Down Expand Up @@ -1742,6 +1743,21 @@
</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="LockOwnerThreadID" inType="win:UInt64" />
<UserData>
<Contention xmlns="myNs">
<ContentionFlags> %1 </ContentionFlags>
<ClrInstanceID> %2 </ClrInstanceID>
<LockID> %3 </LockID>
<LockOwnerThreadID> %4 </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 +3110,18 @@
</Settings>
</UserData>
</template>

<template tid="AwareLockCreated">
<data name="LockID" inType="win:Pointer" />
<data name="ClrInstanceID" inType="win:UInt16" />
<UserData>
<AwareLockCreated xmlns="myNs">
<LockID> %1 </LockID>
<ClrInstanceID> %2 </ClrInstanceID>
</AwareLockCreated>
</UserData>
</template>

</templates>

<events>
Expand Down Expand Up @@ -3642,6 +3670,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 +3685,12 @@
task="Contention"
symbol="ContentionStop_V1" message="$(string.RuntimePublisher.ContentionStop_V1EventMessage)"/>

<event value="414" version="0" level="win:Informational" template="AwareLockCreated"
Copy link
Member

Choose a reason for hiding this comment

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

Looks like event ID 90 is not used:

Suggested change
<event value="414" version="0" level="win:Informational" template="AwareLockCreated"
<event value="90" version="0" level="win:Informational" template="AwareLockCreated"

Copy link
Member

Choose a reason for hiding this comment

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

The name AwareLock is specific to the current implementation. The implementation may be changed, or another implementation may be added in the future (eg. #34812) and may want to reuse the same events, maybe just LockCreated would be more generic

Copy link
Member

Choose a reason for hiding this comment

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

Agreed, this is a good idea.

keywords ="ContentionKeyword" opcode="AwareLockCreated"
task="Contention"
symbol="AwareLockCreated" message="$(string.RuntimePublisher.AwareLockEventMessage)"/>


<!-- CLR Stack events -->
<event value="82" version="0" level="win:LogAlways" template="ClrStackWalk"
keywords ="StackKeyword" opcode="CLRStackWalk"
Expand Down Expand Up @@ -8432,8 +8471,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;%LockID=%3;%LockOwnerThreadID=%4"/>
<string id="RuntimePublisher.ContentionStopEventMessage" value="ContentionFlags=%1;%nClrInstanceID=%2"/>
<string id="RuntimePublisher.ContentionStop_V1EventMessage" value="ContentionFlags=%1;%nClrInstanceID=%2;DurationNs=%3"/>
<string id="RuntimePublisher.AwareLockEventMessage" value="LockID=%1;%nClrInstanceID=%2"/>
<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 Expand Up @@ -9211,6 +9252,8 @@
<string id="RundownPublisher.TieredCompilationSettingsDCStartOpcodeMessage" value="SettingsDCStart" />
<string id="RundownPublisher.ExecutionCheckpointDCEndOpcodeMessage" value="ExecutionCheckpointDCEnd" />

<string id="RundownPublisher.AwareLockCreatedOpcodeMessage" value="AwareLockCreated" />

<string id="PrivatePublisher.FailFastOpcodeMessage" value="FailFast" />

<string id="PrivatePublisher.GCDecisionOpcodeMessage" value="Decision" />
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:::AwareLockCreated

##################
# 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
22 changes: 13 additions & 9 deletions src/coreclr/vm/syncblk.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2541,22 +2541,22 @@ 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();

BOOLEAN isContentionKeywordEnabled = IsContentionKeywordEnabled();
LARGE_INTEGER startTicks = { {0} };

if (IsContentionKeywordEnabled)
if (isContentionKeywordEnabled)
{
QueryPerformanceCounter(&startTicks);

// Fire a contention start event for a managed contention
FireEtwContentionStart_V1(ETW::ContentionLog::ContentionStructs::ManagedContention, GetClrInstanceId());
FireEtwContentionStart_V2(ETW::ContentionLog::ContentionStructs::ManagedContention, GetClrInstanceId(), this, m_HoldingThread->GetOSThreadId64());
}

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 +2684,7 @@ BOOL AwareLock::EnterEpilogHelper(Thread* pCurThread, INT32 timeOut)
GCPROTECT_END();
DecrementTransientPrecious();

if (IsContentionKeywordEnabled)
if (isContentionKeywordEnabled)
{
LARGE_INTEGER endTicks;
QueryPerformanceCounter(&endTicks);
Expand Down Expand Up @@ -2765,6 +2765,10 @@ BOOL AwareLock::OwnedByCurrentThread()
return (GetThread() == m_HoldingThread);
}

BOOLEAN AwareLock::IsContentionKeywordEnabled() const
{
return ETW_TRACING_CATEGORY_ENABLED(MICROSOFT_WINDOWS_DOTNETRUNTIME_PROVIDER_DOTNET_Context, TRACE_LEVEL_INFORMATION, CLR_CONTENTION_KEYWORD);
}

// ***************************************************************************
//
Expand Down
8 changes: 8 additions & 0 deletions src/coreclr/vm/syncblk.h
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -466,6 +466,11 @@ class AwareLock
m_waiterStarvationStartTimeMs(0)
{
LIMITED_METHOD_CONTRACT;

if (IsContentionKeywordEnabled())
{
FireEtwAwareLockCreated(this, GetClrInstanceId());
}
}

~AwareLock()
Expand Down Expand Up @@ -601,6 +606,9 @@ class AwareLock
LIMITED_METHOD_CONTRACT;
return m_HoldingThread;
}

BOOLEAN IsContentionKeywordEnabled() const;

};

#ifdef FEATURE_COMINTEROP
Expand Down