From e4db0db92e0c869c57c826b1926e982418037594 Mon Sep 17 00:00:00 2001 From: Brian Robbins Date: Wed, 1 Aug 2018 11:38:39 -0700 Subject: [PATCH] Expose OSThreadId and TimeStamp on EventWrittenEventArgs (dotnet/coreclr#19002) * Add EventWrittenEventArgs public properties OSThreadId and TimeStamp and plumb through OSThreadId. * Plumb ActivityId and RelatedActivityId to EventListener. Commit migrated from https://github.com/dotnet/coreclr/commit/c4c16723a83c995838508ed7bca7fb99687f6d40 --- .../src/Internal/Runtime/Augments/RuntimeThread.cs | 13 +++ .../Eventing/DotNETRuntimeEventSource.cs | 10 ++- .../src/System/Diagnostics/Eventing/EventPipe.cs | 29 ++++++- .../Eventing/EventPipeEventDispatcher.cs | 52 +++++++++++- src/coreclr/src/pal/inc/pal.h | 6 ++ src/coreclr/src/pal/src/thread/thread.cpp | 25 ++++++ src/coreclr/src/vm/comcallablewrapper.cpp | 30 ++++--- src/coreclr/src/vm/comsynchronizable.cpp | 21 +++++ src/coreclr/src/vm/comsynchronizable.h | 1 + src/coreclr/src/vm/ecalllist.h | 2 + src/coreclr/src/vm/eventpipe.cpp | 75 ++++++++++++++--- src/coreclr/src/vm/eventpipe.h | 29 +++++-- src/coreclr/src/vm/eventpipesession.cpp | 2 + src/coreclr/src/vm/eventpipesession.h | 20 +++++ .../threading/coverage/OSThreadId/OSThreadId.cs | 98 ++++++++++++++++++++++ .../coverage/OSThreadId/osthreadid.csproj | 31 +++++++ .../runtimeeventsource/RuntimeEventSourceTest.cs | 23 ++++- .../src/System/Diagnostics/Tracing/EventSource.cs | 63 ++++++++++++-- 18 files changed, 486 insertions(+), 44 deletions(-) create mode 100644 src/coreclr/tests/src/baseservices/threading/coverage/OSThreadId/OSThreadId.cs create mode 100644 src/coreclr/tests/src/baseservices/threading/coverage/OSThreadId/osthreadid.csproj diff --git a/src/coreclr/src/System.Private.CoreLib/src/Internal/Runtime/Augments/RuntimeThread.cs b/src/coreclr/src/System.Private.CoreLib/src/Internal/Runtime/Augments/RuntimeThread.cs index 9a2204b..c613b2c 100644 --- a/src/coreclr/src/System.Private.CoreLib/src/Internal/Runtime/Augments/RuntimeThread.cs +++ b/src/coreclr/src/System.Private.CoreLib/src/Internal/Runtime/Augments/RuntimeThread.cs @@ -88,6 +88,19 @@ namespace Internal.Runtime.Augments private extern void SetPriorityNative(int priority); /*========================================================================= + ** Returns the operating system identifier for the current thread. + =========================================================================*/ + internal static ulong CurrentOSThreadId + { + get + { + return GetCurrentOSThreadId(); + } + } + [DllImport(JitHelpers.QCall)] + private static extern ulong GetCurrentOSThreadId(); + + /*========================================================================= ** Return the thread state as a consistent set of bits. This is more ** general then IsAlive or IsBackground. =========================================================================*/ diff --git a/src/coreclr/src/System.Private.CoreLib/src/System/Diagnostics/Eventing/DotNETRuntimeEventSource.cs b/src/coreclr/src/System.Private.CoreLib/src/System/Diagnostics/Eventing/DotNETRuntimeEventSource.cs index 8bfac2b..42cf779 100644 --- a/src/coreclr/src/System.Private.CoreLib/src/System/Diagnostics/Eventing/DotNETRuntimeEventSource.cs +++ b/src/coreclr/src/System.Private.CoreLib/src/System/Diagnostics/Eventing/DotNETRuntimeEventSource.cs @@ -16,7 +16,7 @@ namespace System.Diagnostics.Tracing /// The eventID corresponding to the event as defined in the auto-generated portion of the RuntimeEventSource class. /// A span pointing to the data payload for the event. [NonEvent] - internal unsafe void ProcessEvent(uint eventID, ReadOnlySpan payload) + internal unsafe void ProcessEvent(uint eventID, uint osThreadID, DateTime timeStamp, Guid activityId, Guid childActivityId, ReadOnlySpan payload) { // Make sure the eventID is valid. if (eventID >= m_eventData.Length) @@ -26,7 +26,13 @@ namespace System.Diagnostics.Tracing // Decode the payload. object[] decodedPayloadFields = EventPipePayloadDecoder.DecodePayload(ref m_eventData[eventID], payload); - WriteToAllListeners((int)eventID, null, null, decodedPayloadFields); + WriteToAllListeners( + eventId: (int)eventID, + osThreadId: &osThreadID, + timeStamp: &timeStamp, + activityID: &activityId, + childActivityID: &childActivityId, + args: decodedPayloadFields); } } #endif // FEATURE_PERFTRACING diff --git a/src/coreclr/src/System.Private.CoreLib/src/System/Diagnostics/Eventing/EventPipe.cs b/src/coreclr/src/System.Private.CoreLib/src/System/Diagnostics/Eventing/EventPipe.cs index 89528cf..94ace3c 100644 --- a/src/coreclr/src/System.Private.CoreLib/src/System/Diagnostics/Eventing/EventPipe.cs +++ b/src/coreclr/src/System.Private.CoreLib/src/System/Diagnostics/Eventing/EventPipe.cs @@ -16,11 +16,23 @@ namespace System.Diagnostics.Tracing { internal IntPtr ProviderID; internal uint EventID; + internal uint ThreadID; + internal Int64 TimeStamp; + internal Guid ActivityId; + internal Guid ChildActivityId; internal IntPtr Payload; internal uint PayloadLength; } [StructLayout(LayoutKind.Sequential)] + internal struct EventPipeSessionInfo + { + internal Int64 StartTimeAsUTCFileTime; + internal Int64 StartTimeStamp; + internal Int64 TimeStampFrequency; + } + + [StructLayout(LayoutKind.Sequential)] internal struct EventPipeProviderConfiguration { [MarshalAs(UnmanagedType.LPWStr)] @@ -128,6 +140,8 @@ namespace System.Diagnostics.Tracing internal static class EventPipe { + private static UInt64 s_sessionID = 0; + internal static void Enable(EventPipeConfiguration configuration) { if(configuration == null) @@ -142,7 +156,7 @@ namespace System.Diagnostics.Tracing EventPipeProviderConfiguration[] providers = configuration.Providers; - EventPipeInternal.Enable( + s_sessionID = EventPipeInternal.Enable( configuration.OutputFile, configuration.CircularBufferSizeInMB, configuration.ProfilerSamplingRateInNanoseconds, @@ -152,7 +166,7 @@ namespace System.Diagnostics.Tracing internal static void Disable() { - EventPipeInternal.Disable(); + EventPipeInternal.Disable(s_sessionID); } } @@ -162,10 +176,10 @@ namespace System.Diagnostics.Tracing // These PInvokes are used by the configuration APIs to interact with EventPipe. // [DllImport(JitHelpers.QCall, CharSet = CharSet.Unicode)] - internal static extern void Enable(string outputFile, uint circularBufferSizeInMB, long profilerSamplingRateInNanoseconds, EventPipeProviderConfiguration[] providers, int numProviders); + internal static extern UInt64 Enable(string outputFile, uint circularBufferSizeInMB, long profilerSamplingRateInNanoseconds, EventPipeProviderConfiguration[] providers, int numProviders); [DllImport(JitHelpers.QCall, CharSet = CharSet.Unicode)] - internal static extern void Disable(); + internal static extern void Disable(UInt64 sessionID); // // These PInvokes are used by EventSource to interact with the EventPipe. @@ -191,6 +205,13 @@ namespace System.Diagnostics.Tracing [DllImport(JitHelpers.QCall, CharSet = CharSet.Unicode)] internal static extern unsafe void WriteEventData(IntPtr eventHandle, uint eventID, EventProvider.EventData* pEventData, uint dataCount, Guid* activityId, Guid* relatedActivityId); + + // + // These PInvokes are used as part of the EventPipeEventDispatcher. + // + [DllImport(JitHelpers.QCall, CharSet = CharSet.Unicode)] + internal static extern unsafe bool GetSessionInfo(UInt64 sessionID, EventPipeSessionInfo* pSessionInfo); + [DllImport(JitHelpers.QCall, CharSet = CharSet.Unicode)] internal static extern unsafe bool GetNextEvent(EventPipeEventInstanceData* pInstance); } diff --git a/src/coreclr/src/System.Private.CoreLib/src/System/Diagnostics/Eventing/EventPipeEventDispatcher.cs b/src/coreclr/src/System.Private.CoreLib/src/System/Diagnostics/Eventing/EventPipeEventDispatcher.cs index 7d08d0d..f7afd97 100644 --- a/src/coreclr/src/System.Private.CoreLib/src/System/Diagnostics/Eventing/EventPipeEventDispatcher.cs +++ b/src/coreclr/src/System.Private.CoreLib/src/System/Diagnostics/Eventing/EventPipeEventDispatcher.cs @@ -26,6 +26,11 @@ namespace System.Diagnostics.Tracing private IntPtr m_RuntimeProviderID; + private UInt64 m_sessionID = 0; + private DateTime m_syncTimeUtc; + private Int64 m_syncTimeQPC; + private Int64 m_timeQPCFrequency; + private bool m_stopDispatchTask; private Task m_dispatchTask = null; private object m_dispatchControlLock = new object(); @@ -73,13 +78,15 @@ namespace System.Diagnostics.Tracing private void CommitDispatchConfiguration() { + Debug.Assert(Monitor.IsEntered(m_dispatchControlLock)); + // Ensure that the dispatch task is stopped. // This is a no-op if the task is already stopped. StopDispatchTask(); // Stop tracing. // This is a no-op if it's already disabled. - EventPipeInternal.Disable(); + EventPipeInternal.Disable(m_sessionID); // Check to see if tracing should be enabled. if (m_subscriptions.Count <= 0) @@ -87,7 +94,7 @@ namespace System.Diagnostics.Tracing return; } - // Start collecting events. + // Determine the keywords and level that should be used based on the set of enabled EventListeners. EventKeywords aggregatedKeywords = EventKeywords.None; EventLevel highestLevel = EventLevel.LogAlways; @@ -97,12 +104,28 @@ namespace System.Diagnostics.Tracing highestLevel = (subscription.Level > highestLevel) ? subscription.Level : highestLevel; } + // Enable the EventPipe session. EventPipeProviderConfiguration[] providerConfiguration = new EventPipeProviderConfiguration[] { new EventPipeProviderConfiguration(RuntimeEventSource.EventSourceName, (ulong) aggregatedKeywords, (uint) highestLevel) }; - EventPipeInternal.Enable(null, 1024, 1, providerConfiguration, 1); + m_sessionID = EventPipeInternal.Enable(null, 1024, 1, providerConfiguration, 1); + Debug.Assert(m_sessionID != 0); + + // Get the session information that is required to properly dispatch events. + EventPipeSessionInfo sessionInfo; + unsafe + { + if (!EventPipeInternal.GetSessionInfo(m_sessionID, &sessionInfo)) + { + Debug.Assert(false, "GetSessionInfo returned false."); + } + } + + m_syncTimeUtc = DateTime.FromFileTimeUtc(sessionInfo.StartTimeAsUTCFileTime); + m_syncTimeQPC = sessionInfo.StartTimeStamp; + m_timeQPCFrequency = sessionInfo.TimeStampFrequency; // Start the dispatch task. StartDispatchTask(); @@ -146,7 +169,8 @@ namespace System.Diagnostics.Tracing { // Dispatch the event. ReadOnlySpan payload = new ReadOnlySpan((void*)instanceData.Payload, (int)instanceData.PayloadLength); - RuntimeEventSource.Log.ProcessEvent(instanceData.EventID, payload); + DateTime dateTimeStamp = TimeStampToDateTime(instanceData.TimeStamp); + RuntimeEventSource.Log.ProcessEvent(instanceData.EventID, instanceData.ThreadID, dateTimeStamp, instanceData.ActivityId, instanceData.ChildActivityId, payload); } } @@ -157,6 +181,26 @@ namespace System.Diagnostics.Tracing } } } + + /// + /// Converts a QueryPerformanceCounter (QPC) timestamp to a UTC DateTime. + /// + private DateTime TimeStampToDateTime(Int64 timeStamp) + { + if (timeStamp == Int64.MaxValue) + { + return DateTime.MaxValue; + } + + Debug.Assert((m_syncTimeUtc.Ticks != 0) && (m_syncTimeQPC != 0) && (m_timeQPCFrequency != 0)); + Int64 inTicks = (Int64)((timeStamp - m_syncTimeQPC) * 10000000.0 / m_timeQPCFrequency) + m_syncTimeUtc.Ticks; + if((inTicks < 0)|| (DateTime.MaxTicks < inTicks)) + { + inTicks = DateTime.MaxTicks; + } + + return new DateTime(inTicks, DateTimeKind.Utc); + } } #endif // FEATURE_PERFTRACING } diff --git a/src/coreclr/src/pal/inc/pal.h b/src/coreclr/src/pal/inc/pal.h index 98d0ae2..993d76e 100644 --- a/src/coreclr/src/pal/inc/pal.h +++ b/src/coreclr/src/pal/inc/pal.h @@ -1267,6 +1267,12 @@ PALAPI GetCurrentThreadId( VOID); +PALIMPORT +size_t +PALAPI +PAL_GetCurrentOSThreadId( + VOID); + // To work around multiply-defined symbols in the Carbon framework. #define GetCurrentThread PAL_GetCurrentThread PALIMPORT diff --git a/src/coreclr/src/pal/src/thread/thread.cpp b/src/coreclr/src/pal/src/thread/thread.cpp index bc06d2f..66311ed 100644 --- a/src/coreclr/src/pal/src/thread/thread.cpp +++ b/src/coreclr/src/pal/src/thread/thread.cpp @@ -399,6 +399,31 @@ GetCurrentThreadId( return dwThreadId; } +/*++ +Function: + PAL_GetCurrentOSThreadId + +Returns the current thread's OS thread ID. +This API is functionally equivalent to GetCurrentThreadId, but does not truncate the return value to 32-bits. +This is needed to ensure that we can provide the correct OS thread ID on platforms such as OSX that have a 64-bit thread ID. +--*/ +size_t +PALAPI +PAL_GetCurrentOSThreadId( + VOID) +{ + size_t threadId; + + PERF_ENTRY(PAL_GetCurrentOSThreadId); + ENTRY("PAL_GetCurrentOSThreadId()\n"); + + threadId = THREADSilentGetCurrentThreadId(); + + LOGEXIT("PAL_GetCurrentOSThreadId returns %p\n", threadId); + PERF_EXIT(GetCurrentThreadId); + + return threadId; +} /*++ diff --git a/src/coreclr/src/vm/comcallablewrapper.cpp b/src/coreclr/src/vm/comcallablewrapper.cpp index 15e02a2..a2186a7 100644 --- a/src/coreclr/src/vm/comcallablewrapper.cpp +++ b/src/coreclr/src/vm/comcallablewrapper.cpp @@ -958,18 +958,24 @@ void SimpleComCallWrapper::BuildRefCountLogMessage(LPCWSTR wszOperation, StackSS if (ETW_EVENT_ENABLED(MICROSOFT_WINDOWS_DOTNETRUNTIME_PRIVATE_PROVIDER_Context, CCWRefCountChange)) { - SString className; - className.SetUTF8(pszClassName); - SString nameSpace; - nameSpace.SetUTF8(pszNamespace); - - FireEtwCCWRefCountChange( - handle, - (Object *)obj, - this, - dwEstimatedRefCount, - NULL, // domain value is not interesting in CoreCLR - className.GetUnicode(), nameSpace.GetUnicode(), wszOperation, GetClrInstanceId()); + EX_TRY + { + SString className; + className.SetUTF8(pszClassName); + SString nameSpace; + nameSpace.SetUTF8(pszNamespace); + + FireEtwCCWRefCountChange( + handle, + (Object *)obj, + this, + dwEstimatedRefCount, + NULL, // domain value is not interesting in CoreCLR + className.GetUnicode(), nameSpace.GetUnicode(), wszOperation, GetClrInstanceId()); + } + EX_CATCH + { } + EX_END_CATCH(SwallowAllExceptions); } if (g_pConfig->ShouldLogCCWRefCountChange(pszClassName, pszNamespace)) diff --git a/src/coreclr/src/vm/comsynchronizable.cpp b/src/coreclr/src/vm/comsynchronizable.cpp index a476a77..0a6447b 100644 --- a/src/coreclr/src/vm/comsynchronizable.cpp +++ b/src/coreclr/src/vm/comsynchronizable.cpp @@ -804,6 +804,27 @@ FCIMPL0(Object*, ThreadNative::GetCurrentThread) } FCIMPLEND +UINT64 QCALLTYPE ThreadNative::GetCurrentOSThreadId() +{ + QCALL_CONTRACT; + + // The Windows API GetCurrentThreadId returns a 32-bit integer thread ID. + // On some non-Windows platforms (e.g. OSX), the thread ID is a 64-bit value. + // We special case the API for non-Windows to get the 64-bit value and zero-extend + // the Windows value to return a single data type on all platforms. + + UINT64 threadId; + + BEGIN_QCALL; +#ifndef FEATURE_PAL + threadId = (UINT64) GetCurrentThreadId(); +#else + threadId = (UINT64) PAL_GetCurrentOSThreadId(); +#endif + END_QCALL; + + return threadId; +} FCIMPL3(void, ThreadNative::SetStart, ThreadBaseObject* pThisUNSAFE, Object* pDelegateUNSAFE, INT32 iRequestedStackSize) { diff --git a/src/coreclr/src/vm/comsynchronizable.h b/src/coreclr/src/vm/comsynchronizable.h index 87321fd..ddd55cc 100644 --- a/src/coreclr/src/vm/comsynchronizable.h +++ b/src/coreclr/src/vm/comsynchronizable.h @@ -101,6 +101,7 @@ public: static FCDECL1(void, SpinWait, int iterations); static BOOL QCALLTYPE YieldThread(); static FCDECL0(Object*, GetCurrentThread); + static UINT64 QCALLTYPE GetCurrentOSThreadId(); static FCDECL1(void, Finalize, ThreadBaseObject* pThis); #ifdef FEATURE_COMINTEROP static FCDECL1(void, DisableComObjectEagerCleanup, ThreadBaseObject* pThis); diff --git a/src/coreclr/src/vm/ecalllist.h b/src/coreclr/src/vm/ecalllist.h index 25bc85a..46ee7f8 100644 --- a/src/coreclr/src/vm/ecalllist.h +++ b/src/coreclr/src/vm/ecalllist.h @@ -668,6 +668,7 @@ FCFuncStart(gRuntimeThreadFuncs) FCFuncElement("get_IsThreadPoolThread", ThreadNative::IsThreadpoolThread) FCFuncElement("GetPriorityNative", ThreadNative::GetPriority) FCFuncElement("SetPriorityNative", ThreadNative::SetPriority) + QCFuncElement("GetCurrentOSThreadId", ThreadNative::GetCurrentOSThreadId) FCFuncElement("GetThreadStateNative", ThreadNative::GetThreadState) #ifdef FEATURE_COMINTEROP_APARTMENT_SUPPORT FCFuncElement("GetApartmentStateNative", ThreadNative::GetApartmentState) @@ -1154,6 +1155,7 @@ FCFuncEnd() FCFuncStart(gEventPipeInternalFuncs) QCFuncElement("Enable", EventPipeInternal::Enable) QCFuncElement("Disable", EventPipeInternal::Disable) + QCFuncElement("GetSessionInfo", EventPipeInternal::GetSessionInfo) QCFuncElement("CreateProvider", EventPipeInternal::CreateProvider) QCFuncElement("DefineEvent", EventPipeInternal::DefineEvent) QCFuncElement("DeleteProvider", EventPipeInternal::DeleteProvider) diff --git a/src/coreclr/src/vm/eventpipe.cpp b/src/coreclr/src/vm/eventpipe.cpp index 955c757..42eea42 100644 --- a/src/coreclr/src/vm/eventpipe.cpp +++ b/src/coreclr/src/vm/eventpipe.cpp @@ -250,7 +250,7 @@ void EventPipe::Shutdown() // We are shutting down, so if disabling EventPipe throws, we need to move along anyway. EX_TRY { - Disable(); + Disable((EventPipeSessionID)s_pSession); } EX_CATCH { } EX_END_CATCH(SwallowAllExceptions); @@ -279,7 +279,7 @@ void EventPipe::Shutdown() #endif } -void EventPipe::Enable( +EventPipeSessionID EventPipe::Enable( LPCWSTR strOutputPath, unsigned int circularBufferSizeInMB, EventPipeProviderConfiguration *pProviders, @@ -301,10 +301,10 @@ void EventPipe::Enable( static_cast(numProviders)); // Enable the session. - Enable(strOutputPath, pSession); + return Enable(strOutputPath, pSession); } -void EventPipe::Enable(LPCWSTR strOutputPath, EventPipeSession *pSession) +EventPipeSessionID EventPipe::Enable(LPCWSTR strOutputPath, EventPipeSession *pSession) { CONTRACTL { @@ -318,13 +318,13 @@ void EventPipe::Enable(LPCWSTR strOutputPath, EventPipeSession *pSession) // If tracing is not initialized or is already enabled, bail here. if(!s_tracingInitialized || s_pConfig == NULL || s_pConfig->Enabled()) { - return; + return 0; } // If the state or arguments are invalid, bail here. if(pSession == NULL || !pSession->IsValid()) { - return; + return 0; } // Enable the EventPipe EventSource. @@ -365,9 +365,12 @@ void EventPipe::Enable(LPCWSTR strOutputPath, EventPipeSession *pSession) // Enable the sample profiler SampleProfiler::Enable(); + + // Return the session ID. + return (EventPipeSessionID)s_pSession; } -void EventPipe::Disable() +void EventPipe::Disable(EventPipeSessionID id) { CONTRACTL { @@ -377,6 +380,13 @@ void EventPipe::Disable() } CONTRACTL_END; + // Only perform the disable operation if the session ID + // matches the current active session. + if(id != (EventPipeSessionID)s_pSession) + { + return; + } + // Don't block GC during clean-up. GCX_PREEMP(); @@ -463,6 +473,18 @@ void EventPipe::Disable() } } +EventPipeSession* EventPipe::GetSession(EventPipeSessionID id) +{ + LIMITED_METHOD_CONTRACT; + + EventPipeSession *pSession = NULL; + if((EventPipeSessionID)s_pSession == id) + { + pSession = s_pSession; + } + return pSession; +} + bool EventPipe::Enabled() { LIMITED_METHOD_CONTRACT; @@ -1026,7 +1048,7 @@ EventPipeEventInstance* EventPipe::GetNextEvent() return pInstance; } -void QCALLTYPE EventPipeInternal::Enable( +UINT64 QCALLTYPE EventPipeInternal::Enable( __in_z LPCWSTR outputFile, UINT32 circularBufferSizeInMB, INT64 profilerSamplingRateInNanoseconds, @@ -1035,21 +1057,48 @@ void QCALLTYPE EventPipeInternal::Enable( { QCALL_CONTRACT; + UINT64 sessionID = 0; + BEGIN_QCALL; SampleProfiler::SetSamplingRate((unsigned long)profilerSamplingRateInNanoseconds); - EventPipe::Enable(outputFile, circularBufferSizeInMB, pProviders, numProviders); + sessionID = EventPipe::Enable(outputFile, circularBufferSizeInMB, pProviders, numProviders); END_QCALL; + + return sessionID; } -void QCALLTYPE EventPipeInternal::Disable() +void QCALLTYPE EventPipeInternal::Disable(UINT64 sessionID) { QCALL_CONTRACT; BEGIN_QCALL; - EventPipe::Disable(); + EventPipe::Disable(sessionID); END_QCALL; } +bool QCALLTYPE EventPipeInternal::GetSessionInfo(UINT64 sessionID, EventPipeSessionInfo *pSessionInfo) +{ + QCALL_CONTRACT; + + bool retVal = false; + BEGIN_QCALL; + + if(pSessionInfo != NULL) + { + EventPipeSession *pSession = EventPipe::GetSession(sessionID); + if(pSession != NULL) + { + pSessionInfo->StartTimeAsUTCFileTime = pSession->GetStartTime(); + pSessionInfo->StartTimeStamp.QuadPart = pSession->GetStartTimeStamp().QuadPart; + QueryPerformanceFrequency(&pSessionInfo->TimeStampFrequency); + retVal = true; + } + } + + END_QCALL; + return retVal; +} + INT_PTR QCALLTYPE EventPipeInternal::CreateProvider( __in_z LPCWSTR providerName, EventPipeCallback pCallbackFunc) @@ -1235,6 +1284,10 @@ bool QCALLTYPE EventPipeInternal::GetNextEvent( { pInstance->ProviderID = pNextInstance->GetEvent()->GetProvider(); pInstance->EventID = pNextInstance->GetEvent()->GetEventID(); + pInstance->ThreadID = pNextInstance->GetThreadId(); + pInstance->TimeStamp.QuadPart = pNextInstance->GetTimeStamp()->QuadPart; + pInstance->ActivityId = *pNextInstance->GetActivityId(); + pInstance->RelatedActivityId = *pNextInstance->GetRelatedActivityId(); pInstance->Payload = pNextInstance->GetData(); pInstance->PayloadLength = pNextInstance->GetDataLength(); } diff --git a/src/coreclr/src/vm/eventpipe.h b/src/coreclr/src/vm/eventpipe.h index 1904d45..d5273c4 100644 --- a/src/coreclr/src/vm/eventpipe.h +++ b/src/coreclr/src/vm/eventpipe.h @@ -215,6 +215,8 @@ public: } }; +typedef UINT64 EventPipeSessionID; + class EventPipe { // Declare friends. @@ -236,14 +238,17 @@ class EventPipe static void EnableOnStartup(); // Enable tracing via the event pipe. - static void Enable( + static EventPipeSessionID Enable( LPCWSTR strOutputPath, unsigned int circularBufferSizeInMB, EventPipeProviderConfiguration *pProviders, int numProviders); // Disable tracing via the event pipe. - static void Disable(); + static void Disable(EventPipeSessionID id); + + // Get the session for the specified session ID. + static EventPipeSession* GetSession(EventPipeSessionID id); // Specifies whether or not the event pipe is enabled. static bool Enabled(); @@ -288,7 +293,7 @@ class EventPipe private: // Enable the specified EventPipe session. - static void Enable(LPCWSTR strOutputPath, EventPipeSession *pSession); + static EventPipeSessionID Enable(LPCWSTR strOutputPath, EventPipeSession *pSession); // Get the EnableOnStartup configuration from environment. static void GetConfigurationFromEnvironment(SString &outputPath, EventPipeSession *pSession); @@ -385,20 +390,34 @@ private: public: void *ProviderID; unsigned int EventID; + unsigned int ThreadID; + LARGE_INTEGER TimeStamp; + GUID ActivityId; + GUID RelatedActivityId; const BYTE *Payload; unsigned int PayloadLength; }; + struct EventPipeSessionInfo + { + public: + FILETIME StartTimeAsUTCFileTime; + LARGE_INTEGER StartTimeStamp; + LARGE_INTEGER TimeStampFrequency; + }; + public: - static void QCALLTYPE Enable( + static UINT64 QCALLTYPE Enable( __in_z LPCWSTR outputFile, UINT32 circularBufferSizeInMB, INT64 profilerSamplingRateInNanoseconds, EventPipeProviderConfiguration *pProviders, INT32 numProviders); - static void QCALLTYPE Disable(); + static void QCALLTYPE Disable(UINT64 sessionID); + + static bool QCALLTYPE GetSessionInfo(UINT64 sessionID, EventPipeSessionInfo *pSessionInfo); static INT_PTR QCALLTYPE CreateProvider( __in_z LPCWSTR providerName, diff --git a/src/coreclr/src/vm/eventpipesession.cpp b/src/coreclr/src/vm/eventpipesession.cpp index 5f6e415..b10caf2 100644 --- a/src/coreclr/src/vm/eventpipesession.cpp +++ b/src/coreclr/src/vm/eventpipesession.cpp @@ -29,6 +29,8 @@ EventPipeSession::EventPipeSession( m_pProviderList = new EventPipeSessionProviderList( pProviders, numProviders); + GetSystemTimeAsFileTime(&m_sessionStartTime); + QueryPerformanceCounter(&m_sessionStartTimeStamp); } EventPipeSession::~EventPipeSession() diff --git a/src/coreclr/src/vm/eventpipesession.h b/src/coreclr/src/vm/eventpipesession.h index c8c2e1f..5518e76 100644 --- a/src/coreclr/src/vm/eventpipesession.h +++ b/src/coreclr/src/vm/eventpipesession.h @@ -34,6 +34,12 @@ private: // This determines behavior within the system (e.g. policies around which events to drop, etc.) EventPipeSessionType m_sessionType; + // Start date and time in UTC. + FILETIME m_sessionStartTime; + + // Start timestamp. + LARGE_INTEGER m_sessionStartTimeStamp; + public: // TODO: This needs to be exposed via EventPipe::CreateSession() and EventPipe::DeleteSession() to avoid memory ownership issues. @@ -76,6 +82,20 @@ public: m_rundownEnabled = value; } + // Get the session start time in UTC. + FILETIME GetStartTime() const + { + LIMITED_METHOD_CONTRACT; + return m_sessionStartTime; + } + + // Get the session start timestamp. + LARGE_INTEGER GetStartTimeStamp() const + { + LIMITED_METHOD_CONTRACT; + return m_sessionStartTimeStamp; + } + // Enable all events. // This is used for testing and is controlled via COMPLUS_EnableEventPipe. void EnableAllEvents(); diff --git a/src/coreclr/tests/src/baseservices/threading/coverage/OSThreadId/OSThreadId.cs b/src/coreclr/tests/src/baseservices/threading/coverage/OSThreadId/OSThreadId.cs new file mode 100644 index 0000000..85895a7 --- /dev/null +++ b/src/coreclr/tests/src/baseservices/threading/coverage/OSThreadId/OSThreadId.cs @@ -0,0 +1,98 @@ +using System; +using System.Diagnostics; +using System.Reflection; +using System.Threading; + +namespace Threading.Tests +{ + public sealed class OSThreadId + { + private const int NumThreads = 10; + private static MethodInfo s_osThreadIdGetMethod; + private static ManualResetEvent s_resetEvent = new ManualResetEvent(false); + private static ulong[] s_threadIds = new ulong[NumThreads]; + + public static int Main(string[] args) + { + // The property to be tested is internal. + Type runtimeThreadType = typeof(object).Assembly.GetType("Internal.Runtime.Augments.RuntimeThread"); + Assert(runtimeThreadType != null); + PropertyInfo osThreadIdProperty = runtimeThreadType.GetProperty("CurrentOSThreadId", BindingFlags.NonPublic | BindingFlags.Static); + Assert(osThreadIdProperty != null); + s_osThreadIdGetMethod = osThreadIdProperty.GetGetMethod(true); + Assert(s_osThreadIdGetMethod != null); + + // Test the main thread. + Assert(GetCurrentThreadId() > 0); + + // Create more threads. + Thread[] threads = new Thread[NumThreads]; + for (int i = 0; i < NumThreads; i++) + { + threads[i] = new Thread(new ParameterizedThreadStart(ThreadProc)); + threads[i].Start(i); + } + + // Now that all threads have been created, allow them to run. + s_resetEvent.Set(); + + // Wait for all threads to complete. + for (int i = 0; i < NumThreads; i++) + { + threads[i].Join(); + } + + // Check for duplicate thread IDs. + Array.Sort(s_threadIds); + ulong previousThreadId = 0; + for (int i = 0; i < NumThreads; i++) + { + if (i == 0) + { + previousThreadId = s_threadIds[i]; + } + else + { + Assert(s_threadIds[i] > 0); + Assert(previousThreadId != s_threadIds[i]); + previousThreadId = s_threadIds[i]; + } + } + + return 100; + } + + private static ulong GetCurrentThreadId() + { + return (ulong)s_osThreadIdGetMethod.Invoke(null, null); + } + + private static void ThreadProc(object state) + { + // Get the thread index. + int threadIndex = (int)state; + Assert(threadIndex >= 0 && threadIndex < NumThreads); + + // Wait for all threads to be created. + s_resetEvent.WaitOne(); + + // We now know that all threads were created before GetCurrentThread is called. + // Thus, no thread IDs can be duplicates. + ulong threadId = GetCurrentThreadId(); + + // Ensure that the thread ID is valid. + Assert(threadId > 0); + + // Save the thread ID so that it can be checked for duplicates. + s_threadIds[threadIndex] = threadId; + } + + private static void Assert(bool condition) + { + if (!condition) + { + throw new Exception("Assertion failed."); + } + } + } +} diff --git a/src/coreclr/tests/src/baseservices/threading/coverage/OSThreadId/osthreadid.csproj b/src/coreclr/tests/src/baseservices/threading/coverage/OSThreadId/osthreadid.csproj new file mode 100644 index 0000000..6d26304 --- /dev/null +++ b/src/coreclr/tests/src/baseservices/threading/coverage/OSThreadId/osthreadid.csproj @@ -0,0 +1,31 @@ + + + + + Debug + AnyCPU + 2.0 + {8E3244CB-407F-4142-BAAB-E7A55901A5FA} + Exe + {786C830F-07A1-408B-BD7F-6EE04809D6DB};{FAE04EC0-301F-11D3-BF4B-00C04F79EFBC} + ..\..\ + BuildAndRun + $(DefineConstants);STATIC + true + 0 + + + + + + + + + False + + + + + + + diff --git a/src/coreclr/tests/src/tracing/runtimeeventsource/RuntimeEventSourceTest.cs b/src/coreclr/tests/src/tracing/runtimeeventsource/RuntimeEventSourceTest.cs index 94d3585..fdaae9e 100644 --- a/src/coreclr/tests/src/tracing/runtimeeventsource/RuntimeEventSourceTest.cs +++ b/src/coreclr/tests/src/tracing/runtimeeventsource/RuntimeEventSourceTest.cs @@ -1,3 +1,5 @@ +#define REFLECTION + using System; using System.IO; using System.Diagnostics.Tracing; @@ -5,6 +7,10 @@ using System.Runtime.CompilerServices; using System.Threading; using Tracing.Tests.Common; +#if REFLECTION +using System.Reflection; +#endif + namespace Tracing.Tests { public sealed class RuntimeEventSourceTest @@ -76,7 +82,22 @@ namespace Tracing.Tests protected override void OnEventWritten(EventWrittenEventArgs eventData) { - Console.WriteLine($"[{m_name}] ID = {eventData.EventId} Name = {eventData.EventName}"); + long osThreadId = -1; + DateTime timeStamp; +#if REFLECTION + PropertyInfo threadProperty = typeof(EventWrittenEventArgs).GetProperty("OSThreadId"); + MethodInfo threadMethod = threadProperty.GetGetMethod(); + osThreadId = (long)threadMethod.Invoke(eventData, null); + PropertyInfo timeStampProperty = typeof(EventWrittenEventArgs).GetProperty("TimeStamp"); + MethodInfo timeStampMethod = timeStampProperty.GetGetMethod(); + timeStamp = (DateTime)timeStampMethod.Invoke(eventData, null); +#endif + + Console.WriteLine($"[{m_name}] ThreadID = {osThreadId} ID = {eventData.EventId} Name = {eventData.EventName}"); + Console.WriteLine($"TimeStamp: {timeStamp.ToLocalTime()}"); + Console.WriteLine($"LocalTime: {DateTime.Now}"); + Console.WriteLine($"Difference: {DateTime.UtcNow - timeStamp}"); + Assert.True("timeStamp < DateTime.UtcNow", timeStamp < DateTime.UtcNow); for (int i = 0; i < eventData.Payload.Count; i++) { string payloadString = eventData.Payload[i] != null ? eventData.Payload[i].ToString() : string.Empty; diff --git a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs index 6ee5f25..9ebb103 100644 --- a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs +++ b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventSource.cs @@ -1913,13 +1913,25 @@ namespace System.Diagnostics.Tracing // Maintain old behavior - object identity is preserved if (AppContextSwitches.PreserveEventListnerObjectIdentity) { - WriteToAllListeners(eventId, pActivityId, childActivityID, args); + WriteToAllListeners( + eventId: eventId, + osThreadId: null, + timeStamp: null, + activityID: pActivityId, + childActivityID: childActivityID, + args: args); } else #endif // !ES_BUILD_STANDALONE { object[] serializedArgs = SerializeEventArgs(eventId, args); - WriteToAllListeners(eventId, pActivityId, childActivityID, serializedArgs); + WriteToAllListeners( + eventId: eventId, + osThreadId: null, + timeStamp: null, + activityID: pActivityId, + childActivityID: childActivityID, + args: serializedArgs); } } } @@ -2021,14 +2033,24 @@ namespace System.Diagnostics.Tracing EventSource.EventData* dataPtr = data; for (int i = 0; i < paramCount; i++) args[i] = DecodeObject(eventId, i, ref dataPtr); - WriteToAllListeners(eventId, activityID, childActivityID, args); + WriteToAllListeners( + eventId: eventId, + osThreadId: null, + timeStamp: null, + activityID: activityID, + childActivityID: childActivityID, + args: args); } // helper for writing to all EventListeners attached the current eventSource. - internal unsafe void WriteToAllListeners(int eventId, Guid* activityID, Guid* childActivityID, params object[] args) + internal unsafe void WriteToAllListeners(int eventId, uint* osThreadId, DateTime* timeStamp, Guid* activityID, Guid* childActivityID, params object[] args) { EventWrittenEventArgs eventCallbackArgs = new EventWrittenEventArgs(this); eventCallbackArgs.EventId = eventId; + if (osThreadId != null) + eventCallbackArgs.OSThreadId = (int)*osThreadId; + if (timeStamp != null) + eventCallbackArgs.TimeStamp = *timeStamp; if (activityID != null) eventCallbackArgs.ActivityId = *activityID; if (childActivityID != null) @@ -4609,16 +4631,47 @@ namespace System.Diagnostics.Tracing } } -#region private + /// + /// Gets the identifier for the OS thread that wrote the event. + /// + public long OSThreadId + { + get + { + if (!m_osThreadId.HasValue) + { + m_osThreadId = (long)RuntimeThread.CurrentOSThreadId; + } + + return m_osThreadId.Value; + } + internal set + { + m_osThreadId = value; + } + } + + /// + /// Gets a UTC DateTime that specifies when the event was written. + /// + public DateTime TimeStamp + { + get; + internal set; + } + + #region private internal EventWrittenEventArgs(EventSource eventSource) { m_eventSource = eventSource; + TimeStamp = DateTime.UtcNow; } private string m_message; private string m_eventName; private EventSource m_eventSource; private ReadOnlyCollection m_payloadNames; private Guid m_activityId; + private long? m_osThreadId; internal EventTags m_tags; internal EventOpcode m_opcode; internal EventLevel m_level; -- 2.7.4