Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Fix deadlock in EventPipeEventDispatcher #90053

Merged
merged 6 commits into from
Aug 14, 2023
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
Original file line number Diff line number Diff line change
Expand Up @@ -2075,6 +2075,9 @@
<data name="EventSource_ChannelTypeDoesNotMatchEventChannelValue" xml:space="preserve">
<value>Channel {0} does not match event channel value {1}.</value>
</data>
<data name="EventSource_CouldNotEnableEventPipe" xml:space="preserve">
<value>Failed to open an EventPipe session for NativeRuntimeEventSource.</value>
</data>
<data name="EventSource_DataDescriptorsOutOfRange" xml:space="preserve">
<value>Data descriptors are out of range.</value>
</data>
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -27,12 +27,13 @@ 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 CancellationTokenSource? m_dispatchTaskCancellationSource;
private Task? m_dispatchTask;

// 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();
davmason marked this conversation as resolved.
Show resolved Hide resolved
private readonly Dictionary<EventListener, EventListenerSubscription> m_subscriptions = new Dictionary<EventListener, EventListenerSubscription>();

Expand All @@ -46,32 +47,18 @@ private EventPipeEventDispatcher()

internal void SendCommand(EventListener eventListener, EventCommand command, bool enable, EventLevel level, EventKeywords matchAnyKeywords)
{
lock (EventListener.EventListenersLock)
lock (m_dispatchControlLock)
{
if (command == EventCommand.Update && enable)
{
lock (m_dispatchControlLock)
{
// 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();
}
// 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)
{
RemoveEventListener(eventListener);
// 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();
Expand All @@ -82,13 +69,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)
Expand Down Expand Up @@ -122,7 +104,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;
Expand All @@ -134,48 +119,49 @@ 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(sessionID != 0);

if (m_dispatchTask == null)
{
m_stopDispatchTask = false;
m_dispatchTask = Task.Factory.StartNew(DispatchEventsToEventListeners, 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 StopDispatchTask()
private void SetStopDispatchTask()
{
Debug.Assert(Monitor.IsEntered(m_dispatchControlLock));

if (m_dispatchTask != null)
{
m_stopDispatchTask = true;
Debug.Assert(m_dispatchTaskCancellationSource != null);
m_dispatchTaskCancellationSource?.Cancel();
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, Task? previousDispatchTask, CancellationToken token)
{
Debug.Assert(sessionID != 0);
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(m_sessionID, &instanceData))
while (!token.IsCancellationRequested && EventPipeInternal.GetNextEvent(sessionID, &instanceData))
{
eventsReceived = true;

Expand All @@ -184,36 +170,39 @@ private unsafe void DispatchEventsToEventListeners()
{
// Dispatch the event.
ReadOnlySpan<byte> payload = new ReadOnlySpan<byte>((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);
}
}

// Wait for more events.
if (!m_stopDispatchTask)
if (!token.IsCancellationRequested)
{
if (!eventsReceived)
{
EventPipeInternal.WaitForSessionSignal(m_sessionID, Timeout.Infinite);
EventPipeInternal.WaitForSessionSignal(sessionID, Timeout.Infinite);
}

Thread.Sleep(10);
}
}

// Disable the old session. This can happen asynchronously since we aren't using the old session anymore
EventPipeInternal.Disable(sessionID);
}

/// <summary>
/// Converts a QueryPerformanceCounter (QPC) timestamp to a UTC DateTime.
/// </summary>
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;
Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -4075,6 +4075,11 @@ public virtual void Dispose()
}
Validate();
}

#if FEATURE_PERFTRACING
// Remove the listener from the EventPipe dispatcher. EventCommand.Update with enable==false removes it.
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
Expand Down Expand Up @@ -4391,11 +4396,6 @@ private static void RemoveReferencesToListenerInEventSources(EventListener liste
}
}
}

#if FEATURE_PERFTRACING
// Remove the listener from the EventPipe dispatcher.
EventPipeEventDispatcher.Instance.RemoveEventListener(listenerToRemove);
#endif // FEATURE_PERFTRACING
}


Expand Down
6 changes: 4 additions & 2 deletions src/native/eventpipe/ep.c
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down Expand Up @@ -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);
}

Expand Down