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

Jump to bottom

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 7 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 FireEtwLockCreated(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
40 changes: 40 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="LockID" inType="win:Pointer" />
<data name="LockOwnerThreadID" inType="win:Pointer" />
<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 +3109,18 @@
</Settings>
</UserData>
</template>

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

</templates>

<events>
Expand Down Expand Up @@ -3642,6 +3669,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 +3684,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 +8470,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.LockCreatedEventMessage" 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
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
34 changes: 29 additions & 5 deletions src/coreclr/vm/syncblk.cpp
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -2237,10 +2237,14 @@ SyncBlock *ObjHeader::GetSyncBlock()

LEAVE_SPIN_LOCK(this);
}
// SyncBlockCache::LockHolder goes out of scope here
}
// SyncBlockCache::LockHolder goes out of scope here
}

// Fire the LockCreated event last, such that it is outside the FAULT_FORBID region above and outside the SyncBlockCache
// lock. The eventing system may need to allocate.
syncBlock->FireLockCreatedEvent();
Copy link
Member

Choose a reason for hiding this comment

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

Does this guarantee that we only fire this event when a lock is created? There are other paths that create syncblocks, right?

Copy link
Member

Choose a reason for hiding this comment

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

I didn't see any other paths that create sync blocks

Copy link
Member

Choose a reason for hiding this comment

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

From what I can see, there are others. Here's an example: https://github.com/dotnet/runtime/blob/main/src/coreclr/vm/object.cpp#L987

Copy link
Member

Choose a reason for hiding this comment

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

It looks like this path also goes through GetSyncBlock(), which is modified here, so it would also emit the event

Copy link
Member

Choose a reason for hiding this comment

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

Right. There are others too, so I don't think this is the right place to emit the event, as it will be potentially much more verbose (and duplicative) than we want.

Copy link
Member

Choose a reason for hiding this comment

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

I thought the sync block would be created once per object and no more? I

That's only true for precious syncblocks. Syncblocks that are not marked as precious can be reclaimed and re-created multiple times.

Copy link
Member

Choose a reason for hiding this comment

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

That's only true for precious syncblocks. Syncblocks that are not marked as precious can be reclaimed and re-created multiple times.

Wouldn't that mean that each time a sync block is recreated for an object, that it may have a different pointer to the AwareLock and hence warrant emitting the event?

Copy link
Member

Choose a reason for hiding this comment

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

Yes, that's correct.

I think that Brian's concern is that we will emit this event for all SyncBlocks even the ones that are not ever used for locks. SyncBlocks are created for number of different reasons (the name "syncblock" is misleading). For example, interop creates them a lot for COM objects and marshalled delegates.

Copy link
Member

Choose a reason for hiding this comment

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

Yes. What do you think about having the AwareLock log that it was created lazily - on first acquisition?

Copy link
Member

Choose a reason for hiding this comment

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

I see. Yes, it could probably be emitted lazily. Taking a step back, is the lock ID really necessary? The stack trace of the contention event would probably be sufficient to identify the lock. I figure the LockCreated event's stack trace would provide similar information. A benefit may be to have only a few LockCreated events and avoid taking stack traces for contention events, but at the cost of missing those created events in some cases. Is there any other benefit?


RETURN syncBlock;
}

Expand Down Expand Up @@ -2541,15 +2545,19 @@ 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);
bool 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);
Copy link
Member

Choose a reason for hiding this comment

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

The last argument here should actually be the OS thread ID. This allows users of the event to match the lock up with the thread that is holding it in a trace. The memory address of the lock won't allow for this.

Copy link
Member

Choose a reason for hiding this comment

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

I commented on this in #72627 (comment). It looks like the holding thread pointer cannot be dereferenced here because there's not guarantee that it would be alive. The ThreadRunning event is emitted from a newly started thread and can be used to map the Thread pointer to the 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.

For threads that are created from outside the runtime and then enter the runtime, I believe the ThreadCreated event can be used to do the same mapping.

Copy link
Member

Choose a reason for hiding this comment

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

I don't think we can depend on the ThreadRunning event because there is nothing that guarantees that this event is present in the trace. If the thread already exists when the trace is started, then we have no way to correlate it back to the OS thread. That said, this call is made in a function that requires cooperative mode. Given this, even if the thread dies, the memory shouldn't be reclaimed until after the next GC when the managed object Finalizer executes, right?

Copy link
Member

Choose a reason for hiding this comment

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

I don't think we can depend on the ThreadRunning event because there is nothing that guarantees that this event is present in the trace. If the thread already exists when the trace is started, then we have no way to correlate it back to the OS thread.

That's also true for the new LockCreated event. It seems like the ordering of those events would matter, so having a rundown of thread and lock objects may not help much to identify the thread. Perhaps the thread object is stored as the holding thread because it is easily accessible and is the minimum work necessary to identify the holding thread. Storing the OS thread ID instead would involve an indirection, and OS thread IDs may also be reused at some point, I suspect this kind of issue would exist in multiple places.

That said, this call is made in a function that requires cooperative mode. Given this, even if the thread dies, the memory shouldn't be reclaimed until after the next GC when the managed object Finalizer executes, right?

I'm not sure about that, coop GC mode would ensure that the managed thread object would be alive if accessible, but once the managed thread object is deemed unreachable and the finalizer runs, perhaps the native thread object can be deleted irrespective of coop GC mode. Maybe there are further constraints that I'm not aware of?

Copy link
Member

Choose a reason for hiding this comment

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

emitting the LockCreated event more often than we should (e.g. every time there is a call to GetSyncBlock)

Why would the LockCreated event be emitted every time GetSyncBlock() is called?

With regard to the OS thread ID. You're right that these can be re-used. This is addressed because the OS will tell us when a thread is created/destroyed. Thus, if there is a re-use within a trace, we'd see this from the OS thread events.

Why would there not be a similar problem to what you mentioned before regarding missing events when starting a trace on an already-running process? For instance, the create/destroy OS events for threads may not be captured by the trace.

A way to address this would be for the thread that acquires the lock to save its thread ID into the lock when tracing is on and clear it when the lock is relinquished. What do you think of that?

The information stored is probably minimal, in the sense what is stored is what is most easily accessible for correct behavior, a different implementation may store something else and that should be ok. As I mentioned before, storing the thread ID would involve an indirection. Changing the implementation for this particular reason is probably something that would need a lot more scrutiny, I don't see enough reason for it yet.

Copy link
Member

Choose a reason for hiding this comment

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

Why would the LockCreated event be emitted every time GetSyncBlock() is called?

You're right, it shouldn't. I missed the fact that the cache lookup occurs at the beginning of this function, and returns early.

Why would there not be a similar problem to what you mentioned before regarding missing events when starting a trace on an already-running process? For instance, the create/destroy OS events for threads may not be captured by the trace.

You technically don't need to see the thread creation event to know that it existed at the beginning of the trace, as long as you see samples or events on the thread. What you do need is to have a thread creation event during the trace to know that the thread ID has been re-used. That said, the OS provides thread/process rundown events at the beginning of the trace to tell profilers about the existence of all processes and traces.

The information stored is probably minimal, in the sense what is stored is what is most easily accessible for correct behavior, a different implementation may store something else and that should be ok. As I mentioned before, storing the thread ID would involve an indirection. Changing the implementation for this particular reason is probably something that would need a lot more scrutiny, I don't see enough reason for it yet.

I'm not sure I follow. Can you tell me a little bit more here? Are you saying that you don't think having the OS Thread ID is worthwhile here?

Copy link
Member

Choose a reason for hiding this comment

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

That said, the OS provides thread/process rundown events at the beginning of the trace to tell profilers about the existence of all processes and traces.

Curious, does this work with circular buffers? More generally, is there some mechanism by which a trace taken with a circular buffer, where the buffer fills up and is overwritten, can still have an accurate snapshot of live objects through events at the beginning of the trace?

Are you saying that you don't think having the OS Thread ID is worthwhile here?

No, mapping to a thread ID would probably be the most useful part. I don't think we should change or add to what is stored for the lock-holding thread. Perhaps taking the thread store lock could enable emitting the 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.

A thread that orphans a lock does not clear the holding thread pointer before its Thread object is destroyed, so acquiring the thread store lock still would not make it feasible to dereference the holding thread pointer. There seem to be a few other related issues and fixing them properly would likely be more involved. For now, we could also store the OS thread ID when the event keyword is enabled as you suggested and update it after the other issues are fixed.

Copy link
Member

Choose a reason for hiding this comment

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

Updated in the latest commit to store and send the OS thread ID, since I think it would be possible to continue doing so after the complete fixes. Still curious about the question in #72627 (comment), as I've run into that issue before and a solution to it may be useful elsewhere.

}

LogContention();
Expand Down Expand Up @@ -2684,7 +2692,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 +2773,22 @@ BOOL AwareLock::OwnedByCurrentThread()
return (GetThread() == m_HoldingThread);
}

/* static */
bool AwareLock::IsContentionKeywordEnabled()
{
WRAPPER_NO_CONTRACT;
return ETW_TRACING_CATEGORY_ENABLED(MICROSOFT_WINDOWS_DOTNETRUNTIME_PROVIDER_DOTNET_Context, TRACE_LEVEL_INFORMATION, CLR_CONTENTION_KEYWORD);
}

void AwareLock::FireLockCreatedEvent() const
{
WRAPPER_NO_CONTRACT;

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

// ***************************************************************************
//
Expand Down
11 changes: 11 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 @@ -601,6 +601,11 @@ class AwareLock
LIMITED_METHOD_CONTRACT;
return m_HoldingThread;
}

private:
static bool IsContentionKeywordEnabled();
public:
void FireLockCreatedEvent() const;
};

#ifdef FEATURE_COMINTEROP
Expand Down Expand Up @@ -1147,6 +1152,12 @@ class SyncBlock
// We've already destructed. But retain the memory.
}

void FireLockCreatedEvent() const
{
WRAPPER_NO_CONTRACT;
m_Monitor.FireLockCreatedEvent();
}

void EnterMonitor()
{
WRAPPER_NO_CONTRACT;
Expand Down