private void Stop(DiagnoserActionParameters parameters)
{
WaitForDelayedEvents();
string userSessionFile;
try
{
kernelSession.Stop();
heapSession?.Stop();
userSession.Stop();
userSessionFile = userSession.FilePath;
}
finally
{
kernelSession.Dispose();
heapSession?.Dispose();
userSession.Dispose();
}
// Merge the 'primary' etl file X.etl (userSession) with any files that match .clr*.etl .user*.etl. and .kernel.etl.
TraceEventSession.MergeInPlace(userSessionFile, TextWriter.Null);
benchmarkToEtlFile[parameters.BenchmarkCase] = userSessionFile;
}
internal string MergeFiles(Session other)
{
// `other` is not used here because MergeInPlace expects .etl and .kernel.etl files in this folder
// it searches for them and merges into a single file
TraceEventSession.MergeInPlace(FilePath, TextWriter.Null);
return(FilePath);
}
/// <summary>
/// Turning on providers and creating files
/// </summary>
private static void DataCollection(string dataFileName)
{
Out.WriteLine("Collecting 10 seconds of kernel and CLR events to a file, and then printing.");
Out.WriteLine();
Out.WriteLine("Start a .NET program while monitoring to see some events!");
Out.WriteLine();
if (TraceEventSession.IsElevated() != true)
{
Out.WriteLine("Must be elevated (Admin) to run this program.");
Debugger.Break();
return;
}
string kernelDataFileName = Path.ChangeExtension(dataFileName, ".kernel.etl");
// Create one user mode session and one kernel mode session
Out.WriteLine("Creating two raw files, one with kernel events and one with clr events.");
using (var userSession = new TraceEventSession("MonitorKernelAndClrEventsSession", dataFileName))
using (var kernelSession = new TraceEventSession(KernelTraceEventParser.KernelSessionName, kernelDataFileName))
{
// Set up Ctrl-C to stop both user mode and kernel mode sessions
Console.CancelKeyPress += delegate(object sender, ConsoleCancelEventArgs cancelArgs)
{
Out.WriteLine("Insuring all ETW sessions are stopped.");
kernelSession.Stop(true); // true means don't throw on error
userSession.Stop(true); // true means don't throw on error
// Since we don't cancel the Ctrl-C we will terminate the process as normal for Ctrl-C
Out.WriteLine("OnCtrl C handler ending.");
};
// Enable the events we care about for the kernel in the kernel session
// For this instant the session will buffer any incoming events.
kernelSession.EnableKernelProvider(
KernelTraceEventParser.Keywords.ImageLoad |
KernelTraceEventParser.Keywords.Process |
KernelTraceEventParser.Keywords.Thread);
// Enable the events we care about for the CLR (in the user session).
// unlike the kernel session, you can call EnableProvider on other things too.
// For this instant the session will buffer any incoming events.
userSession.EnableProvider(
ClrTraceEventParser.ProviderGuid,
TraceEventLevel.Informational,
(ulong)(ClrTraceEventParser.Keywords.Default));
Out.WriteLine("Collecting data for 10 seconds (run a .Net program to generate events).");
Thread.Sleep(10000);
Out.WriteLine("Stopping sessions");
}// Using clauses will insure that session are disposed (and thus stopped) before Main returns.
Out.WriteLine("Merging the raw files into a single '{0}' file.", dataFileName);
TraceEventSession.MergeInPlace(dataFileName, Out);
Out.WriteLine("Merge complete.");
}
/// <summary>
/// Performs tasks associated with listening ETW events on Windows.
/// </summary>
/// <param name="runner">Operation to be profiled/traced.</param>
/// <returns>The return value of the method that the runner delegate encapsulates.</returns>
public TResult Record(Func <TResult> runner)
{
if (runner == null)
{
throw new ArgumentNullException(nameof(runner));
}
var fi = new FileInfo(UserSessionData.FileName);
var kernelFileName = Path.Combine($"{fi.DirectoryName}", $"{Path.GetFileNameWithoutExtension(fi.Name)}.kernel.etl");
var kernelProvider = KernelProviders.Aggregate(KernelProvider.Default,
(current, item) => new KernelProvider
{
Flags = current.Flags | item.Flags,
StackCapture = current.StackCapture | item.StackCapture,
});
var needKernelSession = Helper.NeedSeparateKernelSession(kernelProvider);
if (needKernelSession && !Helper.CanEnableKernelProvider)
{
const string message = "The application is required to run as Administrator in order to capture kernel data.";
WriteErrorLine(message);
throw new UnauthorizedAccessException(message);
}
TResult result;
WriteDebugLine("ETW capture start.");
using (var kernelSession = needKernelSession ? Helper.MakeKernelSession(kernelFileName, UserSessionData.BufferSizeMB) : null)
{
kernelSession?.EnableKernelProvider(kernelProvider.Flags, kernelProvider.StackCapture);
using (var userSession = new Session(UserSessionData))
{
UserProviders.ForEach(provider =>
{
userSession.EnableProvider(provider.Guid, provider.Level, provider.Keywords, provider.Options);
});
result = runner();
}
}
WriteDebugLine("ETW capture stop.");
WriteDebugLine("ETW merge start.");
TraceEventSession.MergeInPlace(UserSessionData.FileName, Console.Out);
WriteDebugLine("ETW merge stop.");
return(result);
}
/// <summary>
/// Dump the JSHeap for process 'processID' to the etl file name 'etlFileName'. Send diagnostics to 'log'.
/// If 'memoryGraph is non-null also update it to contain the JSDump. If null you get just the ETL file.
/// returns true if successful.
/// </summary>
static public bool DumpAsEtlFile(int processID, string etlFileName, TextWriter log, MemoryGraph memoryGraph = null)
{
var ver = Environment.OSVersion.Version;
var intVer = ver.Major * 10 + ver.Minor;
if (intVer < 62)
{
log.WriteLine("JavaScript Heap Dumping only supported on Win8 or above.");
return(false);
}
bool success = false;
var kernelFileName = Path.ChangeExtension(etlFileName, ".kernel.etl");
try
{
// WPA for some reason won't recognize the ETL file as having a JSDump in it unless it has the process and thread events in it.
log.WriteLine("Starting Kernel Logging on {0}", kernelFileName);
FileUtilities.ForceDelete(kernelFileName);
using (TraceEventSession kernelModeSession = new TraceEventSession("PerfViewGCHeapKernelETLSession", kernelFileName))
{
kernelModeSession.EnableKernelProvider(KernelTraceEventParser.Keywords.Process | KernelTraceEventParser.Keywords.Thread);
log.WriteLine("Starting ETW logging on File {0}", etlFileName);
using (var session = new TraceEventSession("PerfViewGCHeapETLSession", etlFileName))
{
session.EnableProvider(JSDumpHeapTraceEventParser.ProviderGuid, TraceEventLevel.Informational,
(ulong)JSDumpHeapTraceEventParser.Keywords.jsdumpheap);
success = Dump(processID, memoryGraph, log);
log.WriteLine("Stopping ETW logging on {0}", etlFileName);
}
}
if (success)
{
log.WriteLine("Merging JS and Kernel data ");
TraceEventSession.MergeInPlace(etlFileName, log);
}
}
finally
{
FileUtilities.ForceDelete(kernelFileName);
}
log.WriteLine("DumpAsETLFile returns. Success={0}", success);
return(success);
}
public void Stop()
{
using (var rundownSession = new TraceEventSession(sessionName + "Rundown", "data.clrRundown.etl"))
{
rundownSession.EnableProvider(ClrRundownTraceEventParser.ProviderGuid, TraceEventLevel.Verbose,
(ulong)ClrRundownTraceEventParser.Keywords.Default);
// Poll until 2 second goes by without growth.
for (var prevLength = new FileInfo("data.clrRundown.etl").Length;;)
{
Thread.Sleep(2000);
var newLength = new FileInfo("data.clrRundown.etl").Length;
if (newLength == prevLength)
{
break;
}
prevLength = newLength;
}
}
// TODO: Currenty not aware of any more sophisticated control, when hosting sub-process it will wait for timeout without new events after sub-process ends
//Thread.Sleep(4000);
stopped = true;
session?.Dispose();
kernelSession?.Dispose();
TraceEventSession.MergeInPlace("data.etl", TextWriter.Null);
//var traceLog = TraceLog.OpenOrConvert("data.etl");
//var simpleTraceLogProcess = traceLog.Processes.LastProcessWithID(Process.GetCurrentProcess().Id);
//foreach (var data in simpleTraceLogProcess.EventsInProcess)
//{
//}
using (var source = new ETWTraceEventSource("data.etl"))
{
source.Clr.GCHeapStats += ClrOnGcHeapStats;
source.Clr.GCStart += ClrOnGcStart;
source.Clr.GCStop += ClrOnGcStop;
source.Clr.GCGenerationRange += ClrOnGcGenerationRange;
source.Process();
}
}
/// <summary>
/// 1. In the specified assembly, get the ETW providers set as assembly attributes (PerformanceTestInfo)
/// 2. Check if the benchmark assembly request Precise Machine Counters(PMC) to be collected
/// 3. Enable Kernel providers if needed
/// 4. Get non-kernel ETW flags set and enable them
/// 5. Run the benchmarks
/// 6. Stop collecting ETW
/// 7. Merge ETL files.
/// </summary>
/// <param name="xUnitPerformanceSessionData"></param>
/// <param name="xUnitPerformanceMetricData"></param>
/// <param name="action"></param>
public static void Record(XUnitPerformanceSessionData xUnitPerformanceSessionData, XUnitPerformanceMetricData xUnitPerformanceMetricData, Action action)
{
const int bufferSizeMB = 256;
var name = $"{xUnitPerformanceSessionData.RunId}-{Path.GetFileNameWithoutExtension(xUnitPerformanceSessionData.AssemblyFileName)}";
var etwOutputData = new ETWOutputData {
KernelFileName = Path.Combine(xUnitPerformanceSessionData.OutputDirectory, $"{name}.kernel.etl"), // without this parameter, EnableKernelProvider will fail
Name = name,
SessionName = $"Performance-Api-Session-{xUnitPerformanceSessionData.RunId}",
UserFileName = Path.Combine(xUnitPerformanceSessionData.OutputDirectory, $"{name}.etl"),
};
PrintProfilingInformation(xUnitPerformanceSessionData.AssemblyFileName, etwOutputData);
var kernelProviderInfo = xUnitPerformanceMetricData.Providers.OfType <KernelProviderInfo>().FirstOrDefault();
var needKernelSession = NeedSeparateKernelSession(kernelProviderInfo);
if (needKernelSession && !CanEnableEnableKernelProvider)
{
const string message = "In order to capture kernel data the application is required to run as Administrator.";
WriteErrorLine(message);
throw new InvalidOperationException(message);
}
WriteDebugLine("> ETW capture start.");
// Prior to Windows 8 (NT 6.2), all kernel events needed the special kernel session.
using (var safeKernelSession = needKernelSession && CanEnableEnableKernelProvider ? MakeSafeTerminateTraceEventSession(KernelTraceEventParser.KernelSessionName, etwOutputData.KernelFileName) : null)
{
var kernelSession = safeKernelSession?.BaseDisposableObject;
if (kernelSession != null)
{
SetPreciseMachineCounters(xUnitPerformanceMetricData.Providers);
kernelSession.BufferSizeMB = bufferSizeMB;
var flags = (KernelTraceEventParser.Keywords)kernelProviderInfo.Keywords;
var stackCapture = (KernelTraceEventParser.Keywords)kernelProviderInfo.StackKeywords;
kernelSession.EnableKernelProvider(flags, stackCapture);
}
using (var safeUserEventSession = MakeSafeTerminateTraceEventSession(etwOutputData.SessionName, etwOutputData.UserFileName))
{
var userEventSession = safeUserEventSession.BaseDisposableObject;
userEventSession.BufferSizeMB = bufferSizeMB;
if (needKernelSession && CanEnableEnableKernelProvider)
{
userEventSession.EnableKernelProvider(KernelProvider.Default.Flags, KernelProvider.Default.StackCapture);
}
foreach (var provider in UserProvider.Defaults)
{
userEventSession.EnableProvider(provider.Guid, provider.Level, provider.Keywords);
}
foreach (var provider in xUnitPerformanceMetricData.Providers.OfType <UserProviderInfo>())
{
userEventSession.EnableProvider(provider.ProviderGuid, provider.Level, provider.Keywords);
}
action.Invoke();
}
}
WriteDebugLine("> ETW capture stop.");
// TODO: Decouple the code below.
// Collect ETW profile data.
// TODO: Skip collecting kernel data if it was not captured! (data will be zero, there is no point to report it or upload it)
WriteDebugLine("> ETW merge start.");
TraceEventSession.MergeInPlace(etwOutputData.UserFileName, Console.Out);
WriteDebugLine("> ETW merge stop.");
xUnitPerformanceSessionData.CollectOutputFilesCallback(etwOutputData.UserFileName);
var assemblyModel = GetAssemblyModel(xUnitPerformanceSessionData.AssemblyFileName, etwOutputData.UserFileName, xUnitPerformanceSessionData.RunId, xUnitPerformanceMetricData.PerformanceTestMessages);
var xmlFileName = Path.Combine(xUnitPerformanceSessionData.OutputDirectory, $"{etwOutputData.Name}.xml");
new AssemblyModelCollection {
assemblyModel
}.Serialize(xmlFileName);
xUnitPerformanceSessionData.CollectOutputFilesCallback(xmlFileName);
var mdFileName = Path.Combine(xUnitPerformanceSessionData.OutputDirectory, $"{etwOutputData.Name}.md");
var dt = assemblyModel.GetStatistics();
var mdTable = MarkdownHelper.GenerateMarkdownTable(dt);
MarkdownHelper.Write(mdFileName, mdTable);
xUnitPerformanceSessionData.CollectOutputFilesCallback(mdFileName);
Console.WriteLine(MarkdownHelper.ToTrimmedTable(mdTable));
var csvFileName = Path.Combine(xUnitPerformanceSessionData.OutputDirectory, $"{etwOutputData.Name}.csv");
dt.WriteToCSV(csvFileName);
xUnitPerformanceSessionData.CollectOutputFilesCallback(csvFileName);
}
/// <summary>
/// CollectData doe will turn on logging of data from 'eventSourceName' to the file 'dataFileName'.
/// It will then call EventGenerator.CreateEvents and wait 12 seconds for it to generate some data.
/// </summary>
static void CollectData(string eventSourceName, string dataFileName)
{
// Today you have to be Admin to turn on ETW events (anyone can write ETW events).
if (!(TraceEventSession.IsElevated() ?? false))
{
Out.WriteLine("To turn on ETW events you need to be Administrator, please run from an Admin process.");
Debugger.Break();
return;
}
// As mentioned below, sessions can outlive the process that created them. Thus you need a way of
// naming the session so that you can 'reconnect' to it from another process. This is what the name
// is for. It can be anything, but it should be descriptive and unique. If you expect multiple versions
// of your program to run simultaneously, you need to generate unique names (e.g. add a process ID suffix)
// however this is dangerous because you can leave data collection on if the program ends unexpectedly.
//
// In this case we tell the session to place the data in MonitorToFileData.etl.
var sessionName = "SimpleTraceLogSession";
Out.WriteLine("Creating a '{0}' session writing to {1}", sessionName, dataFileName);
Out.WriteLine("Use 'logman query -ets' to see active sessions.");
Out.WriteLine("Use 'logman stop {0} -ets' to manually stop orphans.", sessionName);
using (var session = new TraceEventSession(sessionName, dataFileName)) // Since we give it a file name, the data goes there.
using (var kernelSession = new TraceEventSession(KernelTraceEventParser.KernelSessionName, Path.ChangeExtension(dataFileName, ".kernel.etl")))
{
/* BY DEFAULT ETW SESSIONS SURVIVE THE DEATH OF THE PROCESS THAT CREATES THEM! */
// Unlike most other resources on the system, ETW session live beyond the lifetime of the
// process that created them. This is very useful in some scenarios, but also creates the
// very real possibility of leaving 'orphan' sessions running.
//
// To help avoid this by default TraceEventSession sets 'StopOnDispose' so that it will stop
// the ETW session if the TraceEventSession dies. Thus executions that 'clean up' the TraceEventSession
// will clean up the ETW session. This covers many cases (including throwing exceptions)
//
// However if the process is killed manually (including control C) this cleanup will not happen.
// Thus best practices include
//
// * Add a Control C handler that calls session.Dispose() so it gets cleaned up in this common case
// * use the same session name run-to-run so you don't create many orphans.
//
// By default TraceEventSessions are in 'create' mode where it assumes you want to create a new session.
// In this mode if a session already exists, it is stopped and the new one is created.
//
// Here we install the Control C handler. It is OK if Dispose is called more than once.
Console.CancelKeyPress += delegate(object sender, ConsoleCancelEventArgs e) { session.Dispose(); kernelSession.Dispose(); };
// Enable kernel events.
kernelSession.EnableKernelProvider(KernelTraceEventParser.Keywords.ImageLoad | KernelTraceEventParser.Keywords.Process | KernelTraceEventParser.Keywords.Thread);
// Enable my provider, you can call many of these on the same session to get events from other providers
// Turn on the eventSource given its name.
// Note we turn on Verbose level all keywords (ulong.MaxValue == 0xFFF....) and turn on stacks for
// this provider (for all events, until Windows 8.1 you can only turn on stacks for every event
// for a particular provider or no stacks)
var options = new TraceEventProviderOptions()
{
StacksEnabled = true
};
var restarted = session.EnableProvider(eventSourceName, TraceEventLevel.Verbose, ulong.MaxValue, options);
if (restarted) // Generally you don't bother with this warning, but for the demo we do.
{
Out.WriteLine("The session {0} was already active, it has been restarted.", sessionName);
}
// We also turn on CLR events because we need them to decode Stacks and we also get exception events (and their stacks)
session.EnableProvider(ClrTraceEventParser.ProviderGuid, TraceEventLevel.Verbose, (ulong)ClrTraceEventParser.Keywords.Default);
// Start another thread that Causes MyEventSource to create some events
// Normally this code as well as the EventSource itself would be in a different process.
EventGenerator.CreateEvents();
// Also generate some exceptions so we have interesting stacks to look at
Thread.Sleep(100);
EventGenerator.GenerateExceptions();
Out.WriteLine("Waiting 12 seconds for events to come in.");
Thread.Sleep(12000);
// Because the process in question (this process) lives both before and after the time the events were
// collected, we don't have complete information about JIT compiled methods in that method. There are
// some methods that were JIT compiled before the session started (e.g. SimpleTraceLog.Main) for which
// we do not have information. We collect this by forcing a CLR 'rundown' which will dump method information
// for JIT compiled methods that were not present. If you know that the process of interest ends before
// data collection ended or that data collection started before the process started, then this is not needed.
Out.WriteLine("Forcing rundown of JIT methods.");
var rundownFileName = Path.ChangeExtension(dataFileName, ".clrRundown.etl");
using (var rundownSession = new TraceEventSession(sessionName + "Rundown", rundownFileName))
{
rundownSession.EnableProvider(ClrRundownTraceEventParser.ProviderGuid, TraceEventLevel.Verbose, (ulong)ClrRundownTraceEventParser.Keywords.Default);
// Poll until 2 second goes by without growth.
for (var prevLength = new FileInfo(rundownFileName).Length; ;)
{
Thread.Sleep(2000);
var newLength = new FileInfo(rundownFileName).Length;
if (newLength == prevLength)
{
break;
}
prevLength = newLength;
}
}
Out.WriteLine("Done with rundown.");
}
Out.WriteLine("Merging the raw files into a single '{0}' file.", dataFileName);
TraceEventSession.MergeInPlace(dataFileName, Out);
Out.WriteLine("Merge complete.");
}
/// <summary>
/// 1. In the specified assembly, get the ETW providers set as assembly attributes (PerformanceTestInfo)
/// 2. Check if the benchmark assembly request Precise Machine Counters(PMC) to be collected
/// 3. Enable Kernel providers if needed
/// 4. Get non-kernel ETW flags set and enable them
/// 5. Run the benchmarks
/// 6. Stop collecting ETW
/// 7. Merge ETL files.
/// </summary>
/// <param name="assemblyFileName"></param>
/// <param name="runId"></param>
/// <param name="outputDirectory"></param>
/// <param name="action"></param>
/// <param name="collectOutputFilesCallback">Callback used to collect a list of files generated.</param>
/// <returns></returns>
public static void Record(string assemblyFileName, string runId, string outputDirectory, Action action, Action <string> collectOutputFilesCallback)
{
if (TraceEventSession.IsElevated() != true)
{
const string errMessage = "In order to profile, application is required to run as Administrator.";
WriteErrorLine(errMessage);
throw new InvalidOperationException(errMessage);
}
const int bufferSizeMB = 256;
var sessionName = $"Performance-Api-Session-{runId}";
var name = $"{runId}-{Path.GetFileNameWithoutExtension(assemblyFileName)}";
var userFullFileName = Path.Combine(outputDirectory, $"{name}.etl");
var kernelFullFileName = Path.Combine(outputDirectory, $"{name}.kernel.etl"); // without this parameter, EnableKernelProvider will fail
PrintProfilingInformation(assemblyFileName, sessionName, userFullFileName);
(var providers, var performanceTestMessages) = XunitBenchmark.GetMetadata(assemblyFileName);
var kernelProviderInfo = providers.OfType <KernelProviderInfo>().FirstOrDefault();
var needKernelSession = NeedSeparateKernelSession(kernelProviderInfo);
using (var safeKernelSession = needKernelSession ? MakeSafeTerminateTraceEventSession(KernelTraceEventParser.KernelSessionName, kernelFullFileName) : null)
{
var kernelSession = safeKernelSession?.BaseDisposableObject;
if (kernelSession != null)
{
SetPreciseMachineCounters(providers);
kernelSession.BufferSizeMB = bufferSizeMB;
var flags = (KernelTraceEventParser.Keywords)kernelProviderInfo.Keywords;
var stackCapture = (KernelTraceEventParser.Keywords)kernelProviderInfo.StackKeywords;
kernelSession.EnableKernelProvider(flags, stackCapture);
}
using (var safeUserEventSession = MakeSafeTerminateTraceEventSession(sessionName, userFullFileName))
{
var userEventSession = safeUserEventSession.BaseDisposableObject;
userEventSession.BufferSizeMB = bufferSizeMB;
var flags = KernelTraceEventParser.Keywords.Process | KernelTraceEventParser.Keywords.ImageLoad | KernelTraceEventParser.Keywords.Thread;
var stackCapture = KernelTraceEventParser.Keywords.Profile | KernelTraceEventParser.Keywords.ContextSwitch;
userEventSession.EnableKernelProvider(flags, stackCapture);
foreach (var userProviderInfo in providers.OfType <UserProviderInfo>())
{
userEventSession.EnableProvider(userProviderInfo.ProviderGuid, userProviderInfo.Level, userProviderInfo.Keywords);
}
action.Invoke();
}
}
TraceEventSession.MergeInPlace(userFullFileName, Console.Out);
WriteInfoLine($"ETW Tracing Session saved to \"{userFullFileName}\"");
collectOutputFilesCallback(userFullFileName);
var assemblyModel = GetAssemblyModel(assemblyFileName, userFullFileName, runId, performanceTestMessages);
var xmlFileName = Path.Combine(outputDirectory, $"{name}.xml");
new AssemblyModelCollection {
assemblyModel
}.Serialize(xmlFileName);
WriteInfoLine($"Performance results saved to \"{xmlFileName}\"");
collectOutputFilesCallback(xmlFileName);
var mdFileName = Path.Combine(outputDirectory, $"{name}.md");
var dt = assemblyModel.GetStatistics();
var mdTable = MarkdownHelper.GenerateMarkdownTable(dt);
MarkdownHelper.Write(mdFileName, mdTable);
WriteInfoLine($"Markdown file saved to \"{mdFileName}\"");
collectOutputFilesCallback(mdFileName);
Console.WriteLine(MarkdownHelper.ToTrimmedTable(mdTable));
var csvFileName = Path.Combine(outputDirectory, $"{name}.csv");
dt.WriteToCSV(csvFileName);
WriteInfoLine($"Statistics written to \"{csvFileName}\"");
collectOutputFilesCallback(csvFileName);
}
