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); }