Implement Activity ID / Related Activity ID for EventSources Writing to EventPipe...
authorBrian Robbins <brianrob@microsoft.com>
Thu, 25 May 2017 19:28:24 +0000 (12:28 -0700)
committerGitHub <noreply@github.com>
Thu, 25 May 2017 19:28:24 +0000 (12:28 -0700)
* Implement thread-local storage of activity ids.

* Plumb the activity id and related activity id into the trace file.

12 files changed:
src/mscorlib/src/System/Diagnostics/Eventing/EventPipe.cs
src/mscorlib/src/System/Diagnostics/Eventing/EventPipeEventProvider.cs
src/mscorlib/src/System/Diagnostics/Eventing/EventSource_CoreCLR.cs
src/vm/eventpipe.cpp
src/vm/eventpipe.h
src/vm/eventpipebuffer.cpp
src/vm/eventpipebuffer.h
src/vm/eventpipebuffermanager.cpp
src/vm/eventpipebuffermanager.h
src/vm/eventpipeconfiguration.cpp
src/vm/eventpipeeventinstance.cpp
src/vm/eventpipeeventinstance.h

index 0d66c94..2f6fdf6 100644 (file)
@@ -170,6 +170,6 @@ namespace System.Diagnostics.Tracing
 
         [DllImport(JitHelpers.QCall, CharSet = CharSet.Unicode)]
         [SuppressUnmanagedCodeSecurity]
-        internal static extern unsafe void WriteEvent(IntPtr eventHandle, uint eventID, void* pData, uint length);
+        internal static extern unsafe void WriteEvent(IntPtr eventHandle, uint eventID, void* pData, uint length, Guid* activityId, Guid* relatedActivityId);
     }
 }
index cd9bd3c..d5bc4c2 100644 (file)
@@ -62,7 +62,7 @@ namespace System.Diagnostics.Tracing
             {
                 if (userDataCount == 0)
                 {
-                    EventPipeInternal.WriteEvent(eventHandle, eventID, null, 0);
+                    EventPipeInternal.WriteEvent(eventHandle, eventID, null, 0, activityId, relatedActivityId);
                     return 0;
                 }
 
@@ -82,7 +82,7 @@ namespace System.Diagnostics.Tracing
                         uint singleUserDataSize = userData[i].Size;
                         WriteToBuffer(pData, length, ref offset, singleUserDataPtr, singleUserDataSize);
                     }
-                    EventPipeInternal.WriteEvent(eventHandle, eventID, pData, length);
+                    EventPipeInternal.WriteEvent(eventHandle, eventID, pData, length, activityId, relatedActivityId);
                 }
             }
             return 0;
index a41c069..01aac72 100644 (file)
@@ -11,6 +11,13 @@ namespace System.Diagnostics.Tracing
 {
     public partial class EventSource
     {
+#if FEATURE_MANAGED_ETW && FEATURE_PERFTRACING
+        // For non-Windows, we use a thread-local variable to hold the activity ID.
+        // On Windows, ETW has it's own thread-local variable and we participate in its use.
+        [ThreadStatic]
+        private static Guid s_currentThreadActivityId;
+#endif // FEATURE_MANAGED_ETW && FEATURE_PERFTRACING
+
         // ActivityID support (see also WriteEventWithRelatedActivityIdCore)
         /// <summary>
         /// When a thread starts work that is on behalf of 'something else' (typically another 
@@ -33,16 +40,20 @@ namespace System.Diagnostics.Tracing
         {
             if (TplEtwProvider.Log != null)
                 TplEtwProvider.Log.SetActivityId(activityId);
-#if FEATURE_MANAGED_ETW && PLATFORM_WINDOWS
+#if FEATURE_MANAGED_ETW
 #if FEATURE_ACTIVITYSAMPLING
             Guid newId = activityId;
 #endif // FEATURE_ACTIVITYSAMPLING
             // We ignore errors to keep with the convention that EventSources do not throw errors.
             // Note we can't access m_throwOnWrites because this is a static method.  
 
+#if FEATURE_PERFTRACING
+            s_currentThreadActivityId = activityId;
+#elif PLATFORM_WINDOWS
             if (UnsafeNativeMethods.ManifestEtw.EventActivityIdControl(
                 UnsafeNativeMethods.ManifestEtw.ActivityControl.EVENT_ACTIVITY_CTRL_GET_SET_ID,
                 ref activityId) == 0)
+#endif // FEATURE_PERFTRACING
             {
 #if FEATURE_ACTIVITYSAMPLING
                 var activityDying = s_activityDying;
@@ -57,7 +68,7 @@ namespace System.Diagnostics.Tracing
                 }
 #endif // FEATURE_ACTIVITYSAMPLING
             }
-#endif // FEATURE_MANAGED_ETW && PLATFORM_WINDOWS
+#endif // FEATURE_MANAGED_ETW
         }
 
         /// <summary>
@@ -82,14 +93,19 @@ namespace System.Diagnostics.Tracing
         public static void SetCurrentThreadActivityId(Guid activityId, out Guid oldActivityThatWillContinue)
         {
             oldActivityThatWillContinue = activityId;
-#if FEATURE_MANAGED_ETW && PLATFORM_WINDOWS
+#if FEATURE_MANAGED_ETW
             // We ignore errors to keep with the convention that EventSources do not throw errors.
             // Note we can't access m_throwOnWrites because this is a static method.  
 
+#if FEATURE_PERFTRACING
+            oldActivityThatWillContinue = s_currentThreadActivityId;
+            s_currentThreadActivityId = activityId;
+#elif PLATFORM_WINDOWS
             UnsafeNativeMethods.ManifestEtw.EventActivityIdControl(
                 UnsafeNativeMethods.ManifestEtw.ActivityControl.EVENT_ACTIVITY_CTRL_GET_SET_ID,
                     ref oldActivityThatWillContinue);
-#endif // FEATURE_MANAGED_ETW && PLATFORM_WINDOWS
+#endif // FEATURE_PERFTRACING
+#endif // FEATURE_MANAGED_ETW
 
             // We don't call the activityDying callback here because the caller has declared that
             // it is not dying.  
@@ -107,11 +123,15 @@ namespace System.Diagnostics.Tracing
                 // We ignore errors to keep with the convention that EventSources do not throw 
                 // errors. Note we can't access m_throwOnWrites because this is a static method.
                 Guid retVal = new Guid();
-#if FEATURE_MANAGED_ETW && PLATFORM_WINDOWS
+#if FEATURE_MANAGED_ETW
+#if FEATURE_PERFTRACING
+                retVal = s_currentThreadActivityId;
+#elif PLATFORM_WINDOWS
                 UnsafeNativeMethods.ManifestEtw.EventActivityIdControl(
                     UnsafeNativeMethods.ManifestEtw.ActivityControl.EVENT_ACTIVITY_CTRL_GET_ID,
                     ref retVal);
-#endif // FEATURE_MANAGED_ETW && PLATFORM_WINDOWS
+#endif // FEATURE_PERFTRACING
+#endif // FEATURE_MANAGED_ETW
                 return retVal;
             }
         }
index b73c023..4eae6a8 100644 (file)
@@ -282,7 +282,7 @@ void EventPipe::DeleteProvider(EventPipeProvider *pProvider)
     }
 }
 
-void EventPipe::WriteEvent(EventPipeEvent &event, BYTE *pData, unsigned int length)
+void EventPipe::WriteEvent(EventPipeEvent &event, BYTE *pData, unsigned int length, LPCGUID pActivityId, LPCGUID pRelatedActivityId)
 {
     CONTRACTL
     {
@@ -309,7 +309,7 @@ void EventPipe::WriteEvent(EventPipeEvent &event, BYTE *pData, unsigned int leng
 
     if(!s_pConfig->RundownEnabled() && s_pBufferManager != NULL)
     {
-        if(!s_pBufferManager->WriteEvent(pThread, event, pData, length))
+        if(!s_pBufferManager->WriteEvent(pThread, event, pData, length, pActivityId, pRelatedActivityId))
         {
             // This is used in DEBUG to make sure that we don't log an event synchronously that we didn't log to the buffer.
             return;
@@ -323,7 +323,9 @@ void EventPipe::WriteEvent(EventPipeEvent &event, BYTE *pData, unsigned int leng
             event,
             pThread->GetOSThreadId(),
             pData,
-            length);
+            length,
+            pActivityId,
+            pRelatedActivityId);
 
         if(s_pFile != NULL)
         {
@@ -340,7 +342,9 @@ void EventPipe::WriteEvent(EventPipeEvent &event, BYTE *pData, unsigned int leng
             event,
             pThread->GetOSThreadId(),
             pData,
-            length);
+            length,
+            pActivityId,
+            pRelatedActivityId);
 
         // Write to the EventPipeFile if it exists.
         if(s_pSyncFile != NULL)
@@ -372,7 +376,7 @@ void EventPipe::WriteSampleProfileEvent(Thread *pSamplingThread, EventPipeEvent
     {
         // Specify the sampling thread as the "current thread", so that we select the right buffer.
         // Specify the target thread so that the event gets properly attributed.
-        if(!s_pBufferManager->WriteEvent(pSamplingThread, *pEvent, pData, length, pTargetThread, &stackContents))
+        if(!s_pBufferManager->WriteEvent(pSamplingThread, *pEvent, pData, length, NULL /* pActivityId */, NULL /* pRelatedActivityId */, pTargetThread, &stackContents))
         {
             // This is used in DEBUG to make sure that we don't log an event synchronously that we didn't log to the buffer.
             return;
@@ -577,14 +581,16 @@ void QCALLTYPE EventPipeInternal::WriteEvent(
     INT_PTR eventHandle,
     unsigned int eventID,
     void *pData,
-    unsigned int length)
+    unsigned int length,
+    LPCGUID pActivityId,
+    LPCGUID pRelatedActivityId)
 {
     QCALL_CONTRACT;
     BEGIN_QCALL;
 
     _ASSERTE(eventHandle != NULL);
     EventPipeEvent *pEvent = reinterpret_cast<EventPipeEvent *>(eventHandle);
-    EventPipe::WriteEvent(*pEvent, (BYTE *)pData, length);
+    EventPipe::WriteEvent(*pEvent, (BYTE *)pData, length, pActivityId, pRelatedActivityId);
 
     END_QCALL;
 }
index 0860080..a69e1ba 100644 (file)
@@ -188,7 +188,7 @@ class EventPipe
 
         // Write out an event.
         // Data is written as a serialized blob matching the ETW serialization conventions.
-        static void WriteEvent(EventPipeEvent &event, BYTE *pData, unsigned int length);
+        static void WriteEvent(EventPipeEvent &event, BYTE *pData, unsigned int length, LPCGUID pActivityId = NULL, LPCGUID pRelatedActivityId = NULL);
 
         // Write out a sample profile event.
         static void WriteSampleProfileEvent(Thread *pSamplingThread, EventPipeEvent *pEvent, Thread *pTargetThread, StackContents &stackContents, BYTE *pData = NULL, unsigned int length = 0);
@@ -305,7 +305,8 @@ public:
         INT_PTR eventHandle,
         unsigned int eventID,
         void *pData,
-        unsigned int length);
+        unsigned int length,
+        LPCGUID pActivityId, LPCGUID pRelatedActivityId);
 };
 
 #endif // FEATURE_PERFTRACING
index ed1c547..00652c9 100644 (file)
@@ -46,7 +46,7 @@ EventPipeBuffer::~EventPipeBuffer()
     }
 }
 
-bool EventPipeBuffer::WriteEvent(Thread *pThread, EventPipeEvent &event, BYTE *pData, unsigned int dataLength, StackContents *pStack)
+bool EventPipeBuffer::WriteEvent(Thread *pThread, EventPipeEvent &event, BYTE *pData, unsigned int dataLength, LPCGUID pActivityId, LPCGUID pRelatedActivityId, StackContents *pStack)
 {
     CONTRACTL
     {
@@ -77,7 +77,9 @@ bool EventPipeBuffer::WriteEvent(Thread *pThread, EventPipeEvent &event, BYTE *p
             event,
             pThread->GetOSThreadId(),
             pDataDest,
-            dataLength);
+            dataLength,
+            pActivityId,
+            pRelatedActivityId);
 
         // Copy the stack if a separate stack trace was provided.
         if(pStack != NULL)
index 97b858d..f279a28 100644 (file)
@@ -81,7 +81,7 @@ public:
     // Returns:
     //  - true: The write succeeded.
     //  - false: The write failed.  In this case, the buffer should be considered full.
-    bool WriteEvent(Thread *pThread, EventPipeEvent &event, BYTE *pData, unsigned int dataLength, StackContents *pStack = NULL);
+    bool WriteEvent(Thread *pThread, EventPipeEvent &event, BYTE *pData, unsigned int dataLength, LPCGUID pActivityId, LPCGUID pRelatedActivityId, StackContents *pStack = NULL);
 
     // Get the timestamp of the most recent event in the buffer.
     LARGE_INTEGER GetMostRecentTimeStamp() const;
index e271fce..5edc462 100644 (file)
@@ -217,7 +217,7 @@ void EventPipeBufferManager::DeAllocateBuffer(EventPipeBuffer *pBuffer)
     }
 }
 
-bool EventPipeBufferManager::WriteEvent(Thread *pThread, EventPipeEvent &event, BYTE *pData, unsigned int length, Thread *pEventThread, StackContents *pStack)
+bool EventPipeBufferManager::WriteEvent(Thread *pThread, EventPipeEvent &event, BYTE *pData, unsigned int length, LPCGUID pActivityId, LPCGUID pRelatedActivityId, Thread *pEventThread, StackContents *pStack)
 {
     CONTRACTL
     {
@@ -276,7 +276,7 @@ bool EventPipeBufferManager::WriteEvent(Thread *pThread, EventPipeEvent &event,
         else
         {
             // Attempt to write the event to the buffer.  If this fails, we should allocate a new buffer.
-            allocNewBuffer = !pBuffer->WriteEvent(pEventThread, event, pData, length, pStack);
+            allocNewBuffer = !pBuffer->WriteEvent(pEventThread, event, pData, length, pActivityId, pRelatedActivityId, pStack);
         }
     }
 
@@ -294,7 +294,7 @@ bool EventPipeBufferManager::WriteEvent(Thread *pThread, EventPipeEvent &event,
     // This is the second time if this thread did have one or more buffers, but they were full.
     if(allocNewBuffer && pBuffer != NULL)
     {
-        allocNewBuffer = !pBuffer->WriteEvent(pEventThread, event, pData, length, pStack);
+        allocNewBuffer = !pBuffer->WriteEvent(pEventThread, event, pData, length, pActivityId, pRelatedActivityId, pStack);
     }
 
     // Mark that the thread is no longer writing an event.
index 74783d2..a53721b 100644 (file)
@@ -67,7 +67,7 @@ public:
     // This is because the thread that writes the events is not the same as the "event thread".
     // An optional stack trace can be provided for sample profiler events.
     // Otherwise, if a stack trace is needed, one will be automatically collected.
-    bool WriteEvent(Thread *pThread, EventPipeEvent &event, BYTE *pData, unsigned int length, Thread *pEventThread = NULL, StackContents *pStack = NULL);
+    bool WriteEvent(Thread *pThread, EventPipeEvent &event, BYTE *pData, unsigned int length, LPCGUID pActivityId, LPCGUID pRelatedActivityId, Thread *pEventThread = NULL, StackContents *pStack = NULL);
 
     // Write the contents of the managed buffers to the specified file.
     // The stopTimeStamp is used to determine when tracing was stopped to ensure that we
index 73379fe..42f9daf 100644 (file)
@@ -370,7 +370,9 @@ EventPipeEventInstance* EventPipeConfiguration::BuildEventMetadataEvent(EventPip
         *m_pMetadataEvent,
         GetCurrentThreadId(),
         pInstancePayload,
-        instancePayloadSize);
+        instancePayloadSize,
+        NULL /* pActivityId */,
+        NULL /* pRelatedActivityId */);
 
     // Set the timestamp to match the source event, because the metadata event
     // will be emitted right before the source event.
index 9372cec..afde2c0 100644 (file)
@@ -14,7 +14,9 @@ EventPipeEventInstance::EventPipeEventInstance(
     EventPipeEvent &event,
     DWORD threadID,
     BYTE *pData,
-    unsigned int length)
+    unsigned int length,
+    LPCGUID pActivityId,
+    LPCGUID pRelatedActivityId)
 {
     CONTRACTL
     {
@@ -30,6 +32,23 @@ EventPipeEventInstance::EventPipeEventInstance(
 #endif // _DEBUG
     m_pEvent = &event;
     m_threadID = threadID;
+    if(pActivityId != NULL)
+    {
+        m_activityId = *pActivityId;
+    }
+    else
+    {
+        m_activityId = {0};
+    }
+    if(pRelatedActivityId != NULL)
+    {
+        m_relatedActivityId = *pRelatedActivityId;
+    }
+    else
+    {
+        m_relatedActivityId = {0};
+    }
+
     m_pData = pData;
     m_dataLength = length;
     QueryPerformanceCounter(&m_timeStamp);
@@ -98,11 +117,14 @@ void EventPipeEventInstance::FastSerialize(FastSerializer *pSerializer, StreamLa
     // Calculate the size of the total payload so that it can be written to the file.
     unsigned int payloadLength =
         sizeof(metadataLabel) +
-        sizeof(m_threadID) +        // Thread ID
-        sizeof(m_timeStamp) +       // TimeStamp
-        m_dataLength +              // Event payload data length
-        sizeof(unsigned int) +      // Prepended stack payload size in bytes
-        m_stackContents.GetSize();  // Stack payload size
+        sizeof(m_threadID) +            // Thread ID
+        sizeof(m_timeStamp) +           // TimeStamp
+        sizeof(m_activityId) +          // Activity ID
+        sizeof(m_relatedActivityId) +   // Related Activity ID
+        sizeof(m_dataLength) +          // Data payload length
+        m_dataLength +                  // Event payload data
+        sizeof(unsigned int) +          // Prepended stack payload size in bytes
+        m_stackContents.GetSize();      // Stack payload size
 
     // Write the size of the event to the file.
     pSerializer->WriteBuffer((BYTE*)&payloadLength, sizeof(payloadLength));
@@ -116,6 +138,15 @@ void EventPipeEventInstance::FastSerialize(FastSerializer *pSerializer, StreamLa
     // Write the timestamp.
     pSerializer->WriteBuffer((BYTE*)&m_timeStamp, sizeof(m_timeStamp));
 
+    // Write the activity id.
+    pSerializer->WriteBuffer((BYTE*)&m_activityId, sizeof(m_activityId));
+
+    // Write the related activity id.
+    pSerializer->WriteBuffer((BYTE*)&m_relatedActivityId, sizeof(m_relatedActivityId));
+
+    // Write the data payload size.
+    pSerializer->WriteBuffer((BYTE*)&m_dataLength, sizeof(m_dataLength));
+
     // Write the event data payload.
     if(m_dataLength > 0)
     {
@@ -199,7 +230,7 @@ bool EventPipeEventInstance::EnsureConsistency()
 #endif // _DEBUG
 
 SampleProfilerEventInstance::SampleProfilerEventInstance(EventPipeEvent &event, Thread *pThread, BYTE *pData, unsigned int length)
-    :EventPipeEventInstance(event, pThread->GetOSThreadId(), pData, length)
+    :EventPipeEventInstance(event, pThread->GetOSThreadId(), pData, length, NULL /* pActivityId */, NULL /* pRelatedActivityId */)
 {
     LIMITED_METHOD_CONTRACT;
 }
index f54a894..4fcf95c 100644 (file)
@@ -19,7 +19,7 @@ class EventPipeEventInstance
 
 public:
 
-    EventPipeEventInstance(EventPipeEvent &event, DWORD threadID, BYTE *pData, unsigned int length);
+    EventPipeEventInstance(EventPipeEvent &event, DWORD threadID, BYTE *pData, unsigned int length, LPCGUID pActivityId, LPCGUID pRelatedActivityId);
 
     // Get the event associated with this instance.
     EventPipeEvent* GetEvent() const;
@@ -55,6 +55,8 @@ protected:
     EventPipeEvent *m_pEvent;
     DWORD m_threadID;
     LARGE_INTEGER m_timeStamp;
+    GUID m_activityId;
+    GUID m_relatedActivityId;
 
     BYTE *m_pData;
     unsigned int m_dataLength;