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 2 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
1 change: 1 addition & 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,6 +98,7 @@
#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 FireEtwCLRStackWalk(ClrInstanceID, Reserved1, Reserved2, FrameCount, Stack) 0
#define FireEtwAppDomainMemAllocated(AppDomainID, Allocated, ClrInstanceID) 0
Expand Down
21 changes: 21 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,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="LockObjectID" inType="win:Pointer" />
Copy link
Member

Choose a reason for hiding this comment

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

Recommend calling this LockID, and then match with the same name in the AwareLockCreated event.

<data name="LockOwnerThreadID" inType="win:Pointer" />
<UserData>
<Contention xmlns="myNs">
<ContentionFlags> %1 </ContentionFlags>
<ClrInstanceID> %2 </ClrInstanceID>
<LockObjectID> %3 </LockObjectID>
<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 @@ -3642,6 +3657,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 Down Expand Up @@ -8432,6 +8452,7 @@
<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;%LockObjectID=%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.DCStartCompleteEventMessage" value="NONE" />
Expand Down
3 changes: 2 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,6 +185,7 @@ 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
Expand Down Expand Up @@ -698,4 +699,4 @@ nostack:MonoProfiler:::MonoProfilerThreadStopped
nostack:MonoProfiler:::MonoProfilerThreadExited
nostack:MonoProfiler:::MonoProfilerThreadName
nostack:MonoProfiler:::MonoProfilerJitDoneVerbose
nostack:MonoProfiler:::MonoProfilerGCHeapDumpVTableClassReference
nostack:MonoProfiler:::MonoProfilerGCHeapDumpVTableClassReference
12 changes: 6 additions & 6 deletions src/coreclr/vm/syncblk.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2541,6 +2541,11 @@ BOOL AwareLock::EnterEpilogHelper(Thread* pCurThread, INT32 timeOut)
// the object associated with this lock.
_ASSERTE(pCurThread->PreemptiveGCDisabled());

LogContention();
Thread::IncrementMonitorLockContentionCount(pCurThread);

OBJECTREF obj = GetOwningObject();

BOOLEAN IsContentionKeywordEnabled = ETW_TRACING_CATEGORY_ENABLED(MICROSOFT_WINDOWS_DOTNETRUNTIME_PROVIDER_DOTNET_Context, TRACE_LEVEL_INFORMATION, CLR_CONTENTION_KEYWORD);
LARGE_INTEGER startTicks = { {0} };

Expand All @@ -2549,14 +2554,9 @@ BOOL AwareLock::EnterEpilogHelper(Thread* pCurThread, INT32 timeOut)
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(), OBJECTREFToObject(obj), m_HoldingThread);
Copy link
Member

Choose a reason for hiding this comment

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

Rather than writing out m_HoldingThread which is the address of the Thread object in memory, can we change this to m_HoldingThread->GetOSThreadId64()? This will allow a profiler to display what the thread that currently holds the lock is doing. With the pointer value, you would need to provide another event that correlates between Thread* and the actual OS thread ID.

Copy link
Member

Choose a reason for hiding this comment

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

Another potential issue here is that the value of obj can change during GC relocation. Is the goal to also watch the GC survival and movement events, or do you want to try and have a more durable ID? I'm wondering if AwareLock should also have a set of creation/destruction events so that you can see the full lifetime of the lock.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

@brianrob good point. I'll make the change to replace the pointer by the OS Thread id.

Another potential issue here is that the value of obj can change during GC relocation.

Does it mean that the address is changed also ?
The goal, at least in this PR, is not to watch the lock object lifetime, but more having an ID to do some correlation.

Copy link
Member

@kouvel kouvel Aug 2, 2022 •
edited
Loading

Choose a reason for hiding this comment

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

Does it mean that the address is changed also ?

Yes the object address also changes when it's moved. Could pass in this instead to include the AwareLock pointer as just an identifier for the lock.

Copy link
Member

Choose a reason for hiding this comment

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

Using this is a good idea. Worth calling out though that it is possible to destroy and then create a new lock at the same address. To make sure that you know about this, you may wish to write an event in the AwareLock ctor so that you know when the aware lock is created. This type of pattern is other places such as module and type loads. We use the address of the module or type in memory, but handle questions of lifetime using load/unload events.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Thanks for the info.
So if I understand correctly, in the AwareLock ctor I emit an event (we know the lock is created) and I will have to emit an event in the dtor to know when the lock is deleted, right ?

I'll do the change taking into account your comment.

Copy link
Member

Choose a reason for hiding this comment

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

To avoid emitting too many events, I think you can safely emit just the creation event. If you see two creation events at the same address, you know that it's a new lock.

}

LogContention();
Thread::IncrementMonitorLockContentionCount(pCurThread);

OBJECTREF obj = GetOwningObject();

// We cannot allow the AwareLock to be cleaned up underneath us by the GC.
IncrementTransientPrecious();

Expand Down