From 60fa305098b720aee21bc3267dec26a8a685fa4f Mon Sep 17 00:00:00 2001 From: John Salem Date: Fri, 16 Jul 2021 16:21:21 -0700 Subject: [PATCH 1/5] Null out m_provHandle when deleted --- .../Diagnostics/Tracing/EventPipeEventProvider.cs | 13 ++++++++++--- 1 file changed, 10 insertions(+), 3 deletions(-) diff --git a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventProvider.cs b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventProvider.cs index 2696fa21716eba..902d89111cbe44 100644 --- a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventProvider.cs +++ b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventProvider.cs @@ -35,7 +35,9 @@ unsafe uint IEventProvider.EventRegister( // Unregister an event provider. uint IEventProvider.EventUnregister(long registrationHandle) { - EventPipeInternal.DeleteProvider(m_provHandle); + IntPtr provHandle = m_provHandle; + m_provHandle = IntPtr.Zero; + EventPipeInternal.DeleteProvider(provHandle); return 0; } @@ -82,8 +84,13 @@ int IEventProvider.EventActivityIdControl(Interop.Advapi32.ActivityControl Contr unsafe IntPtr IEventProvider.DefineEventHandle(uint eventID, string eventName, long keywords, uint eventVersion, uint level, byte *pMetadata, uint metadataLength) { - IntPtr eventHandlePtr = EventPipeInternal.DefineEvent(m_provHandle, eventID, keywords, eventVersion, level, pMetadata, metadataLength); - return eventHandlePtr; + if (m_provHandle != IntPtr.Zero) + { + IntPtr eventHandlePtr = EventPipeInternal.DefineEvent(m_provHandle, eventID, keywords, eventVersion, level, pMetadata, metadataLength); + return eventHandlePtr; + } + + return IntPtr.Zero; } // Get or set the per-thread activity ID. From ddb2fb93c947bc5161a7b131b87d90dd63f6a3cc Mon Sep 17 00:00:00 2001 From: John Salem Date: Fri, 16 Jul 2021 16:22:12 -0700 Subject: [PATCH 2/5] two-phase disable checking in EventSource * prevent writers from accessing internal data while it is being disposed --- .../System/Diagnostics/Tracing/EventSource.cs | 25 +++++++++++++++---- .../TraceLogging/TraceLoggingEventSource.cs | 11 ++++++++ 2 files changed, 31 insertions(+), 5 deletions(-) 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 4800a2cde47365..a75d154e04ea7b 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 @@ -295,7 +295,7 @@ public bool IsEnabled(EventLevel level, EventKeywords keywords, EventChannel cha if (!IsEnabled()) return false; - if (!IsEnabledCommon(m_eventSourceEnabled, m_level, m_matchAnyKeyword, level, keywords, channel)) + if (!IsEnabledCommon(IsEnabled(), m_level, m_matchAnyKeyword, level, keywords, channel)) return false; return true; @@ -1307,6 +1307,7 @@ protected unsafe void WriteEventWithRelatedActivityIdCore(int eventId, Guid* rel Debug.Assert(m_eventData != null); // You must have initialized this if you enabled the source. try { + m_activeWritesCount++; ref EventMetadata metadata = ref m_eventData[eventId]; EventOpcode opcode = (EventOpcode)metadata.Descriptor.Opcode; @@ -1380,6 +1381,10 @@ protected unsafe void WriteEventWithRelatedActivityIdCore(int eventId, Guid* rel else ThrowEventSourceException(m_eventData[eventId].Name, ex); } + finally + { + m_activeWritesCount--; + } } } @@ -1448,7 +1453,7 @@ protected virtual void Dispose(bool disposing) #if FEATURE_MANAGED_ETW // Send the manifest one more time to ensure circular buffers have a chance to get to this information // even in scenarios with a high volume of ETW events. - if (m_eventSourceEnabled) + if (IsEnabled()) { try { @@ -1457,6 +1462,10 @@ protected virtual void Dispose(bool disposing) catch { } // If it fails, simply give up. m_eventSourceEnabled = false; } + + // Wait till active writes have finished (stop waiting at 1 second) + SpinWait.SpinUntil(() => m_activeWritesCount == 0, 1000); + if (m_etwProvider != null) { m_etwProvider.Dispose(); @@ -1625,7 +1634,7 @@ private unsafe void Initialize(Guid eventSourceGuid, string eventSourceName, str #if FEATURE_PERFTRACING m_eventPipeProvider = eventPipeProvider; #endif - Debug.Assert(!m_eventSourceEnabled); // We can't be enabled until we are completely initted. + Debug.Assert(!IsEnabled()); // We can't be enabled until we are completely initted. // We are logically completely initialized at this point. m_completelyInited = true; } @@ -1897,6 +1906,7 @@ private unsafe void WriteEventVarargs(int eventId, Guid* childActivityID, object Debug.Assert(m_eventData != null); // You must have initialized this if you enabled the source. try { + m_activeWritesCount++; ref EventMetadata metadata = ref m_eventData[eventId]; if (childActivityID != null) @@ -1996,6 +2006,10 @@ private unsafe void WriteEventVarargs(int eventId, Guid* childActivityID, object else ThrowEventSourceException(m_eventData[eventId].Name, ex); } + finally + { + m_activeWritesCount--; + } } } @@ -2625,7 +2639,7 @@ internal void DoCommand(EventCommandEventArgs commandArgs) if (commandArgs.enable) { - if (!m_eventSourceEnabled) + if (!IsEnabled()) { // EventSource turned on for the first time, simply copy the bits. m_level = commandArgs.level; @@ -3852,9 +3866,10 @@ private bool SelfDescribingEvents private bool m_eventSourceDisposed; // has Dispose been called. // Enabling bits - private bool m_eventSourceEnabled; // am I enabled (any of my events are enabled for any dispatcher) + private volatile bool m_eventSourceEnabled; // am I enabled (any of my events are enabled for any dispatcher) internal EventLevel m_level; // highest level enabled by any output dispatcher internal EventKeywords m_matchAnyKeyword; // the logical OR of all levels enabled by any output dispatcher (zero is a special case) meaning 'all keywords' + private volatile int m_activeWritesCount; // The number of currently active calls to Write methods that have already checked m_eventSourceEnabled // Dispatching state internal volatile EventDispatcher? m_Dispatchers; // Linked list of code:EventDispatchers we write the data to (we also do ETW specially) diff --git a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/TraceLogging/TraceLoggingEventSource.cs b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/TraceLogging/TraceLoggingEventSource.cs index c51d731e0c61e8..f0eceba9235424 100644 --- a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/TraceLogging/TraceLoggingEventSource.cs +++ b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/TraceLogging/TraceLoggingEventSource.cs @@ -378,7 +378,9 @@ private unsafe void WriteMultiMerge( if (this.IsEnabled((EventLevel)level, keywords)) { + m_activeWritesCount++; WriteMultiMergeInner(eventName, ref options, eventTypes, activityID, childActivityID, values); + m_activeWritesCount--; } } @@ -555,6 +557,8 @@ internal unsafe void WriteMultiMerge( return; } + m_activeWritesCount++; + fixed (EventSourceOptions* pOptions = &options) { NameInfo? nameInfo = this.UpdateDescriptor(eventName, eventTypes, ref options, out EventDescriptor descriptor); @@ -610,6 +614,8 @@ internal unsafe void WriteMultiMerge( (IntPtr)descriptors); } } + + m_activeWritesCount--; #endif // FEATURE_MANAGED_ETW } @@ -623,6 +629,7 @@ private unsafe void WriteImpl( { try { + m_activeWritesCount++; fixed (EventSourceOptions* pOptions = &options) { options.Opcode = options.IsOpcodeSet ? options.Opcode : GetOpcodeWithDefault(options.Opcode, eventName); @@ -741,6 +748,10 @@ private unsafe void WriteImpl( else ThrowEventSourceException(eventName, ex); } + finally + { + m_activeWritesCount--; + } } private unsafe void WriteToAllListeners(string? eventName, ref EventDescriptor eventDescriptor, EventTags tags, Guid* pActivityId, Guid* pChildActivityId, EventPayload? payload) From f7a43a8044480a98a7893fc8fb79b6806042fe9c Mon Sep 17 00:00:00 2001 From: John Salem Date: Mon, 19 Jul 2021 13:08:34 -0700 Subject: [PATCH 3/5] Fix positioning of incr/decr pairs * add comment --- .../System/Diagnostics/Tracing/EventSource.cs | 5 +- .../TraceLogging/TraceLoggingEventSource.cs | 359 +++++++++--------- 2 files changed, 188 insertions(+), 176 deletions(-) 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 a75d154e04ea7b..1c771881657683 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 @@ -1302,12 +1302,12 @@ protected unsafe void WriteEventCore(int eventId, int eventDataCount, EventSourc [CLSCompliant(false)] protected unsafe void WriteEventWithRelatedActivityIdCore(int eventId, Guid* relatedActivityId, int eventDataCount, EventSource.EventData* data) { + m_activeWritesCount++; if (IsEnabled()) { Debug.Assert(m_eventData != null); // You must have initialized this if you enabled the source. try { - m_activeWritesCount++; ref EventMetadata metadata = ref m_eventData[eventId]; EventOpcode opcode = (EventOpcode)metadata.Descriptor.Opcode; @@ -1464,6 +1464,7 @@ protected virtual void Dispose(bool disposing) } // Wait till active writes have finished (stop waiting at 1 second) + // TODO: determine appropriate break out mechanism. Is 1 second appropriate? Is a timeout appropriate at all? SpinWait.SpinUntil(() => m_activeWritesCount == 0, 1000); if (m_etwProvider != null) @@ -1901,12 +1902,12 @@ private static unsafe void AssertValidString(EventData* data) #endif private unsafe void WriteEventVarargs(int eventId, Guid* childActivityID, object?[] args) { + m_activeWritesCount++; if (IsEnabled()) { Debug.Assert(m_eventData != null); // You must have initialized this if you enabled the source. try { - m_activeWritesCount++; ref EventMetadata metadata = ref m_eventData[eventId]; if (childActivityID != null) diff --git a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/TraceLogging/TraceLoggingEventSource.cs b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/TraceLogging/TraceLoggingEventSource.cs index f0eceba9235424..e133c06d835f99 100644 --- a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/TraceLogging/TraceLoggingEventSource.cs +++ b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/TraceLogging/TraceLoggingEventSource.cs @@ -365,22 +365,27 @@ private unsafe void WriteMultiMerge( Guid* childActivityID, params object?[] values) { - if (!this.IsEnabled()) - { - return; - } - byte level = (options.valuesSet & EventSourceOptions.levelSet) != 0 - ? options.level - : eventTypes.level; - EventKeywords keywords = (options.valuesSet & EventSourceOptions.keywordsSet) != 0 - ? options.keywords - : eventTypes.keywords; - - if (this.IsEnabled((EventLevel)level, keywords)) + m_activeWritesCount++; + if (this.IsEnabled()) { - m_activeWritesCount++; - WriteMultiMergeInner(eventName, ref options, eventTypes, activityID, childActivityID, values); - m_activeWritesCount--; + try + { + byte level = (options.valuesSet & EventSourceOptions.levelSet) != 0 + ? options.level + : eventTypes.level; + EventKeywords keywords = (options.valuesSet & EventSourceOptions.keywordsSet) != 0 + ? options.keywords + : eventTypes.keywords; + + if (this.IsEnabled((EventLevel)level, keywords)) + { + WriteMultiMergeInner(eventName, ref options, eventTypes, activityID, childActivityID, values); + } + } + finally + { + m_activeWritesCount--; + } } } @@ -552,70 +557,73 @@ internal unsafe void WriteMultiMerge( EventData* data) { #if FEATURE_MANAGED_ETW - if (!this.IsEnabled()) - { - return; - } - m_activeWritesCount++; - - fixed (EventSourceOptions* pOptions = &options) + if (this.IsEnabled()) { - NameInfo? nameInfo = this.UpdateDescriptor(eventName, eventTypes, ref options, out EventDescriptor descriptor); - if (nameInfo == null) + try { - return; - } + fixed (EventSourceOptions* pOptions = &options) + { + NameInfo? nameInfo = this.UpdateDescriptor(eventName, eventTypes, ref options, out EventDescriptor descriptor); + if (nameInfo == null) + { + return; + } #if FEATURE_PERFTRACING - IntPtr eventHandle = nameInfo.GetOrCreateEventHandle(m_eventPipeProvider, m_eventHandleTable, descriptor, eventTypes); - Debug.Assert(eventHandle != IntPtr.Zero); + IntPtr eventHandle = nameInfo.GetOrCreateEventHandle(m_eventPipeProvider, m_eventHandleTable, descriptor, eventTypes); + Debug.Assert(eventHandle != IntPtr.Zero); #else - IntPtr eventHandle = IntPtr.Zero; + IntPtr eventHandle = IntPtr.Zero; #endif - // We make a descriptor for each EventData, and because we morph strings to counted strings - // we may have 2 for each arg, so we allocate enough for this. - int descriptorsLength = eventTypes.dataCount + eventTypes.typeInfos.Length * 2 + 3; - EventData* descriptors = stackalloc EventData[descriptorsLength]; - for (int i = 0; i < descriptorsLength; i++) - descriptors[i] = default; - - var providerMetadata = ProviderMetadata; - fixed (byte* - pMetadata0 = providerMetadata, - pMetadata1 = nameInfo.nameMetadata, - pMetadata2 = eventTypes.typeMetadata) - { - descriptors[0].SetMetadata(pMetadata0, providerMetadata.Length, 2); - descriptors[1].SetMetadata(pMetadata1, nameInfo.nameMetadata.Length, 1); - descriptors[2].SetMetadata(pMetadata2, eventTypes.typeMetadata.Length, 1); - int numDescrs = 3; + // We make a descriptor for each EventData, and because we morph strings to counted strings + // we may have 2 for each arg, so we allocate enough for this. + int descriptorsLength = eventTypes.dataCount + eventTypes.typeInfos.Length * 2 + 3; + EventData* descriptors = stackalloc EventData[descriptorsLength]; + for (int i = 0; i < descriptorsLength; i++) + descriptors[i] = default; + + var providerMetadata = ProviderMetadata; + fixed (byte* + pMetadata0 = providerMetadata, + pMetadata1 = nameInfo.nameMetadata, + pMetadata2 = eventTypes.typeMetadata) + { + descriptors[0].SetMetadata(pMetadata0, providerMetadata.Length, 2); + descriptors[1].SetMetadata(pMetadata1, nameInfo.nameMetadata.Length, 1); + descriptors[2].SetMetadata(pMetadata2, eventTypes.typeMetadata.Length, 1); + int numDescrs = 3; - for (int i = 0; i < eventTypes.typeInfos.Length; i++) - { - descriptors[numDescrs].m_Ptr = data[i].m_Ptr; - descriptors[numDescrs].m_Size = data[i].m_Size; + for (int i = 0; i < eventTypes.typeInfos.Length; i++) + { + descriptors[numDescrs].m_Ptr = data[i].m_Ptr; + descriptors[numDescrs].m_Size = data[i].m_Size; - // old conventions for bool is 4 bytes, but meta-data assumes 1. - if (data[i].m_Size == 4 && eventTypes.typeInfos[i].DataType == typeof(bool)) - descriptors[numDescrs].m_Size = 1; + // old conventions for bool is 4 bytes, but meta-data assumes 1. + if (data[i].m_Size == 4 && eventTypes.typeInfos[i].DataType == typeof(bool)) + descriptors[numDescrs].m_Size = 1; - numDescrs++; - } + numDescrs++; + } - this.WriteEventRaw( - eventName, - ref descriptor, - eventHandle, - activityID, - childActivityID, - numDescrs, - (IntPtr)descriptors); + this.WriteEventRaw( + eventName, + ref descriptor, + eventHandle, + activityID, + childActivityID, + numDescrs, + (IntPtr)descriptors); + } + } + } + finally + { + m_activeWritesCount--; } } - m_activeWritesCount--; #endif // FEATURE_MANAGED_ETW } @@ -627,130 +635,133 @@ private unsafe void WriteImpl( Guid* pRelatedActivityId, TraceLoggingEventTypes eventTypes) { - try + m_activeWritesCount++; + if (IsEnabled()) { - m_activeWritesCount++; - fixed (EventSourceOptions* pOptions = &options) + try { - options.Opcode = options.IsOpcodeSet ? options.Opcode : GetOpcodeWithDefault(options.Opcode, eventName); - NameInfo? nameInfo = this.UpdateDescriptor(eventName, eventTypes, ref options, out EventDescriptor descriptor); - if (nameInfo == null) - { - return; - } - -#if FEATURE_PERFTRACING - IntPtr eventHandle = nameInfo.GetOrCreateEventHandle(m_eventPipeProvider, m_eventHandleTable, descriptor, eventTypes); - Debug.Assert(eventHandle != IntPtr.Zero); -#else - IntPtr eventHandle = IntPtr.Zero; -#endif - -#if FEATURE_MANAGED_ETW - int pinCount = eventTypes.pinCount; - byte* scratch = stackalloc byte[eventTypes.scratchSize]; - EventData* descriptors = stackalloc EventData[eventTypes.dataCount + 3]; - for (int i = 0; i < eventTypes.dataCount + 3; i++) - descriptors[i] = default; - - GCHandle* pins = stackalloc GCHandle[pinCount]; - for (int i = 0; i < pinCount; i++) - pins[i] = default; - - var providerMetadata = ProviderMetadata; - fixed (byte* - pMetadata0 = providerMetadata, - pMetadata1 = nameInfo.nameMetadata, - pMetadata2 = eventTypes.typeMetadata) + fixed (EventSourceOptions* pOptions = &options) { - descriptors[0].SetMetadata(pMetadata0, providerMetadata.Length, 2); - descriptors[1].SetMetadata(pMetadata1, nameInfo.nameMetadata.Length, 1); - descriptors[2].SetMetadata(pMetadata2, eventTypes.typeMetadata.Length, 1); -#endif // FEATURE_MANAGED_ETW - -#if ES_BUILD_STANDALONE - System.Runtime.CompilerServices.RuntimeHelpers.PrepareConstrainedRegions(); -#endif - EventOpcode opcode = (EventOpcode)descriptor.Opcode; + options.Opcode = options.IsOpcodeSet ? options.Opcode : GetOpcodeWithDefault(options.Opcode, eventName); + NameInfo? nameInfo = this.UpdateDescriptor(eventName, eventTypes, ref options, out EventDescriptor descriptor); + if (nameInfo == null) + { + return; + } - Guid activityId = Guid.Empty; - Guid relatedActivityId = Guid.Empty; - if (pActivityId == null && pRelatedActivityId == null && - ((options.ActivityOptions & EventActivityOptions.Disable) == 0)) + #if FEATURE_PERFTRACING + IntPtr eventHandle = nameInfo.GetOrCreateEventHandle(m_eventPipeProvider, m_eventHandleTable, descriptor, eventTypes); + Debug.Assert(eventHandle != IntPtr.Zero); + #else + IntPtr eventHandle = IntPtr.Zero; + #endif + + #if FEATURE_MANAGED_ETW + int pinCount = eventTypes.pinCount; + byte* scratch = stackalloc byte[eventTypes.scratchSize]; + EventData* descriptors = stackalloc EventData[eventTypes.dataCount + 3]; + for (int i = 0; i < eventTypes.dataCount + 3; i++) + descriptors[i] = default; + + GCHandle* pins = stackalloc GCHandle[pinCount]; + for (int i = 0; i < pinCount; i++) + pins[i] = default; + + var providerMetadata = ProviderMetadata; + fixed (byte* + pMetadata0 = providerMetadata, + pMetadata1 = nameInfo.nameMetadata, + pMetadata2 = eventTypes.typeMetadata) { - if (opcode == EventOpcode.Start) + descriptors[0].SetMetadata(pMetadata0, providerMetadata.Length, 2); + descriptors[1].SetMetadata(pMetadata1, nameInfo.nameMetadata.Length, 1); + descriptors[2].SetMetadata(pMetadata2, eventTypes.typeMetadata.Length, 1); + #endif // FEATURE_MANAGED_ETW + + #if ES_BUILD_STANDALONE + System.Runtime.CompilerServices.RuntimeHelpers.PrepareConstrainedRegions(); + #endif + EventOpcode opcode = (EventOpcode)descriptor.Opcode; + + Guid activityId = Guid.Empty; + Guid relatedActivityId = Guid.Empty; + if (pActivityId == null && pRelatedActivityId == null && + ((options.ActivityOptions & EventActivityOptions.Disable) == 0)) { - Debug.Assert(eventName != null, "GetOpcodeWithDefault should not returned Start when eventName is null"); - m_activityTracker.OnStart(m_name, eventName, 0, ref activityId, ref relatedActivityId, options.ActivityOptions); + if (opcode == EventOpcode.Start) + { + Debug.Assert(eventName != null, "GetOpcodeWithDefault should not returned Start when eventName is null"); + m_activityTracker.OnStart(m_name, eventName, 0, ref activityId, ref relatedActivityId, options.ActivityOptions); + } + else if (opcode == EventOpcode.Stop) + { + Debug.Assert(eventName != null, "GetOpcodeWithDefault should not returned Stop when eventName is null"); + m_activityTracker.OnStop(m_name, eventName, 0, ref activityId); + } + if (activityId != Guid.Empty) + pActivityId = &activityId; + if (relatedActivityId != Guid.Empty) + pRelatedActivityId = &relatedActivityId; } - else if (opcode == EventOpcode.Stop) + + try { - Debug.Assert(eventName != null, "GetOpcodeWithDefault should not returned Stop when eventName is null"); - m_activityTracker.OnStop(m_name, eventName, 0, ref activityId); + #if FEATURE_MANAGED_ETW + DataCollector.ThreadInstance.Enable( + scratch, + eventTypes.scratchSize, + descriptors + 3, + eventTypes.dataCount, + pins, + pinCount); + + TraceLoggingTypeInfo info = eventTypes.typeInfos[0]; + info.WriteData(info.PropertyValueFactory(data)); + + this.WriteEventRaw( + eventName, + ref descriptor, + eventHandle, + pActivityId, + pRelatedActivityId, + (int)(DataCollector.ThreadInstance.Finish() - descriptors), + (IntPtr)descriptors); + #endif // FEATURE_MANAGED_ETW + + // TODO enable filtering for listeners. + if (m_Dispatchers != null) + { + var eventData = (EventPayload?)(eventTypes.typeInfos[0].GetData(data)); + WriteToAllListeners(eventName, ref descriptor, nameInfo.tags, pActivityId, pRelatedActivityId, eventData); + } } - if (activityId != Guid.Empty) - pActivityId = &activityId; - if (relatedActivityId != Guid.Empty) - pRelatedActivityId = &relatedActivityId; - } - - try - { -#if FEATURE_MANAGED_ETW - DataCollector.ThreadInstance.Enable( - scratch, - eventTypes.scratchSize, - descriptors + 3, - eventTypes.dataCount, - pins, - pinCount); - - TraceLoggingTypeInfo info = eventTypes.typeInfos[0]; - info.WriteData(info.PropertyValueFactory(data)); - - this.WriteEventRaw( - eventName, - ref descriptor, - eventHandle, - pActivityId, - pRelatedActivityId, - (int)(DataCollector.ThreadInstance.Finish() - descriptors), - (IntPtr)descriptors); -#endif // FEATURE_MANAGED_ETW - - // TODO enable filtering for listeners. - if (m_Dispatchers != null) + catch (Exception ex) { - var eventData = (EventPayload?)(eventTypes.typeInfos[0].GetData(data)); - WriteToAllListeners(eventName, ref descriptor, nameInfo.tags, pActivityId, pRelatedActivityId, eventData); + if (ex is EventSourceException) + throw; + else + ThrowEventSourceException(eventName, ex); + } + #if FEATURE_MANAGED_ETW + finally + { + WriteCleanup(pins, pinCount); } } - catch (Exception ex) - { - if (ex is EventSourceException) - throw; - else - ThrowEventSourceException(eventName, ex); - } -#if FEATURE_MANAGED_ETW - finally - { - WriteCleanup(pins, pinCount); - } + #endif // FEATURE_MANAGED_ETW } -#endif // FEATURE_MANAGED_ETW } - } - catch (Exception ex) - { - if (ex is EventSourceException) - throw; - else - ThrowEventSourceException(eventName, ex); - } - finally - { - m_activeWritesCount--; + catch (Exception ex) + { + if (ex is EventSourceException) + throw; + else + ThrowEventSourceException(eventName, ex); + } + finally + { + m_activeWritesCount--; + } } } From 0f7a8b93088084b02188d28abc2794f322617e94 Mon Sep 17 00:00:00 2001 From: John Salem Date: Mon, 19 Jul 2021 17:05:21 -0700 Subject: [PATCH 4/5] Switch to interlocked.incr/decr --- .../System/Diagnostics/Tracing/EventSource.cs | 16 ++++++++++------ .../TraceLogging/TraceLoggingEventSource.cs | 12 ++++++------ 2 files changed, 16 insertions(+), 12 deletions(-) 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 1c771881657683..7117508466612b 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 @@ -1302,7 +1302,7 @@ protected unsafe void WriteEventCore(int eventId, int eventDataCount, EventSourc [CLSCompliant(false)] protected unsafe void WriteEventWithRelatedActivityIdCore(int eventId, Guid* relatedActivityId, int eventDataCount, EventSource.EventData* data) { - m_activeWritesCount++; + WriteGuardEnter(); if (IsEnabled()) { Debug.Assert(m_eventData != null); // You must have initialized this if you enabled the source. @@ -1383,7 +1383,7 @@ protected unsafe void WriteEventWithRelatedActivityIdCore(int eventId, Guid* rel } finally { - m_activeWritesCount--; + WriteGuardExit(); } } } @@ -1465,7 +1465,8 @@ protected virtual void Dispose(bool disposing) // Wait till active writes have finished (stop waiting at 1 second) // TODO: determine appropriate break out mechanism. Is 1 second appropriate? Is a timeout appropriate at all? - SpinWait.SpinUntil(() => m_activeWritesCount == 0, 1000); + // TODO: use Volatile.Read instead? It's an int, so we shouldn't get tearing. + SpinWait.SpinUntil(() => Interlocked.CompareExchange(ref m_activeWritesCount, 0, 0) == 0, 1000); if (m_etwProvider != null) { @@ -1902,7 +1903,7 @@ private static unsafe void AssertValidString(EventData* data) #endif private unsafe void WriteEventVarargs(int eventId, Guid* childActivityID, object?[] args) { - m_activeWritesCount++; + WriteGuardEnter(); if (IsEnabled()) { Debug.Assert(m_eventData != null); // You must have initialized this if you enabled the source. @@ -2009,7 +2010,7 @@ private unsafe void WriteEventVarargs(int eventId, Guid* childActivityID, object } finally { - m_activeWritesCount--; + WriteGuardExit(); } } } @@ -3853,6 +3854,9 @@ private bool SelfDescribingEvents } } + private void WriteGuardEnter() => Interlocked.Increment(ref m_activeWritesCount); + private void WriteGuardExit() => Interlocked.Decrement(ref m_activeWritesCount); + // private instance state private string m_name = null!; // My friendly name (privided in ctor) internal int m_id; // A small integer that is unique to this instance. @@ -3870,7 +3874,7 @@ private bool SelfDescribingEvents private volatile bool m_eventSourceEnabled; // am I enabled (any of my events are enabled for any dispatcher) internal EventLevel m_level; // highest level enabled by any output dispatcher internal EventKeywords m_matchAnyKeyword; // the logical OR of all levels enabled by any output dispatcher (zero is a special case) meaning 'all keywords' - private volatile int m_activeWritesCount; // The number of currently active calls to Write methods that have already checked m_eventSourceEnabled + private int m_activeWritesCount; // The number of currently active calls to Write methods that have already checked m_eventSourceEnabled // Dispatching state internal volatile EventDispatcher? m_Dispatchers; // Linked list of code:EventDispatchers we write the data to (we also do ETW specially) diff --git a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/TraceLogging/TraceLoggingEventSource.cs b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/TraceLogging/TraceLoggingEventSource.cs index e133c06d835f99..4057c93637a50d 100644 --- a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/TraceLogging/TraceLoggingEventSource.cs +++ b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/TraceLogging/TraceLoggingEventSource.cs @@ -365,7 +365,7 @@ private unsafe void WriteMultiMerge( Guid* childActivityID, params object?[] values) { - m_activeWritesCount++; + WriteGuardEnter(); if (this.IsEnabled()) { try @@ -384,7 +384,7 @@ private unsafe void WriteMultiMerge( } finally { - m_activeWritesCount--; + WriteGuardExit(); } } } @@ -557,7 +557,7 @@ internal unsafe void WriteMultiMerge( EventData* data) { #if FEATURE_MANAGED_ETW - m_activeWritesCount++; + WriteGuardEnter(); if (this.IsEnabled()) { try @@ -620,7 +620,7 @@ internal unsafe void WriteMultiMerge( } finally { - m_activeWritesCount--; + WriteGuardExit(); } } @@ -635,7 +635,7 @@ private unsafe void WriteImpl( Guid* pRelatedActivityId, TraceLoggingEventTypes eventTypes) { - m_activeWritesCount++; + WriteGuardEnter(); if (IsEnabled()) { try @@ -760,7 +760,7 @@ private unsafe void WriteImpl( } finally { - m_activeWritesCount--; + WriteGuardExit(); } } } From 172547982f5481f1f79995616d0cbdd7e6b95b44 Mon Sep 17 00:00:00 2001 From: John Salem Date: Fri, 23 Jul 2021 12:19:22 -0700 Subject: [PATCH 5/5] switch to a using statement with a ref struct --- .../System/Diagnostics/Tracing/EventSource.cs | 30 ++-- .../TraceLogging/TraceLoggingEventSource.cs | 144 ++++++++---------- 2 files changed, 83 insertions(+), 91 deletions(-) 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 7117508466612b..6ea88e9fa0ef4c 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 @@ -1302,7 +1302,7 @@ protected unsafe void WriteEventCore(int eventId, int eventDataCount, EventSourc [CLSCompliant(false)] protected unsafe void WriteEventWithRelatedActivityIdCore(int eventId, Guid* relatedActivityId, int eventDataCount, EventSource.EventData* data) { - WriteGuardEnter(); + using var writeGuard = new WriteGuard(this); if (IsEnabled()) { Debug.Assert(m_eventData != null); // You must have initialized this if you enabled the source. @@ -1381,10 +1381,6 @@ protected unsafe void WriteEventWithRelatedActivityIdCore(int eventId, Guid* rel else ThrowEventSourceException(m_eventData[eventId].Name, ex); } - finally - { - WriteGuardExit(); - } } } @@ -1903,7 +1899,7 @@ private static unsafe void AssertValidString(EventData* data) #endif private unsafe void WriteEventVarargs(int eventId, Guid* childActivityID, object?[] args) { - WriteGuardEnter(); + using var writeGuard = new WriteGuard(this); if (IsEnabled()) { Debug.Assert(m_eventData != null); // You must have initialized this if you enabled the source. @@ -2008,10 +2004,6 @@ private unsafe void WriteEventVarargs(int eventId, Guid* childActivityID, object else ThrowEventSourceException(m_eventData[eventId].Name, ex); } - finally - { - WriteGuardExit(); - } } } @@ -3854,8 +3846,22 @@ private bool SelfDescribingEvents } } - private void WriteGuardEnter() => Interlocked.Increment(ref m_activeWritesCount); - private void WriteGuardExit() => Interlocked.Decrement(ref m_activeWritesCount); + // Helper class for guarding writes to prevent Dispose from happening while we are writing + private ref struct WriteGuard + { + private EventSource _source; + + public WriteGuard(EventSource source) + { + _source = source; + Interlocked.Increment(ref _source.m_activeWritesCount); + } + + public void Dispose() + { + Interlocked.Decrement(ref _source.m_activeWritesCount); + } + } // private instance state private string m_name = null!; // My friendly name (privided in ctor) diff --git a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/TraceLogging/TraceLoggingEventSource.cs b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/TraceLogging/TraceLoggingEventSource.cs index 4057c93637a50d..f23134ca9276d3 100644 --- a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/TraceLogging/TraceLoggingEventSource.cs +++ b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/TraceLogging/TraceLoggingEventSource.cs @@ -365,27 +365,23 @@ private unsafe void WriteMultiMerge( Guid* childActivityID, params object?[] values) { - WriteGuardEnter(); - if (this.IsEnabled()) + using var writeGuard = new WriteGuard(this); + + if (!this.IsEnabled()) { - try - { - byte level = (options.valuesSet & EventSourceOptions.levelSet) != 0 - ? options.level - : eventTypes.level; - EventKeywords keywords = (options.valuesSet & EventSourceOptions.keywordsSet) != 0 - ? options.keywords - : eventTypes.keywords; - - if (this.IsEnabled((EventLevel)level, keywords)) - { - WriteMultiMergeInner(eventName, ref options, eventTypes, activityID, childActivityID, values); - } - } - finally - { - WriteGuardExit(); - } + return; + } + + byte level = (options.valuesSet & EventSourceOptions.levelSet) != 0 + ? options.level + : eventTypes.level; + EventKeywords keywords = (options.valuesSet & EventSourceOptions.keywordsSet) != 0 + ? options.keywords + : eventTypes.keywords; + + if (this.IsEnabled((EventLevel)level, keywords)) + { + WriteMultiMergeInner(eventName, ref options, eventTypes, activityID, childActivityID, values); } } @@ -557,73 +553,67 @@ internal unsafe void WriteMultiMerge( EventData* data) { #if FEATURE_MANAGED_ETW - WriteGuardEnter(); - if (this.IsEnabled()) + using var writeGuard = new WriteGuard(this); + if (!this.IsEnabled()) { - try + return; + } + + fixed (EventSourceOptions* pOptions = &options) + { + NameInfo? nameInfo = this.UpdateDescriptor(eventName, eventTypes, ref options, out EventDescriptor descriptor); + if (nameInfo == null) { - fixed (EventSourceOptions* pOptions = &options) - { - NameInfo? nameInfo = this.UpdateDescriptor(eventName, eventTypes, ref options, out EventDescriptor descriptor); - if (nameInfo == null) - { - return; - } + return; + } #if FEATURE_PERFTRACING - IntPtr eventHandle = nameInfo.GetOrCreateEventHandle(m_eventPipeProvider, m_eventHandleTable, descriptor, eventTypes); - Debug.Assert(eventHandle != IntPtr.Zero); + IntPtr eventHandle = nameInfo.GetOrCreateEventHandle(m_eventPipeProvider, m_eventHandleTable, descriptor, eventTypes); + Debug.Assert(eventHandle != IntPtr.Zero); #else - IntPtr eventHandle = IntPtr.Zero; + IntPtr eventHandle = IntPtr.Zero; #endif - // We make a descriptor for each EventData, and because we morph strings to counted strings - // we may have 2 for each arg, so we allocate enough for this. - int descriptorsLength = eventTypes.dataCount + eventTypes.typeInfos.Length * 2 + 3; - EventData* descriptors = stackalloc EventData[descriptorsLength]; - for (int i = 0; i < descriptorsLength; i++) - descriptors[i] = default; - - var providerMetadata = ProviderMetadata; - fixed (byte* - pMetadata0 = providerMetadata, - pMetadata1 = nameInfo.nameMetadata, - pMetadata2 = eventTypes.typeMetadata) - { - descriptors[0].SetMetadata(pMetadata0, providerMetadata.Length, 2); - descriptors[1].SetMetadata(pMetadata1, nameInfo.nameMetadata.Length, 1); - descriptors[2].SetMetadata(pMetadata2, eventTypes.typeMetadata.Length, 1); - int numDescrs = 3; - - for (int i = 0; i < eventTypes.typeInfos.Length; i++) - { - descriptors[numDescrs].m_Ptr = data[i].m_Ptr; - descriptors[numDescrs].m_Size = data[i].m_Size; + // We make a descriptor for each EventData, and because we morph strings to counted strings + // we may have 2 for each arg, so we allocate enough for this. + int descriptorsLength = eventTypes.dataCount + eventTypes.typeInfos.Length * 2 + 3; + EventData* descriptors = stackalloc EventData[descriptorsLength]; + for (int i = 0; i < descriptorsLength; i++) + descriptors[i] = default; + + var providerMetadata = ProviderMetadata; + fixed (byte* + pMetadata0 = providerMetadata, + pMetadata1 = nameInfo.nameMetadata, + pMetadata2 = eventTypes.typeMetadata) + { + descriptors[0].SetMetadata(pMetadata0, providerMetadata.Length, 2); + descriptors[1].SetMetadata(pMetadata1, nameInfo.nameMetadata.Length, 1); + descriptors[2].SetMetadata(pMetadata2, eventTypes.typeMetadata.Length, 1); + int numDescrs = 3; - // old conventions for bool is 4 bytes, but meta-data assumes 1. - if (data[i].m_Size == 4 && eventTypes.typeInfos[i].DataType == typeof(bool)) - descriptors[numDescrs].m_Size = 1; + for (int i = 0; i < eventTypes.typeInfos.Length; i++) + { + descriptors[numDescrs].m_Ptr = data[i].m_Ptr; + descriptors[numDescrs].m_Size = data[i].m_Size; - numDescrs++; - } + // old conventions for bool is 4 bytes, but meta-data assumes 1. + if (data[i].m_Size == 4 && eventTypes.typeInfos[i].DataType == typeof(bool)) + descriptors[numDescrs].m_Size = 1; - this.WriteEventRaw( - eventName, - ref descriptor, - eventHandle, - activityID, - childActivityID, - numDescrs, - (IntPtr)descriptors); - } + numDescrs++; } - } - finally - { - WriteGuardExit(); + + this.WriteEventRaw( + eventName, + ref descriptor, + eventHandle, + activityID, + childActivityID, + numDescrs, + (IntPtr)descriptors); } } - #endif // FEATURE_MANAGED_ETW } @@ -635,7 +625,7 @@ private unsafe void WriteImpl( Guid* pRelatedActivityId, TraceLoggingEventTypes eventTypes) { - WriteGuardEnter(); + using var writeGuard = new WriteGuard(this); if (IsEnabled()) { try @@ -758,10 +748,6 @@ private unsafe void WriteImpl( else ThrowEventSourceException(eventName, ex); } - finally - { - WriteGuardExit(); - } } }