/// <summary>
/// Given a factory for creating an EventPipe session with the appropriate provider and keywords turned on,
/// generate a GCHeapDump using the resulting events. The correct keywords and provider name
/// are given as input to the Func eventPipeEventSourceFactory.
/// </summary>
/// <param name="processID"></param>
/// <param name="eventPipeEventSourceFactory">A delegate for creating and stopping EventPipe sessions</param>
/// <param name="memoryGraph"></param>
/// <param name="log"></param>
/// <param name="dotNetInfo"></param>
/// <returns></returns>
public static bool DumpFromEventPipe(CancellationToken ct, int processID, MemoryGraph memoryGraph, TextWriter log, int timeout, DotNetHeapInfo dotNetInfo = null)
{
var startTicks = Stopwatch.GetTimestamp();
Func <TimeSpan> getElapsed = () => TimeSpan.FromTicks(Stopwatch.GetTimestamp() - startTicks);
var dumper = new DotNetHeapDumpGraphReader(log)
{
DotNetHeapInfo = dotNetInfo
};
try
{
TimeSpan lastEventPipeUpdate = getElapsed();
bool fDone = false;
log.WriteLine("{0,5:n1}s: Creating type table flushing task", getElapsed().TotalSeconds);
using (EventPipeSessionController typeFlushSession = new EventPipeSessionController(processID, new List <EventPipeProvider> {
new EventPipeProvider("Microsoft-DotNETCore-SampleProfiler", EventLevel.Informational)
}, false))
{
log.WriteLine("{0,5:n1}s: Flushing the type table", getElapsed().TotalSeconds);
typeFlushSession.Source.AllEvents += (traceEvent) => {
if (!fDone)
{
fDone = true;
Task.Run(() => typeFlushSession.EndSession())
.ContinueWith(_ => typeFlushSession.Source.StopProcessing());
}
};
typeFlushSession.Source.Process();
log.WriteLine("{0,5:n1}s: Done flushing the type table", getElapsed().TotalSeconds);
}
// Start the providers and trigger the GCs.
log.WriteLine("{0,5:n1}s: Requesting a .NET Heap Dump", getElapsed().TotalSeconds);
using EventPipeSessionController gcDumpSession = new EventPipeSessionController(processID, new List <EventPipeProvider> {
new EventPipeProvider("Microsoft-Windows-DotNETRuntime", EventLevel.Verbose, (long)(ClrTraceEventParser.Keywords.GCHeapSnapshot))
});
log.WriteLine("{0,5:n1}s: gcdump EventPipe Session started", getElapsed().TotalSeconds);
int gcNum = -1;
gcDumpSession.Source.Clr.GCStart += delegate(GCStartTraceData data)
{
if (data.ProcessID != processID)
{
return;
}
eventPipeDataPresent = true;
if (gcNum < 0 && data.Depth == 2 && data.Type != GCType.BackgroundGC)
{
gcNum = data.Count;
log.WriteLine("{0,5:n1}s: .NET Dump Started...", getElapsed().TotalSeconds);
}
};
gcDumpSession.Source.Clr.GCStop += delegate(GCEndTraceData data)
{
if (data.ProcessID != processID)
{
return;
}
if (data.Count == gcNum)
{
log.WriteLine("{0,5:n1}s: .NET GC Complete.", getElapsed().TotalSeconds);
dumpComplete = true;
}
};
gcDumpSession.Source.Clr.GCBulkNode += delegate(GCBulkNodeTraceData data)
{
if (data.ProcessID != processID)
{
return;
}
eventPipeDataPresent = true;
if ((getElapsed() - lastEventPipeUpdate).TotalMilliseconds > 500)
{
log.WriteLine("{0,5:n1}s: Making GC Heap Progress...", getElapsed().TotalSeconds);
}
lastEventPipeUpdate = getElapsed();
};
if (memoryGraph != null)
{
dumper.SetupCallbacks(memoryGraph, gcDumpSession.Source, processID.ToString());
}
// Set up a separate thread that will listen for EventPipe events coming back telling us we succeeded.
Task readerTask = Task.Run(() =>
{
// cancelled before we began
if (ct.IsCancellationRequested)
{
return;
}
log.WriteLine("{0,5:n1}s: Starting to process events", getElapsed().TotalSeconds);
gcDumpSession.Source.Process();
log.WriteLine("{0,5:n1}s: EventPipe Listener dying", getElapsed().TotalSeconds);
}, ct);
for (; ;)
{
if (ct.IsCancellationRequested)
{
log.WriteLine("{0,5:n1}s: Cancelling...", getElapsed().TotalSeconds);
break;
}
if (readerTask.Wait(100))
{
break;
}
if (!eventPipeDataPresent && getElapsed().TotalSeconds > 5) // Assume it started within 5 seconds.
{
log.WriteLine("{0,5:n1}s: Assume no .NET Heap", getElapsed().TotalSeconds);
break;
}
if (getElapsed().TotalSeconds > timeout) // Time out after `timeout` seconds. defaults to 30s.
{
log.WriteLine("{0,5:n1}s: Timed out after {1} seconds", getElapsed().TotalSeconds, timeout);
break;
}
if (dumpComplete)
{
break;
}
}
var stopTask = Task.Run(() =>
{
log.WriteLine("{0,5:n1}s: Shutting down gcdump EventPipe session", getElapsed().TotalSeconds);
gcDumpSession.EndSession();
log.WriteLine("{0,5:n1}s: gcdump EventPipe session shut down", getElapsed().TotalSeconds);
}, ct);
try
{
while (!Task.WaitAll(new Task[] { readerTask, stopTask }, 1000))
{
log.WriteLine("{0,5:n1}s: still reading...", getElapsed().TotalSeconds);
}
}
catch (AggregateException ae) // no need to throw if we're just cancelling the tasks
{
foreach (var e in ae.Flatten().InnerExceptions)
{
if (!(e is TaskCanceledException))
{
throw ae;
}
}
}
log.WriteLine("{0,5:n1}s: gcdump EventPipe Session closed", getElapsed().TotalSeconds);
if (ct.IsCancellationRequested)
{
return(false);
}
if (eventPipeDataPresent)
{
dumper.ConvertHeapDataToGraph(); // Finish the conversion.
}
}
catch (Exception e)
{
log.WriteLine($"{getElapsed().TotalSeconds,5:n1}s: [Error] Exception during gcdump: {e.ToString()}");
}
log.WriteLine("[{0,5:n1}s: Done Dumping .NET heap success={1}]", getElapsed().TotalSeconds, dumpComplete);
return(dumpComplete);
}
private async Task HandleGCEvents(EventPipeEventSource source, int pid, Func <Task> stopFunc, CancellationToken token)
{
int gcNum = -1;
Action <GCStartTraceData, Action> gcStartHandler = (GCStartTraceData data, Action taskComplete) =>
{
if (data.ProcessID != pid)
{
return;
}
taskComplete();
if (gcNum < 0 && data.Depth == 2 && data.Type != GCType.BackgroundGC)
{
gcNum = data.Count;
}
};
Action <GCBulkNodeTraceData, Action> gcBulkNodeHandler = (GCBulkNodeTraceData data, Action taskComplete) =>
{
if (data.ProcessID != pid)
{
return;
}
taskComplete();
};
Action <GCEndTraceData, Action> gcEndHandler = (GCEndTraceData data, Action taskComplete) =>
{
if (data.ProcessID != pid)
{
return;
}
if (data.Count == gcNum)
{
taskComplete();
}
};
// Register event handlers on the event source and represent their completion as tasks
using var gcStartTaskSource = new EventTaskSource <Action <GCStartTraceData> >(
taskComplete => data => gcStartHandler(data, taskComplete),
handler => source.Clr.GCStart += handler,
handler => source.Clr.GCStart -= handler,
token);
using var gcBulkNodeTaskSource = new EventTaskSource <Action <GCBulkNodeTraceData> >(
taskComplete => data => gcBulkNodeHandler(data, taskComplete),
handler => source.Clr.GCBulkNode += handler,
handler => source.Clr.GCBulkNode -= handler,
token);
using var gcStopTaskSource = new EventTaskSource <Action <GCEndTraceData> >(
taskComplete => data => gcEndHandler(data, taskComplete),
handler => source.Clr.GCStop += handler,
handler => source.Clr.GCStop -= handler,
token);
using var sourceCompletedTaskSource = new EventTaskSource <Action>(
taskComplete => taskComplete,
handler => source.Completed += handler,
handler => source.Completed -= handler,
token);
// A task that is completed whenever GC data is received
Task gcDataTask = Task.WhenAny(gcStartTaskSource.Task, gcBulkNodeTaskSource.Task);
Task gcStopTask = gcStopTaskSource.Task;
DotNetHeapDumpGraphReader dumper = new DotNetHeapDumpGraphReader(TextWriter.Null)
{
DotNetHeapInfo = new DotNetHeapInfo()
};
dumper.SetupCallbacks(_gcGraph, source, pid.ToString(CultureInfo.InvariantCulture));
// The event source will not always provide the GC events when it starts listening. However,
// they will be provided when the event source is told to stop processing events. Give the
// event source some time to produce the events, but if it doesn't start producing them within
// a short amount of time (5 seconds), then stop processing events to allow them to be flushed.
Task eventsTimeoutTask = Task.Delay(TimeSpan.FromSeconds(5), token);
Task completedTask = await Task.WhenAny(gcDataTask, eventsTimeoutTask);
token.ThrowIfCancellationRequested();
// If started receiving GC events, wait for the GC Stop event.
if (completedTask == gcDataTask)
{
await gcStopTask;
}
// Stop receiving events; if haven't received events yet, this will force flushing of events.
await stopFunc();
// Wait for all received events to be processed.
await sourceCompletedTaskSource.Task;
// Check that GC data and stop events were received. This is done by checking that the
// associated tasks have ran to completion. If one of them has not reached the completion state, then
// fail the GC dump operation.
if (gcDataTask.Status != TaskStatus.RanToCompletion ||
gcStopTask.Status != TaskStatus.RanToCompletion)
{
throw new InvalidOperationException("Unable to create GC dump due to incomplete GC data.");
}
dumper.ConvertHeapDataToGraph();
_gcGraph.AllowReading();
}
/// <summary>
/// Add the nodes of the .NET heap for the process 'processID' to 'memoryGraph' sending diagnostic
/// messages to 'log'. If 'memoryGraph' is null, the ETW providers are triggered by we obviously
/// don't update the memoryGraph. Thus it is only done for the side effect of triggering a .NET heap
/// dump. returns true if successful.
/// </summary>
static public bool Dump(int processID, MemoryGraph memoryGraph, TextWriter log, DotNetHeapInfo dotNetInfo = null)
{
var sw = Stopwatch.StartNew();
var dumper = new DotNetHeapDumpGraphReader(log);
dumper.DotNetHeapInfo = dotNetInfo;
bool dumpComplete = false;
bool listening = false;
TraceEventSession session = null;
Task readerTask = null;
try
{
bool etwDataPresent = false;
TimeSpan lastEtwUpdate = sw.Elapsed;
// Set up a separate thread that will listen for ETW events coming back telling us we succeeded.
readerTask = Task.Factory.StartNew(delegate
{
string sessionName = "PerfViewGCHeapSession";
session = new TraceEventSession(sessionName, null);
int gcNum = -1;
session.BufferSizeMB = 256; // Events come pretty fast, so make the buffer bigger.
// Start the providers and trigger the GCs.
log.WriteLine("{0,5:n1}s: Requesting a .NET Heap Dump", sw.Elapsed.TotalSeconds);
// Have to turn on Kernel provider first (before touching Source) so we do it here.
session.EnableKernelProvider(KernelTraceEventParser.Keywords.Process | KernelTraceEventParser.Keywords.ImageLoad);
session.Source.Clr.GCStart += delegate(GCStartTraceData data)
{
if (data.ProcessID != processID)
{
return;
}
etwDataPresent = true;
if (gcNum < 0 && data.Depth == 2 && data.Type != GCType.BackgroundGC)
{
gcNum = data.Count;
log.WriteLine("{0,5:n1}s: Dot Net Dump Started...", sw.Elapsed.TotalSeconds);
}
};
session.Source.Clr.GCStop += delegate(GCEndTraceData data)
{
if (data.ProcessID != processID)
{
return;
}
if (data.Count == gcNum)
{
log.WriteLine("{0,5:n1}s: DotNet GC Complete.", sw.Elapsed.TotalSeconds);
dumpComplete = true;
}
};
session.Source.Clr.GCBulkNode += delegate(GCBulkNodeTraceData data)
{
if (data.ProcessID != processID)
{
return;
}
etwDataPresent = true;
if ((sw.Elapsed - lastEtwUpdate).TotalMilliseconds > 500)
{
log.WriteLine("{0,5:n1}s: Making GC Heap Progress...", sw.Elapsed.TotalSeconds);
}
lastEtwUpdate = sw.Elapsed;
};
if (memoryGraph != null)
{
dumper.SetupCallbacks(memoryGraph, session.Source, processID.ToString());
}
listening = true;
session.Source.Process();
log.WriteLine("{0,5:n1}s: ETW Listener dieing", sw.Elapsed.TotalSeconds);
});
// Wait for thread above to start listening (should be very fast)
while (!listening)
{
readerTask.Wait(1);
}
Debug.Assert(session != null);
// Request the heap dump. We try to isolate this to a single process.
var options = new TraceEventProviderOptions()
{
ProcessIDFilter = new List <int>()
{
processID
}
};
// There is a bug in the runtime 4.6.2 and earlier where we only clear the table of types we have already emitted when you ENABLE
// the Clr Provider WITHOUT the ClrTraceEventParser.Keywords.Type keyword. we achive this by turning on just the GC events,
// (which clears the Type table) and then turn all the events we need on.
session.EnableProvider(ClrTraceEventParser.ProviderGuid, TraceEventLevel.Informational, (ulong)ClrTraceEventParser.Keywords.GC, options);
System.Threading.Thread.Sleep(50); // Wait for it to complete (it is async)
// For non-project N we need module rundown to figure out the correct module name
session.EnableProvider(ClrRundownTraceEventParser.ProviderGuid, TraceEventLevel.Verbose,
(ulong)(ClrRundownTraceEventParser.Keywords.Loader | ClrRundownTraceEventParser.Keywords.ForceEndRundown), options);
session.EnableProvider(ClrTraceEventParser.ProviderGuid, TraceEventLevel.Informational, (ulong)ClrTraceEventParser.Keywords.GCHeapSnapshot, options);
// Project N support.
session.EnableProvider(ClrTraceEventParser.NativeProviderGuid, TraceEventLevel.Informational, (ulong)ClrTraceEventParser.Keywords.GCHeapSnapshot, options);
for (;;)
{
if (readerTask.Wait(100))
{
break;
}
if (!etwDataPresent && sw.Elapsed.TotalSeconds > 5) // Assume it started within 5 seconds.
{
log.WriteLine("{0,5:n1}s: Assume no Dot Heap", sw.Elapsed.TotalSeconds);
break;
}
if (sw.Elapsed.TotalSeconds > 100) // Time out after 100 seconds.
{
log.WriteLine("{0,5:n1}s: Timed out after 100 seconds", sw.Elapsed.TotalSeconds);
break;
}
// TODO FIX NOW, time out faster if we seek to be stuck
if (dumpComplete)
{
break;
}
}
if (etwDataPresent)
{
dumper.ConvertHeapDataToGraph(); // Finish the conversion.
}
}
finally
{
// Stop the ETW providers
log.WriteLine("{0,5:n1}s: Shutting down ETW session", sw.Elapsed.TotalSeconds);
if (session != null)
{
session.Dispose();
}
}
if (readerTask != null)
{
log.WriteLine("{0,5:n1}s: Waiting for shutdown to complete.", sw.Elapsed.TotalSeconds);
if (!readerTask.Wait(2000))
{
log.WriteLine("{0,5:n1}s: Shutdown wait timed out after 2 seconds.", sw.Elapsed.TotalSeconds);
}
}
log.WriteLine("[{0,5:n1}s: Done Dumping .NET heap success={1}]", sw.Elapsed.TotalSeconds, dumpComplete);
return(dumpComplete);
}