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.

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 EventSource event for WaitHandle waits #94737

Merged
merged 36 commits into from
Dec 7, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
36 commits
Select commit Hold shift + click to select a range
68e7c3f
Add etw event for Monitor.Wait
verdie-g Nov 14, 2023
a770ac4
Move event to Thread::DoAppropriateWait
verdie-g Nov 17, 2023
d26f018
Emit event from managed code
verdie-g Nov 18, 2023
3f0ec4b
Fix compilation errors
verdie-g Nov 18, 2023
02eb12a
Define WaitHandle source strings
verdie-g Nov 18, 2023
8388740
Move CrlInstanceId as last parameter
verdie-g Nov 20, 2023
e5f58b0
Complete mono implementation
verdie-g Nov 20, 2023
d861183
fix mono
verdie-g Nov 20, 2023
eebe9e6
Fix mono but I commit all files
verdie-g Nov 20, 2023
4d2444a
Fix unsafe usage
verdie-g Nov 20, 2023
cb9b71a
Fix trimming issue
verdie-g Nov 20, 2023
f96f636
Fix uninitialized variable
verdie-g Nov 20, 2023
58a733e
MethodImplOptions.InternalCall in mono
verdie-g Nov 21, 2023
8b724e0
WaitSource 1 byte + remove DurationNs
verdie-g Nov 21, 2023
86f1a68
Fix errors
verdie-g Nov 21, 2023
f52bfc9
Add existing event name to exception
verdie-g Nov 27, 2023
a743853
Address comments
verdie-g Nov 28, 2023
235774f
Remove this as associated object in Condition
verdie-g Nov 28, 2023
88d96ac
Disable wait handle event geneneration
verdie-g Nov 28, 2023
b554d49
Fix mono build
verdie-g Nov 28, 2023
45d4628
Pass associated object in Condition
verdie-g Nov 28, 2023
8bdf215
Rename user data
verdie-g Nov 28, 2023
909bccc
Adjust wait source in native wait
verdie-g Nov 28, 2023
f1cf600
Fix task name
verdie-g Nov 28, 2023
e0d77ca
Add test
verdie-g Nov 30, 2023
c6b1f6f
Only emit event in native code
verdie-g Nov 30, 2023
e83a522
Disable test for mono
verdie-g Nov 30, 2023
7c82bc4
Fix test
verdie-g Nov 30, 2023
500455a
Assert.NotEqual doesn't support custom error message
verdie-g Nov 30, 2023
3730b7f
Make test more robust
verdie-g Nov 30, 2023
81b689f
Make test even more robust
verdie-g Nov 30, 2023
22ffb48
Revert "Only emit event in native code"
verdie-g Dec 6, 2023
c514edb
Remove unrelated changes
verdie-g Dec 6, 2023
a5443af
Raise the events in NativeAOT and Mono, some other updates
kouvel Dec 1, 2023
e868b0e
Fix merge
verdie-g Dec 7, 2023
e29adcf
Fix merge
verdie-g Dec 7, 2023
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
Original file line number Diff line number Diff line change
Expand Up @@ -97,5 +97,18 @@ private static partial void LogThreadPoolIOPack(
IntPtr NativeOverlapped,
IntPtr Overlapped,
ushort ClrInstanceID);

#pragma warning disable IDE0060 // Remove unused parameter
[NonEvent]
private static void LogWaitHandleWaitStart(
WaitHandleWaitSourceMap WaitSource,
IntPtr AssociatedObjectID,
ushort ClrInstanceID) =>
Debug.Fail("This event is currently not expected to be raised by managed code in CoreCLR.");

[NonEvent]
private static void LogWaitHandleWaitStop(ushort ClrInstanceID) =>
Debug.Fail("This event is currently not expected to be raised by managed code in CoreCLR.");
#pragma warning restore IDE0060
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -11,7 +11,7 @@ public abstract partial class WaitHandle
[MethodImpl(MethodImplOptions.InternalCall)]
private static extern int WaitOneCore(IntPtr waitHandle, int millisecondsTimeout);

internal static unsafe int WaitMultipleIgnoringSyncContext(Span<IntPtr> waitHandles, bool waitAll, int millisecondsTimeout)
private static unsafe int WaitMultipleIgnoringSyncContextCore(Span<IntPtr> waitHandles, bool waitAll, int millisecondsTimeout)
{
fixed (IntPtr* pWaitHandles = &MemoryMarshal.GetReference(waitHandles))
{
Expand Down
2 changes: 2 additions & 0 deletions src/coreclr/gc/env/etmdummy.h
Original file line number Diff line number Diff line change
Expand Up @@ -417,3 +417,5 @@
#define FireEtwAppDomainAssemblyResolveHandlerInvoked(ClrInstanceId, assemblyName, handlerName, resultAssemblyName, resultAssemblyPath) 0
#define FireEtwAssemblyLoadFromResolveHandlerInvoked(ClrInstanceId, assemblyName, isTrackedAssembly, requestingAssemblyPath, requestedAssemblyPath) 0
#define FireEtwEventSource(eventID, eventName, eventSourceName, payload) 0
#define FireEtwWaitHandleWaitStart(WaitSource, AssociatedObjectID, ClrInstanceID) 0
#define FireEtwWaitHandleWaitStop(ClrInstanceID) 0
13 changes: 13 additions & 0 deletions src/coreclr/inc/eventtracebase.h
Original file line number Diff line number Diff line change
Expand Up @@ -1153,6 +1153,19 @@ namespace ETW
} ContentionFlags;
} ContentionStructs;
};

class WaitHandleLog
{
public:
typedef union _WaitHandleStructs
{
typedef enum _WaitSource {
Unknown=0,
MonitorWait=1
} WaitSource;
} WaitHandleStructs;
};

// Class to wrap all Interop logic for ETW
class InteropLog
{
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -84,4 +84,12 @@ EXTERN_C NATIVEAOT_API void __cdecl NativeRuntimeEventSource_LogExceptionThrown(
{
}

EXTERN_C NATIVEAOT_API void __cdecl NativeRuntimeEventSource_LogWaitHandleWaitStart(uint8_t WaitSource, intptr_t AssociatedObjectID, uint16_t ClrInstanceID)
{
}

EXTERN_C NATIVEAOT_API void __cdecl NativeRuntimeEventSource_LogWaitHandleWaitStop(uint16_t ClrInstanceID)
{
}

#endif // FEATURE_PERFTRACING
Original file line number Diff line number Diff line change
Expand Up @@ -110,3 +110,5 @@ ThreadPoolWorkerThreadStop
ThreadPoolWorkerThreadWait
ThreadPoolWorkingThreadCount
ThreadRunning
WaitHandleWaitStart
WaitHandleWaitStop
10 changes: 10 additions & 0 deletions src/coreclr/nativeaot/Runtime/runtimeeventinternal.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -100,4 +100,14 @@ EXTERN_C NATIVEAOT_API void __cdecl NativeRuntimeEventSource_LogExceptionThrown(
GetClrInstanceId());
}

EXTERN_C NATIVEAOT_API void __cdecl NativeRuntimeEventSource_LogWaitHandleWaitStart(uint8_t WaitSource, intptr_t AssociatedObjectID, uint16_t ClrInstanceID)
{
FireEtwWaitHandleWaitStart(WaitSource, reinterpret_cast<const void*>(AssociatedObjectID), ClrInstanceID);
}

EXTERN_C NATIVEAOT_API void __cdecl NativeRuntimeEventSource_LogWaitHandleWaitStop(uint16_t ClrInstanceID)
{
FireEtwWaitHandleWaitStop(ClrInstanceID);
}

#endif // FEATURE_PERFTRACING
Original file line number Diff line number Diff line change
Expand Up @@ -22,6 +22,7 @@ public static partial class Keywords
public const EventKeywords ContentionKeyword = (EventKeywords)0x4000;
public const EventKeywords ThreadingKeyword = (EventKeywords)0x10000;
public const EventKeywords ThreadTransferKeyword = (EventKeywords)0x80000000;
public const EventKeywords WaitHandleKeyword = (EventKeywords)0x40000000000;
}

[NonEvent]
Expand Down Expand Up @@ -132,5 +133,20 @@ internal static void LogThreadPoolIOPack(
{
RuntimeImports.NativeRuntimeEventSource_LogThreadPoolIOPack(NativeOverlapped, Overlapped, ClrInstanceID);
}

[NonEvent]
internal static void LogWaitHandleWaitStart(
WaitHandleWaitSourceMap WaitSource,
IntPtr AssociatedObjectID,
ushort ClrInstanceID)
{
RuntimeImports.NativeRuntimeEventSource_LogWaitHandleWaitStart((byte)WaitSource, AssociatedObjectID, ClrInstanceID);
}

[NonEvent]
internal static void LogWaitHandleWaitStop(ushort ClrInstanceID)
{
RuntimeImports.NativeRuntimeEventSource_LogWaitHandleWaitStop(ClrInstanceID);
}
}
}
Original file line number Diff line number Diff line change
Expand Up @@ -826,6 +826,17 @@ internal static partial void NativeRuntimeEventSource_LogThreadPoolIOPack(
[LibraryImport(RuntimeLibrary)]
[UnmanagedCallConv(CallConvs = new Type[] { typeof(CallConvCdecl) })]
internal static unsafe partial void NativeRuntimeEventSource_LogExceptionThrown(char* exceptionTypeName, char* exceptionMessage, IntPtr faultingIP, long hresult);

[LibraryImport(RuntimeLibrary)]
[UnmanagedCallConv(CallConvs = new Type[] { typeof(CallConvCdecl) })]
internal static partial void NativeRuntimeEventSource_LogWaitHandleWaitStart(
byte WaitSource,
IntPtr AssociatedObjectID,
ushort ClrInstanceID);

[LibraryImport(RuntimeLibrary)]
[UnmanagedCallConv(CallConvs = new Type[] { typeof(CallConvCdecl) })]
internal static partial void NativeRuntimeEventSource_LogWaitHandleWaitStop(ushort ClrInstanceID);
#endif // FEATURE_PERFTRACING

//
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -3,8 +3,8 @@

#pragma warning disable 0420 //passing volatile fields by ref


using System.Diagnostics;
using System.Diagnostics.Tracing;

namespace System.Threading
{
Expand Down Expand Up @@ -97,7 +97,7 @@ public Condition(Lock @lock)

public bool Wait(TimeSpan timeout) => Wait(WaitHandle.ToTimeoutMilliseconds(timeout));

public unsafe bool Wait(int millisecondsTimeout)
public unsafe bool Wait(int millisecondsTimeout, object? associatedObjectForMonitorWait = null)
{
ArgumentOutOfRangeException.ThrowIfLessThan(millisecondsTimeout, -1);

Expand All @@ -111,7 +111,13 @@ public unsafe bool Wait(int millisecondsTimeout)
bool success = false;
try
{
success = waiter.ev.WaitOne(millisecondsTimeout);
success =
waiter.ev.WaitOneNoCheck(
millisecondsTimeout,
associatedObjectForMonitorWait,
associatedObjectForMonitorWait != null
? NativeRuntimeEventSource.WaitHandleWaitSourceMap.MonitorWait
: NativeRuntimeEventSource.WaitHandleWaitSourceMap.Unknown);
}
finally
{
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -146,7 +146,7 @@ public static bool IsEntered(object obj)
[UnsupportedOSPlatform("browser")]
public static bool Wait(object obj, int millisecondsTimeout)
{
return GetCondition(obj).Wait(millisecondsTimeout);
return GetCondition(obj).Wait(millisecondsTimeout, obj);
}

public static void Pulse(object obj)
Expand Down
6 changes: 2 additions & 4 deletions src/coreclr/scripts/genRuntimeEventSources.py
Original file line number Diff line number Diff line change
Expand Up @@ -85,11 +85,9 @@ def getManifestsToGenerate(runtimeFlavor):

def generateEvent(eventNode, providerNode, outputFile, stringTable):

# ThreadPool and Contention events are defined manually in NativeRuntimeEventSource.Threading.cs
# Some threading events are defined manually in NativeRuntimeEventSource.Threading.cs
symbol = eventNode.getAttribute("symbol")
if "ThreadPool" in symbol:
return
if "Contention" in symbol:
if any(s in symbol for s in ["ThreadPool", "Contention", "WaitHandle"]):
return

evtLevel = eventNode.getAttribute("level")[4:]
Expand Down
56 changes: 54 additions & 2 deletions src/coreclr/vm/ClrEtwAll.man
Original file line number Diff line number Diff line change
Expand Up @@ -89,6 +89,8 @@
message="$(string.RuntimePublisher.JitInstrumentationDataKeywordMessage)" symbol="CLR_JITINSTRUMENTEDDATA_KEYWORD" />
<keyword name="ProfilerKeyword" mask="0x20000000000"
message="$(string.RuntimePublisher.ProfilerKeywordMessage)" symbol="CLR_PROFILER_KEYWORD" />
<keyword name="WaitHandleKeyword" mask="0x40000000000"
message="$(string.RuntimePublisher.WaitHandleKeywordMessage)" symbol="CLR_WAITHANDLE_KEYWORD"/>
</keywords>
<!--Tasks-->
<tasks>
Expand Down Expand Up @@ -453,7 +455,13 @@
<opcodes>
</opcodes>
</task>
<!--Next available ID is 39-->
<task name="WaitHandleWait" symbol="CLR_WAITHANDLEWAIT_TASK"
value="39" eventGUID="{E90049D8-8AB8-4799-B072-EEF41265BCA4}"
message="$(string.RuntimePublisher.WaitHandleWaitTaskMessage)">
<opcodes>
</opcodes>
</task>
<!--Next available ID is 40-->
</tasks>
<!--Maps-->
<maps>
Expand Down Expand Up @@ -504,6 +512,10 @@
<map value="0x0" message="$(string.RuntimePublisher.Contention.ManagedMapMessage)"/>
<map value="0x1" message="$(string.RuntimePublisher.Contention.NativeMapMessage)"/>
</valueMap>
<valueMap name="WaitHandleWaitSourceMap">
<map value="0x0" message="$(string.RuntimePublisher.WaitHandleWaitSource.UnknownMapMessage)"/>
<map value="0x1" message="$(string.RuntimePublisher.WaitHandleWaitSource.MonitorWaitMapMessage)"/>
</valueMap>
<valueMap name="TailCallTypeMap">
<map value="0x0" message="$(string.RuntimePublisher.TailCallType.OptimizedMapMessage)"/>
<map value="0x1" message="$(string.RuntimePublisher.TailCallType.RecursiveMapMessage)"/>
Expand Down Expand Up @@ -1775,6 +1787,30 @@
</UserData>
</template>

<template tid="WaitHandleWaitStart">
<data name="WaitSource" inType="win:UInt8" map="WaitHandleWaitSourceMap" />
<data name="AssociatedObjectID" inType="win:Pointer" />
<data name="ClrInstanceID" inType="win:UInt16" />

<UserData>
verdie-g marked this conversation as resolved.
Show resolved Hide resolved
<WaitHandleWaitStart xmlns="myNs">
<WaitSource> %1 </WaitSource>
<AssociatedObjectID> %2 </AssociatedObjectID>
<ClrInstanceID> %3 </ClrInstanceID>
</WaitHandleWaitStart>
</UserData>
</template>

<template tid="WaitHandleWaitStop">
<data name="ClrInstanceID" inType="win:UInt16" />

<UserData>
<WaitHandleWaitStop xmlns="myNs">
<ClrInstanceID> %1 </ClrInstanceID>
</WaitHandleWaitStop>
</UserData>
</template>

<template tid="DomainModuleLoadUnload">
<data name="ModuleID" inType="win:UInt64" outType="win:HexInt64" />
<data name="AssemblyID" inType="win:UInt64" outType="win:HexInt64" />
Expand Down Expand Up @@ -3696,7 +3732,6 @@
task="Contention"
symbol="ContentionLockCreated" message="$(string.RuntimePublisher.ContentionLockCreatedEventMessage)"/>


<!-- CLR Stack events -->
<event value="82" version="0" level="win:LogAlways" template="ClrStackWalk"
keywords ="StackKeyword" opcode="CLRStackWalk"
Expand Down Expand Up @@ -4211,6 +4246,17 @@
keywords ="PerfTrackKeyword" opcode="ExecutionCheckpoint" task="ExecutionCheckpoint" symbol="ExecutionCheckpoint"
message="$(string.RuntimePublisher.ExecutionCheckpointEventMessage)"/>

<!-- Wait Handle events -->
<event value="301" version="0" level="win:Verbose" template="WaitHandleWaitStart"
keywords="WaitHandleKeyword" opcode="win:Start"
task="WaitHandleWait"
symbol="WaitHandleWaitStart" message="$(string.RuntimePublisher.WaitHandleWaitStartEventMessage)"/>

<event value="302" version="0" level="win:Verbose" template="WaitHandleWaitStop"
keywords="WaitHandleKeyword" opcode="win:Stop"
task="WaitHandleWait"
symbol="WaitHandleWaitStop" message="$(string.RuntimePublisher.WaitHandleWaitStopEventMessage)"/>

</events>
</provider>

Expand Down Expand Up @@ -8568,6 +8614,8 @@
<string id="RuntimePublisher.TieredCompilationBackgroundJitStartEventMessage" value="ClrInstanceID=%1;%nPendingMethodCount=%2" />
<string id="RuntimePublisher.TieredCompilationBackgroundJitStopEventMessage" value="ClrInstanceID=%1;%nPendingMethodCount=%2;%nJittedMethodCount=%3" />
<string id="RuntimePublisher.ExecutionCheckpointEventMessage" value="ClrInstanceID=%1;Checkpoint=%2;Timestamp=%3"/>
<string id="RuntimePublisher.WaitHandleWaitStartEventMessage" value="WaitSource=%1;%nAssociatedObjectID=%2;%nClrInstanceID=%3"/>
<string id="RuntimePublisher.WaitHandleWaitStopEventMessage" value="ClrInstanceID=%1"/>

<string id="RundownPublisher.MethodDCStartEventMessage" value="MethodID=%1;%nModuleID=%2;%nMethodStartAddress=%3;%nMethodSize=%4;%nMethodToken=%5;%nMethodFlags=%6" />
<string id="RundownPublisher.MethodDCStart_V1EventMessage" value="MethodID=%1;%nModuleID=%2;%nMethodStartAddress=%3;%nMethodSize=%4;%nMethodToken=%5;%nMethodFlags=%6;%nClrInstanceID=%7" />
Expand Down Expand Up @@ -8742,6 +8790,7 @@
<string id="RuntimePublisher.ExecutionCheckpointTaskMessage" value="ExecutionCheckpoint" />
<string id="RuntimePublisher.ProfilerTaskMessage" value="Profiler" />
<string id="RuntimePublisher.YieldProcessorMeasurementTaskMessage" value="YieldProcessorMeasurement" />
<string id="RuntimePublisher.WaitHandleWaitTaskMessage" value="WaitHandleWait" />

<string id="RundownPublisher.GCTaskMessage" value="GC" />
<string id="RundownPublisher.EEStartupTaskMessage" value="Runtime" />
Expand Down Expand Up @@ -8934,6 +8983,8 @@
<string id="RuntimePublisher.ResolutionAttempted.IncompatibleVersion" value="IncompatibleVersion" />
<string id="RuntimePublisher.ResolutionAttempted.Failure" value="Failure" />
<string id="RuntimePublisher.ResolutionAttempted.Exception" value="Exception" />
<string id="RuntimePublisher.WaitHandleWaitSource.UnknownMapMessage" value="Unknown" />
<string id="RuntimePublisher.WaitHandleWaitSource.MonitorWaitMapMessage" value="MonitorWait" />

<string id="RundownPublisher.AppDomain.ExecutableMapMessage" value="Executable" />
<string id="RundownPublisher.AppDomain.SharedMapMessage" value="Shared" />
Expand Down Expand Up @@ -9103,6 +9154,7 @@
<string id="RundownPublisher.PerfTrackRundownKeywordMessage" value="PerfTrack" />
<string id="RundownPublisher.StackKeywordMessage" value="Stack" />
<string id="RundownPublisher.CompilationKeywordMessage" value="Compilation" />
<string id="RuntimePublisher.WaitHandleKeywordMessage" value="WaitHandle" />

<string id="PrivatePublisher.GCPrivateKeywordMessage" value="GC" />
<string id="PrivatePublisher.StartupKeywordMessage" value="Startup" />
Expand Down
7 changes: 7 additions & 0 deletions src/coreclr/vm/ClrEtwAllMeta.lst
Original file line number Diff line number Diff line change
Expand Up @@ -192,6 +192,13 @@ nostack:Contention:::ContentionStop_V1
nomac:Contention:::ContentionStop_V1
nomac:Contention:::ContentionLockCreated

###################
# WaitHandle events
###################
nomac:WaitHandle:::WaitHandleWaitStart
nostack:WaitHandle:::WaitHandleWaitStop
nomac:WaitHandle:::WaitHandleWaitStop
verdie-g marked this conversation as resolved.
Show resolved Hide resolved

##################
# StackWalk events
##################
Expand Down
1 change: 1 addition & 0 deletions src/coreclr/vm/syncblk.cpp
Original file line number Diff line number Diff line change
Expand Up @@ -2850,6 +2850,7 @@ BOOL SyncBlock::Wait(INT32 timeOut)
PendingSync syncState(walk);

OBJECTREF obj = m_Monitor.GetOwningObject();
syncState.m_Object = OBJECTREFToObject(obj);

m_Monitor.IncrementTransientPrecious();

Expand Down
Loading
Loading