From 9c2e4ee0757c4f44b924ee39e06a91ee1bc281b4 Mon Sep 17 00:00:00 2001 From: David Mason Date: Wed, 26 Jul 2023 22:44:40 -0700 Subject: [PATCH 1/6] Update EventPipeEventDispatcher.cs --- .../src/Resources/Strings.resx | 3 + .../Tracing/EventPipeEventDispatcher.cs | 108 +++++++++--------- .../System/Diagnostics/Tracing/EventSource.cs | 11 +- 3 files changed, 66 insertions(+), 56 deletions(-) diff --git a/src/libraries/System.Private.CoreLib/src/Resources/Strings.resx b/src/libraries/System.Private.CoreLib/src/Resources/Strings.resx index bd016b716a1617..4ca876bfecbbe8 100644 --- a/src/libraries/System.Private.CoreLib/src/Resources/Strings.resx +++ b/src/libraries/System.Private.CoreLib/src/Resources/Strings.resx @@ -2075,6 +2075,9 @@ Channel {0} does not match event channel value {1}. + + Failed to open an EventPipe session for NativeRuntimeEventSource. + Data descriptors are out of range. diff --git a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventDispatcher.cs b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventDispatcher.cs index c9daf4e6cd2f3c..1ca30d8892aa79 100644 --- a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventDispatcher.cs +++ b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventDispatcher.cs @@ -27,12 +27,10 @@ internal EventListenerSubscription(EventKeywords matchAnyKeywords, EventLevel le private readonly IntPtr m_RuntimeProviderID; private ulong m_sessionID; - private DateTime m_syncTimeUtc; - private long m_syncTimeQPC; - private long m_timeQPCFrequency; private bool m_stopDispatchTask; private Task? m_dispatchTask; + private ManualResetEvent m_stoppedEvent = new ManualResetEvent(true); private readonly object m_dispatchControlLock = new object(); private readonly Dictionary m_subscriptions = new Dictionary(); @@ -46,35 +44,39 @@ private EventPipeEventDispatcher() internal void SendCommand(EventListener eventListener, EventCommand command, bool enable, EventLevel level, EventKeywords matchAnyKeywords) { - lock (EventListener.EventListenersLock) + while (true) { - if (command == EventCommand.Update && enable) + if (m_stopDispatchTask) { - lock (m_dispatchControlLock) + m_stoppedEvent.WaitOne(); + } + + lock (m_dispatchControlLock) + { + if (m_stopDispatchTask) + { + // We happened to end up here after the task was marked as stopping, give up the lock and try again later + continue; + } + + Debug.Assert(!m_stopDispatchTask); + if (command == EventCommand.Update && enable) { // Add the new subscription. This will overwrite an existing subscription for the listener if one exists. m_subscriptions[eventListener] = new EventListenerSubscription(matchAnyKeywords, level); - - // Commit the configuration change. - CommitDispatchConfiguration(); } - } - else if (command == EventCommand.Update && !enable) - { - RemoveEventListener(eventListener); - } - } - } + else if (command == EventCommand.Update && !enable) + { + // Remove the event listener from the list of subscribers. + m_subscriptions.Remove(eventListener); + } - internal void RemoveEventListener(EventListener listener) - { - lock (m_dispatchControlLock) - { - // Remove the event listener from the list of subscribers. - m_subscriptions.Remove(listener); + // Commit the configuration change. + CommitDispatchConfiguration(); - // Commit the configuration change. - CommitDispatchConfiguration(); + // We were successful, break out of the loop + break; + } } } @@ -82,13 +84,8 @@ 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(m_sessionID); + // Signal that the thread should shut down + SetStopDispatchTask(); // Check to see if tracing should be enabled. if (m_subscriptions.Count <= 0) @@ -122,7 +119,10 @@ private void CommitDispatchConfiguration() }; m_sessionID = EventPipeInternal.Enable(null, EventPipeSerializationFormat.NetTrace, DefaultEventListenerCircularMBSize, providerConfiguration); - Debug.Assert(m_sessionID != 0); + if (m_sessionID == 0) + { + throw new EventSourceException(SR.EventSource_CouldNotEnableEventPipe); + } // Get the session information that is required to properly dispatch events. EventPipeSessionInfo sessionInfo; @@ -134,39 +134,37 @@ private void CommitDispatchConfiguration() } } - m_syncTimeUtc = DateTime.FromFileTimeUtc(sessionInfo.StartTimeAsUTCFileTime); - m_syncTimeQPC = sessionInfo.StartTimeStamp; - m_timeQPCFrequency = sessionInfo.TimeStampFrequency; + + DateTime syncTimeUtc = DateTime.FromFileTimeUtc(sessionInfo.StartTimeAsUTCFileTime); + long syncTimeQPC = sessionInfo.StartTimeStamp; + long timeQPCFrequency = sessionInfo.TimeStampFrequency; // Start the dispatch task. - StartDispatchTask(); + StartDispatchTask(m_sessionID, syncTimeUtc, syncTimeQPC, timeQPCFrequency); } - private void StartDispatchTask() + private void StartDispatchTask(ulong sessionID, DateTime syncTimeUtc, long syncTimeQPC, long timeQPCFrequency) { Debug.Assert(Monitor.IsEntered(m_dispatchControlLock)); + Debug.Assert(m_dispatchTask == null); + Debug.Assert(m_stopDispatchTask == false); - if (m_dispatchTask == null) - { - m_stopDispatchTask = false; - m_dispatchTask = Task.Factory.StartNew(DispatchEventsToEventListeners, CancellationToken.None, TaskCreationOptions.LongRunning, TaskScheduler.Default); - } + m_dispatchTask = Task.Factory.StartNew(() => DispatchEventsToEventListeners(sessionID, syncTimeUtc, syncTimeQPC, timeQPCFrequency), CancellationToken.None, TaskCreationOptions.LongRunning, TaskScheduler.Default); } - private void StopDispatchTask() + private void SetStopDispatchTask() { Debug.Assert(Monitor.IsEntered(m_dispatchControlLock)); if (m_dispatchTask != null) { + m_stoppedEvent.Reset(); m_stopDispatchTask = true; EventPipeInternal.SignalSession(m_sessionID); - m_dispatchTask.Wait(); - m_dispatchTask = null; } } - private unsafe void DispatchEventsToEventListeners() + private unsafe void DispatchEventsToEventListeners(ulong sessionID, DateTime syncTimeUtc, long syncTimeQPC, long timeQPCFrequency) { // Struct to fill with the call to GetNextEvent. EventPipeEventInstanceData instanceData; @@ -175,7 +173,7 @@ private unsafe void DispatchEventsToEventListeners() { bool eventsReceived = false; // Get the next event. - while (!m_stopDispatchTask && EventPipeInternal.GetNextEvent(m_sessionID, &instanceData)) + while (!m_stopDispatchTask && EventPipeInternal.GetNextEvent(sessionID, &instanceData)) { eventsReceived = true; @@ -184,7 +182,7 @@ private unsafe void DispatchEventsToEventListeners() { // Dispatch the event. ReadOnlySpan payload = new ReadOnlySpan((void*)instanceData.Payload, (int)instanceData.PayloadLength); - DateTime dateTimeStamp = TimeStampToDateTime(instanceData.TimeStamp); + DateTime dateTimeStamp = TimeStampToDateTime(instanceData.TimeStamp, syncTimeUtc, syncTimeQPC, timeQPCFrequency); NativeRuntimeEventSource.Log.ProcessEvent(instanceData.EventID, instanceData.ThreadID, dateTimeStamp, instanceData.ActivityId, instanceData.ChildActivityId, payload); } } @@ -200,20 +198,28 @@ private unsafe void DispatchEventsToEventListeners() Thread.Sleep(10); } } + + m_dispatchTask = null; + m_stopDispatchTask = false; + // Signal to threads that they can stop waiting since we are done + m_stoppedEvent.Set(); + + // Disable the old session. This can happen asynchronously since we aren't using the old session anymore + EventPipeInternal.Disable(sessionID); } /// /// Converts a QueryPerformanceCounter (QPC) timestamp to a UTC DateTime. /// - private DateTime TimeStampToDateTime(long timeStamp) + private static DateTime TimeStampToDateTime(long timeStamp, DateTime syncTimeUtc, long syncTimeQPC, long timeQPCFrequency) { if (timeStamp == long.MaxValue) { return DateTime.MaxValue; } - Debug.Assert((m_syncTimeUtc.Ticks != 0) && (m_syncTimeQPC != 0) && (m_timeQPCFrequency != 0)); - long inTicks = (long)((timeStamp - m_syncTimeQPC) * 10000000.0 / m_timeQPCFrequency) + m_syncTimeUtc.Ticks; + Debug.Assert((syncTimeUtc.Ticks != 0) && (syncTimeQPC != 0) && (timeQPCFrequency != 0)); + long inTicks = (long)((timeStamp - syncTimeQPC) * 10000000.0 / timeQPCFrequency) + syncTimeUtc.Ticks; if ((inTicks < 0) || (DateTime.MaxTicks < inTicks)) { inTicks = DateTime.MaxTicks; 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 d9fa4d943bf2aa..8cfe030639dd12 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 @@ -4075,6 +4075,12 @@ public virtual void Dispose() } Validate(); } + +#if FEATURE_PERFTRACING + // Remove the listener from the EventPipe dispatcher. EventCommand.Update with enable==false removes it. + // Have to send outside of EventListenersLock, or we risk deadlocks. + EventPipeEventDispatcher.Instance.SendCommand(this, EventCommand.Update, false, EventLevel.LogAlways, (EventKeywords)0); +#endif // FEATURE_PERFTRACING } // We don't expose a Dispose(bool), because the contract is that you don't have any non-syncronous // 'cleanup' associated with this object @@ -4391,11 +4397,6 @@ private static void RemoveReferencesToListenerInEventSources(EventListener liste } } } - -#if FEATURE_PERFTRACING - // Remove the listener from the EventPipe dispatcher. - EventPipeEventDispatcher.Instance.RemoveEventListener(listenerToRemove); -#endif // FEATURE_PERFTRACING } From 375238255b749998cd800fcccb7e45be0bf36665 Mon Sep 17 00:00:00 2001 From: David Mason Date: Thu, 10 Aug 2023 13:47:33 -0700 Subject: [PATCH 2/6] Code review feedback --- .../Tracing/EventPipeEventDispatcher.cs | 70 +++++++------------ 1 file changed, 25 insertions(+), 45 deletions(-) diff --git a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventDispatcher.cs b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventDispatcher.cs index 1ca30d8892aa79..60cdc2617810fb 100644 --- a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventDispatcher.cs +++ b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventDispatcher.cs @@ -28,9 +28,12 @@ internal EventListenerSubscription(EventKeywords matchAnyKeywords, EventLevel le private ulong m_sessionID; - private bool m_stopDispatchTask; + private CancellationTokenSource? m_dispatchTaskCancellationSource; private Task? m_dispatchTask; - private ManualResetEvent m_stoppedEvent = new ManualResetEvent(true); + + // We take this lock to synchronize access to the shared session state. It is important to never take the EventSource.EventListenersLock while + // holding this, or we can deadlock. Unfortunately calling in to EventSource at all can take the EventListenersLock in ways that are not obvious, + // so don't call in to EventSource or other EventListeners while holding this unless you are certain it can't take the EventListenersLock. private readonly object m_dispatchControlLock = new object(); private readonly Dictionary m_subscriptions = new Dictionary(); @@ -44,39 +47,21 @@ private EventPipeEventDispatcher() internal void SendCommand(EventListener eventListener, EventCommand command, bool enable, EventLevel level, EventKeywords matchAnyKeywords) { - while (true) + lock (m_dispatchControlLock) { - if (m_stopDispatchTask) + if (command == EventCommand.Update && enable) { - m_stoppedEvent.WaitOne(); + // Add the new subscription. This will overwrite an existing subscription for the listener if one exists. + m_subscriptions[eventListener] = new EventListenerSubscription(matchAnyKeywords, level); } - - lock (m_dispatchControlLock) + else if (command == EventCommand.Update && !enable) { - if (m_stopDispatchTask) - { - // We happened to end up here after the task was marked as stopping, give up the lock and try again later - continue; - } - - Debug.Assert(!m_stopDispatchTask); - if (command == EventCommand.Update && enable) - { - // Add the new subscription. This will overwrite an existing subscription for the listener if one exists. - m_subscriptions[eventListener] = new EventListenerSubscription(matchAnyKeywords, level); - } - else if (command == EventCommand.Update && !enable) - { - // Remove the event listener from the list of subscribers. - m_subscriptions.Remove(eventListener); - } - - // Commit the configuration change. - CommitDispatchConfiguration(); - - // We were successful, break out of the loop - break; + // Remove the event listener from the list of subscribers. + m_subscriptions.Remove(eventListener); } + + // Commit the configuration change. + CommitDispatchConfiguration(); } } @@ -146,10 +131,10 @@ private void CommitDispatchConfiguration() private void StartDispatchTask(ulong sessionID, DateTime syncTimeUtc, long syncTimeQPC, long timeQPCFrequency) { Debug.Assert(Monitor.IsEntered(m_dispatchControlLock)); - Debug.Assert(m_dispatchTask == null); - Debug.Assert(m_stopDispatchTask == false); - m_dispatchTask = Task.Factory.StartNew(() => DispatchEventsToEventListeners(sessionID, syncTimeUtc, syncTimeQPC, timeQPCFrequency), CancellationToken.None, TaskCreationOptions.LongRunning, TaskScheduler.Default); + m_dispatchTaskCancellationSource = new CancellationTokenSource(); + Task? previousDispatchTask = m_dispatchTask; + m_dispatchTask = Task.Factory.StartNew(() => DispatchEventsToEventListeners(sessionID, syncTimeUtc, syncTimeQPC, timeQPCFrequency, previousDispatchTask, m_dispatchTaskCancellationSource.Token), CancellationToken.None, TaskCreationOptions.LongRunning, TaskScheduler.Default); } private void SetStopDispatchTask() @@ -158,22 +143,22 @@ private void SetStopDispatchTask() if (m_dispatchTask != null) { - m_stoppedEvent.Reset(); - m_stopDispatchTask = true; + m_dispatchTaskCancellationSource?.Cancel(); EventPipeInternal.SignalSession(m_sessionID); } } - private unsafe void DispatchEventsToEventListeners(ulong sessionID, DateTime syncTimeUtc, long syncTimeQPC, long timeQPCFrequency) + private unsafe void DispatchEventsToEventListeners(ulong sessionID, DateTime syncTimeUtc, long syncTimeQPC, long timeQPCFrequency, Task? previousDispatchTask, CancellationToken token) { + previousDispatchTask?.Wait(CancellationToken.None); + // Struct to fill with the call to GetNextEvent. EventPipeEventInstanceData instanceData; - - while (!m_stopDispatchTask) + while (!token.IsCancellationRequested) { bool eventsReceived = false; // Get the next event. - while (!m_stopDispatchTask && EventPipeInternal.GetNextEvent(sessionID, &instanceData)) + while (!token.IsCancellationRequested && EventPipeInternal.GetNextEvent(sessionID, &instanceData)) { eventsReceived = true; @@ -188,7 +173,7 @@ private unsafe void DispatchEventsToEventListeners(ulong sessionID, DateTime syn } // Wait for more events. - if (!m_stopDispatchTask) + if (!token.IsCancellationRequested) { if (!eventsReceived) { @@ -199,11 +184,6 @@ private unsafe void DispatchEventsToEventListeners(ulong sessionID, DateTime syn } } - m_dispatchTask = null; - m_stopDispatchTask = false; - // Signal to threads that they can stop waiting since we are done - m_stoppedEvent.Set(); - // Disable the old session. This can happen asynchronously since we aren't using the old session anymore EventPipeInternal.Disable(sessionID); } From 24613a4a4c6979508e47fb4df51bbf89bca561fd Mon Sep 17 00:00:00 2001 From: David Mason Date: Fri, 11 Aug 2023 15:29:23 -0700 Subject: [PATCH 3/6] Update EventPipeEventDispatcher.cs --- .../src/System/Diagnostics/Tracing/EventPipeEventDispatcher.cs | 1 + 1 file changed, 1 insertion(+) diff --git a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventDispatcher.cs b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventDispatcher.cs index 60cdc2617810fb..69b64c2aeec92c 100644 --- a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventDispatcher.cs +++ b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventDispatcher.cs @@ -143,6 +143,7 @@ private void SetStopDispatchTask() if (m_dispatchTask != null) { + Debug.Assert(m_dispatchTaskCancellationSource != null); m_dispatchTaskCancellationSource?.Cancel(); EventPipeInternal.SignalSession(m_sessionID); } From 331c8ed65618debdbd60fe02147281873cfa295f Mon Sep 17 00:00:00 2001 From: David Mason Date: Fri, 11 Aug 2023 15:50:19 -0700 Subject: [PATCH 4/6] Remove outdated comment --- .../src/System/Diagnostics/Tracing/EventSource.cs | 1 - 1 file changed, 1 deletion(-) 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 8cfe030639dd12..a71a23ca88abe9 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 @@ -4078,7 +4078,6 @@ public virtual void Dispose() #if FEATURE_PERFTRACING // Remove the listener from the EventPipe dispatcher. EventCommand.Update with enable==false removes it. - // Have to send outside of EventListenersLock, or we risk deadlocks. EventPipeEventDispatcher.Instance.SendCommand(this, EventCommand.Update, false, EventLevel.LogAlways, (EventKeywords)0); #endif // FEATURE_PERFTRACING } From 7ca77a6ef77d92e7fb4153563e22c9d98c1ddecf Mon Sep 17 00:00:00 2001 From: David Mason Date: Fri, 11 Aug 2023 15:29:23 -0700 Subject: [PATCH 5/6] Fix assert --- .../System/Diagnostics/Tracing/EventPipeEventDispatcher.cs | 4 +++- src/native/eventpipe/ep.c | 2 +- 2 files changed, 4 insertions(+), 2 deletions(-) diff --git a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventDispatcher.cs b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventDispatcher.cs index 69b64c2aeec92c..efd4b8cfb656dd 100644 --- a/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventDispatcher.cs +++ b/src/libraries/System.Private.CoreLib/src/System/Diagnostics/Tracing/EventPipeEventDispatcher.cs @@ -131,6 +131,7 @@ private void CommitDispatchConfiguration() private void StartDispatchTask(ulong sessionID, DateTime syncTimeUtc, long syncTimeQPC, long timeQPCFrequency) { Debug.Assert(Monitor.IsEntered(m_dispatchControlLock)); + Debug.Assert(sessionID != 0); m_dispatchTaskCancellationSource = new CancellationTokenSource(); Task? previousDispatchTask = m_dispatchTask; @@ -151,6 +152,7 @@ private void SetStopDispatchTask() private unsafe void DispatchEventsToEventListeners(ulong sessionID, DateTime syncTimeUtc, long syncTimeQPC, long timeQPCFrequency, Task? previousDispatchTask, CancellationToken token) { + Debug.Assert(sessionID != 0); previousDispatchTask?.Wait(CancellationToken.None); // Struct to fill with the call to GetNextEvent. @@ -178,7 +180,7 @@ private unsafe void DispatchEventsToEventListeners(ulong sessionID, DateTime syn { if (!eventsReceived) { - EventPipeInternal.WaitForSessionSignal(m_sessionID, Timeout.Infinite); + EventPipeInternal.WaitForSessionSignal(sessionID, Timeout.Infinite); } Thread.Sleep(10); diff --git a/src/native/eventpipe/ep.c b/src/native/eventpipe/ep.c index dd327efd8ba3b8..c0b8027a9d7281 100644 --- a/src/native/eventpipe/ep.c +++ b/src/native/eventpipe/ep.c @@ -665,7 +665,7 @@ disable_helper (EventPipeSessionID id) ep_provider_callback_data_queue_fini (provider_callback_data_queue); #ifdef EP_CHECKED_BUILD - if (ep_volatile_load_number_of_sessions () == 0) + if (ep_volatile_load_number_of_sessions () == 0 && ep_volatile_load_eventpipe_state () != EP_STATE_SHUTTING_DOWN) EP_ASSERT (ep_rt_providers_validate_all_disabled ()); #endif From 7969c97a997f25f78d22f6905f7d70afcd5f0d1a Mon Sep 17 00:00:00 2001 From: David Mason Date: Sat, 12 Aug 2023 21:13:49 -0700 Subject: [PATCH 6/6] Don't shut down listeners --- src/native/eventpipe/ep.c | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/src/native/eventpipe/ep.c b/src/native/eventpipe/ep.c index c0b8027a9d7281..d007702dde463f 100644 --- a/src/native/eventpipe/ep.c +++ b/src/native/eventpipe/ep.c @@ -1432,7 +1432,9 @@ ep_shutdown (void) for (uint32_t i = 0; i < EP_MAX_NUMBER_OF_SESSIONS; ++i) { EventPipeSession *session = ep_volatile_load_session (i); - if (session) + // Do not shut down listener sessions on shutdown, the processing thread will + // still be trying to process events in the background until the process is torn down + if (session && session->session_type != EP_SESSION_TYPE_LISTENER) ep_disable ((EventPipeSessionID)session); }