private void StopMonitor() { try { _session.Stop(); } catch (EndOfStreamException ex) { // If the app we're monitoring exits abruptly, this may throw in which case we just swallow the exception and exit gracefully. Debug.WriteLine($"[ERROR] {ex.ToString()}"); } // We may time out if the process ended before we sent StopTracing command. We can just exit in that case. catch (TimeoutException) { } // On Unix platforms, we may actually get a PNSE since the pipe is gone with the process, and Runtime Client Library // does not know how to distinguish a situation where there is no pipe to begin with, or where the process has exited // before dotnet-counters and got rid of a pipe that once existed. // Since we are catching this in StopMonitor() we know that the pipe once existed (otherwise the exception would've // been thrown in StartMonitor directly) catch (PlatformNotSupportedException) { } // On non-abrupt exits, the socket may be already closed by the runtime and we won't be able to send a stop request through it. catch (ServerNotAvailableException) { } _renderer.Stop(); }
public async Task <int> Monitor(CancellationToken ct, List <string> counter_list, string counters, IConsole console, int processId, int refreshInterval, string name) { if (!ValidateAndSetProcessId(processId, name)) { return(0); } try { InitializeCounterList(counters, counter_list); _ct = ct; _console = console; _interval = refreshInterval; _renderer = new ConsoleWriter(); if (!BuildDiagnosticsClient()) { return(0); } int ret = await Start(); ProcessLauncher.Launcher.Cleanup(); return(ret); } catch (OperationCanceledException) { try { _session.Stop(); } catch (Exception) {} // Swallow all exceptions for now. console.Out.WriteLine($"Complete"); return(1); } }
public Task <Stream> StartCpuTrace(int pid, int durationSeconds, CancellationToken cancellationToken) { if ((durationSeconds < 1) || (durationSeconds > MaxTraceSeconds)) { throw new InvalidOperationException("Invalid duration"); } //TODO Should we limit only 1 trace per file? var client = new DiagnosticsClient(pid); //TODO Pull event providers from the configuration. var cpuProviders = new EventPipeProvider[] { new EventPipeProvider("Microsoft-DotNETCore-SampleProfiler", System.Diagnostics.Tracing.EventLevel.Informational), new EventPipeProvider("Microsoft-Windows-DotNETRuntime", System.Diagnostics.Tracing.EventLevel.Informational, (long)Tracing.Parsers.ClrTraceEventParser.Keywords.Default) }; EventPipeSession session = client.StartEventPipeSession(cpuProviders, requestRundown: true); CancellationTokenSource linkedTokenSource = CancellationTokenSource.CreateLinkedTokenSource(_tokenSource.Token, cancellationToken); Task traceTask = Task.Run(async() => { try { await Task.Delay(TimeSpan.FromSeconds(durationSeconds), linkedTokenSource.Token); } finally { session.Stop(); linkedTokenSource.Dispose(); //We rely on the caller to Dispose the EventStream file. } }, CancellationToken.None); return(Task.FromResult(session.EventStream)); }
private static void StopSession(EventPipeSession session) { try { session.Stop(); } catch (EndOfStreamException) { // If the app we're monitoring exits abruptly, this may throw in which case we just swallow the exception and exit gracefully. } // We may time out if the process ended before we sent StopTracing command. We can just exit in that case. catch (TimeoutException) { } // On Unix platforms, we may actually get a PNSE since the pipe is gone with the process, and Runtime Client Library // does not know how to distinguish a situation where there is no pipe to begin with, or where the process has exited // before collection started and got rid of a pipe that once existed. // Since we are catching this at the end of a session we know that the pipe once existed (otherwise the exception would've // been thrown at the beginning directly) catch (PlatformNotSupportedException) { } // On non-abrupt exits, the socket may be already closed by the runtime and we won't be able to send a stop request through it. catch (ServerNotAvailableException) { } }
public void Dispose() { try { _session?.Stop(); } catch (ServerNotAvailableException) { } _session?.Dispose(); }
public async Task <int> Monitor(CancellationToken ct, List <string> counter_list, string counters, IConsole console, int processId, int refreshInterval, string name, string diagnosticPort, bool resumeRuntime) { if (!ProcessLauncher.Launcher.HasChildProc && !CommandUtils.ValidateArgumentsForAttach(processId, name, diagnosticPort, out _processId)) { return(0); } shouldExit = new ManualResetEvent(false); _ct.Register(() => shouldExit.Set()); DiagnosticsClientBuilder builder = new DiagnosticsClientBuilder("dotnet-counters", 10); using (DiagnosticsClientHolder holder = await builder.Build(ct, _processId, diagnosticPort, showChildIO: false, printLaunchCommand: false)) { if (holder == null) { return(1); } try { InitializeCounterList(counters, counter_list); _ct = ct; _console = console; _interval = refreshInterval; _renderer = new ConsoleWriter(); _diagnosticsClient = holder.Client; shouldResumeRuntime = ProcessLauncher.Launcher.HasChildProc || !string.IsNullOrEmpty(diagnosticPort) || resumeRuntime; int ret = await Start(); ProcessLauncher.Launcher.Cleanup(); return(ret); } catch (OperationCanceledException) { try { _session.Stop(); } catch (Exception) { } // Swallow all exceptions for now. console.Out.WriteLine($"Complete"); return(1); } } }
public void Stop() { if (_process != null) { _session.Stop(); _counters = null; _task = null; _process = null; } }
public async Task <int> Monitor(CancellationToken ct, List <string> counter_list, IConsole console, int processId, int refreshInterval, string name) { if (name != null) { if (processId != 0) { Console.WriteLine("Can only specify either --name or --process-id option."); return(0); } processId = CommandUtils.FindProcessIdWithName(name); if (processId < 0) { return(0); } } try { _ct = ct; _counterList = counter_list; // NOTE: This variable name has an underscore because that's the "name" that the CLI displays. System.CommandLine doesn't like it if we change the variable to camelcase. _console = console; _processId = processId; _interval = refreshInterval; _renderer = new ConsoleWriter(); _diagnosticsClient = new DiagnosticsClient(processId); return(await Start()); } catch (OperationCanceledException) { try { _session.Stop(); } catch (Exception) {} // Swallow all exceptions for now. console.Out.WriteLine($"Complete"); return(1); } }
private static void StopSession(EventPipeSession session) { try { session.Stop(); } catch (EndOfStreamException) { // If the app we're monitoring exits abruptly, this may throw in which case we just swallow the exception and exit gracefully. } // We may time out if the process ended before we sent StopTracing command. We can just exit in that case. catch (TimeoutException) { } // On Unix platforms, we may actually get a PNSE since the pipe is gone with the process, and Runtime Client Library // does not know how to distinguish a situation where there is no pipe to begin with, or where the process has exited // before dotnet-counters and got rid of a pipe that once existed. // Since we are catching this in StopMonitor() we know that the pipe once existed (otherwise the exception would've // been thrown in StartMonitor directly) catch (PlatformNotSupportedException) { } }
/// <summary> /// Collects a diagnostic trace from a currently running process. /// </summary> /// <param name="ct">The cancellation token</param> /// <param name="console"></param> /// <param name="processId">The process to collect the trace from.</param> /// <param name="output">The output path for the collected trace data.</param> /// <param name="buffersize">Sets the size of the in-memory circular buffer in megabytes.</param> /// <param name="providers">A list of EventPipe providers to be enabled. This is in the form 'Provider[,Provider]', where Provider is in the form: 'KnownProviderName[:Flags[:Level][:KeyValueArgs]]', and KeyValueArgs is in the form: '[key1=value1][;key2=value2]'</param> /// <param name="profile">A named pre-defined set of provider configurations that allows common tracing scenarios to be specified succinctly.</param> /// <param name="format">The desired format of the created trace file.</param> /// <param name="duration">The duration of trace to be taken. </param> /// <param name="clrevents">A list of CLR events to be emitted.</param> /// <param name="clreventlevel">The verbosity level of CLR events</param> /// <returns></returns> private static async Task <int> Collect(CancellationToken ct, IConsole console, int processId, FileInfo output, uint buffersize, string providers, string profile, TraceFileFormat format, TimeSpan duration, string clrevents, string clreventlevel) { try { Debug.Assert(output != null); Debug.Assert(profile != null); bool hasConsole = console.GetTerminal() != null; if (hasConsole) { Console.Clear(); } if (processId < 0) { Console.Error.WriteLine("Process ID should not be negative."); return(ErrorCodes.ArgumentError); } else if (processId == 0) { Console.Error.WriteLine("--process-id is required"); return(ErrorCodes.ArgumentError); } if (profile.Length == 0 && providers.Length == 0 && clrevents.Length == 0) { Console.Out.WriteLine("No profile or providers specified, defaulting to trace profile 'cpu-sampling'"); profile = "cpu-sampling"; } Dictionary <string, string> enabledBy = new Dictionary <string, string>(); var providerCollection = Extensions.ToProviders(providers); foreach (EventPipeProvider providerCollectionProvider in providerCollection) { enabledBy[providerCollectionProvider.Name] = "--providers "; } if (profile.Length != 0) { var selectedProfile = ListProfilesCommandHandler.DotNETRuntimeProfiles .FirstOrDefault(p => p.Name.Equals(profile, StringComparison.OrdinalIgnoreCase)); if (selectedProfile == null) { Console.Error.WriteLine($"Invalid profile name: {profile}"); return(ErrorCodes.ArgumentError); } Profile.MergeProfileAndProviders(selectedProfile, providerCollection, enabledBy); } // Parse --clrevents parameter if (clrevents.Length != 0) { // Ignore --clrevents if CLR event provider was already specified via --profile or --providers command. if (enabledBy.ContainsKey(Extensions.CLREventProviderName)) { Console.WriteLine($"The argument --clrevents {clrevents} will be ignored because the CLR provider was configured via either --profile or --providers command."); } else { var clrProvider = Extensions.ToCLREventPipeProvider(clrevents, clreventlevel); providerCollection.Add(clrProvider); enabledBy[Extensions.CLREventProviderName] = "--clrevents"; } } if (providerCollection.Count <= 0) { Console.Error.WriteLine("No providers were specified to start a trace."); return(ErrorCodes.ArgumentError); } PrintProviders(providerCollection, enabledBy); var process = Process.GetProcessById(processId); var shouldExit = new ManualResetEvent(false); var shouldStopAfterDuration = duration != default(TimeSpan); var failed = false; var terminated = false; var rundownRequested = false; System.Timers.Timer durationTimer = null; ct.Register(() => shouldExit.Set()); var diagnosticsClient = new DiagnosticsClient(processId); using (VirtualTerminalMode vTermMode = VirtualTerminalMode.TryEnable()) { EventPipeSession session = null; try { session = diagnosticsClient.StartEventPipeSession(providerCollection, true); } catch (DiagnosticsClientException e) { Console.Error.WriteLine($"Unable to start a tracing session: {e.ToString()}"); } if (session == null) { Console.Error.WriteLine("Unable to create session."); return(ErrorCodes.SessionCreationError); } if (shouldStopAfterDuration) { durationTimer = new System.Timers.Timer(duration.TotalMilliseconds); durationTimer.Elapsed += (s, e) => shouldExit.Set(); durationTimer.AutoReset = false; } var collectingTask = new Task(() => { try { var stopwatch = new Stopwatch(); durationTimer?.Start(); stopwatch.Start(); using (var fs = new FileStream(output.FullName, FileMode.Create, FileAccess.Write)) { Console.Out.WriteLine($"Process : {process.MainModule.FileName}"); Console.Out.WriteLine($"Output File : {fs.Name}"); if (shouldStopAfterDuration) { Console.Out.WriteLine($"Trace Duration : {duration.ToString(@"dd\:hh\:mm\:ss")}"); } Console.Out.WriteLine("\n\n"); var buffer = new byte[16 * 1024]; while (true) { int nBytesRead = session.EventStream.Read(buffer, 0, buffer.Length); if (nBytesRead <= 0) { break; } fs.Write(buffer, 0, nBytesRead); if (!rundownRequested) { if (hasConsole) { lineToClear = Console.CursorTop - 1; ResetCurrentConsoleLine(vTermMode.IsEnabled); } Console.Out.WriteLine($"[{stopwatch.Elapsed.ToString(@"dd\:hh\:mm\:ss")}]\tRecording trace {GetSize(fs.Length)}"); Console.Out.WriteLine("Press <Enter> or <Ctrl+C> to exit..."); Debug.WriteLine($"PACKET: {Convert.ToBase64String(buffer, 0, nBytesRead)} (bytes {nBytesRead})"); } } } } catch (Exception ex) { failed = true; Console.Error.WriteLine($"[ERROR] {ex.ToString()}"); } finally { terminated = true; shouldExit.Set(); } }); collectingTask.Start(); do { while (!Console.KeyAvailable && !shouldExit.WaitOne(250)) { } } while (!shouldExit.WaitOne(0) && Console.ReadKey(true).Key != ConsoleKey.Enter); if (!terminated) { durationTimer?.Stop(); if (hasConsole) { lineToClear = Console.CursorTop; ResetCurrentConsoleLine(vTermMode.IsEnabled); } Console.Out.WriteLine("Stopping the trace. This may take up to minutes depending on the application being traced."); rundownRequested = true; session.Stop(); } await collectingTask; } Console.Out.WriteLine(); Console.Out.WriteLine("Trace completed."); if (format != TraceFileFormat.NetTrace) { TraceFileFormatConverter.ConvertToFormat(format, output.FullName); } return(failed ? ErrorCodes.TracingError : 0); } catch (Exception ex) { Console.Error.WriteLine($"[ERROR] {ex.ToString()}"); return(ErrorCodes.UnknownError); } }
public async Task <int> Monitor( CancellationToken ct, List <string> counter_list, string counters, IConsole console, int processId, int refreshInterval, string name, string diagnosticPort, bool resumeRuntime, int maxHistograms, int maxTimeSeries) { try { // System.CommandLine does have an option to specify arguments as uint and it would validate they are non-negative. However the error // message is "Cannot parse argument '-1' for option '--maxTimeSeries' as expected type System.UInt32" which is not as user friendly. // If there was another option to leverage System.CommandLine that provides a little more user friendly error message we could switch // to it. ValidateNonNegative(maxHistograms, nameof(maxHistograms)); ValidateNonNegative(maxTimeSeries, nameof(maxTimeSeries)); if (!ProcessLauncher.Launcher.HasChildProc && !CommandUtils.ValidateArgumentsForAttach(processId, name, diagnosticPort, out _processId)) { return(ReturnCode.ArgumentError); } _ct.Register(() => _shouldExit.TrySetResult(ReturnCode.Ok)); DiagnosticsClientBuilder builder = new DiagnosticsClientBuilder("dotnet-counters", 10); using (DiagnosticsClientHolder holder = await builder.Build(ct, _processId, diagnosticPort, showChildIO: false, printLaunchCommand: false)) { if (holder == null) { return(ReturnCode.Ok); } try { _console = console; // the launch command may misinterpret app arguments as the old space separated // provider list so we need to ignore it in that case _counterList = ConfigureCounters(counters, _processId != 0 ? counter_list : null); _ct = ct; _interval = refreshInterval; _maxHistograms = maxHistograms; _maxTimeSeries = maxTimeSeries; _renderer = new ConsoleWriter(); _diagnosticsClient = holder.Client; _resumeRuntime = resumeRuntime; int ret = await Start(); ProcessLauncher.Launcher.Cleanup(); return(ret); } catch (OperationCanceledException) { try { _session.Stop(); } catch (Exception) { } // Swallow all exceptions for now. console.Out.WriteLine($"Complete"); return(ReturnCode.Ok); } } } catch (CommandLineErrorException e) { console.Error.WriteLine(e.Message); return(ReturnCode.ArgumentError); } }
public void Stop() { m_session.Stop(); }
/// <summary> /// Collects a diagnostic trace from a currently running process or launch a child process and trace it. /// Append -- to the collect command to instruct the tool to run a command and trace it immediately. By default the IO from this process is hidden, but the --show-child-io option may be used to show the child process IO. /// </summary> /// <param name="ct">The cancellation token</param> /// <param name="console"></param> /// <param name="processId">The process to collect the trace from.</param> /// <param name="name">The name of process to collect the trace from.</param> /// <param name="output">The output path for the collected trace data.</param> /// <param name="buffersize">Sets the size of the in-memory circular buffer in megabytes.</param> /// <param name="providers">A list of EventPipe providers to be enabled. This is in the form 'Provider[,Provider]', where Provider is in the form: 'KnownProviderName[:Flags[:Level][:KeyValueArgs]]', and KeyValueArgs is in the form: '[key1=value1][;key2=value2]'</param> /// <param name="profile">A named pre-defined set of provider configurations that allows common tracing scenarios to be specified succinctly.</param> /// <param name="format">The desired format of the created trace file.</param> /// <param name="duration">The duration of trace to be taken. </param> /// <param name="clrevents">A list of CLR events to be emitted.</param> /// <param name="clreventlevel">The verbosity level of CLR events</param> /// <param name="port">Path to the diagnostic port to be created.</param> /// <param name="showchildio">Should IO from a child process be hidden.</param> /// <returns></returns> private static async Task <int> Collect(CancellationToken ct, IConsole console, int processId, FileInfo output, uint buffersize, string providers, string profile, TraceFileFormat format, TimeSpan duration, string clrevents, string clreventlevel, string name, string diagnosticPort, bool showchildio) { int ret = 0; bool collectionStopped = false; bool cancelOnEnter = true; bool cancelOnCtrlC = true; bool printStatusOverTime = true; try { Debug.Assert(output != null); Debug.Assert(profile != null); if (ProcessLauncher.Launcher.HasChildProc && showchildio) { // If showing IO, then all IO (including CtrlC) behavior is delegated to the child process cancelOnCtrlC = false; cancelOnEnter = false; printStatusOverTime = false; } else { cancelOnCtrlC = true; cancelOnEnter = !Console.IsInputRedirected; printStatusOverTime = !Console.IsInputRedirected; } if (!cancelOnCtrlC) { ct = CancellationToken.None; } if (!ProcessLauncher.Launcher.HasChildProc) { if (showchildio) { Console.WriteLine("--show-child-io must not be specified when attaching to a process"); return(ErrorCodes.ArgumentError); } if (CommandUtils.ValidateArgumentsForAttach(processId, name, diagnosticPort, out int resolvedProcessId)) { processId = resolvedProcessId; } else { return(ErrorCodes.ArgumentError); } } else if (!CommandUtils.ValidateArgumentsForChildProcess(processId, name, diagnosticPort)) { return(ErrorCodes.ArgumentError); } if (profile.Length == 0 && providers.Length == 0 && clrevents.Length == 0) { Console.Out.WriteLine("No profile or providers specified, defaulting to trace profile 'cpu-sampling'"); profile = "cpu-sampling"; } Dictionary <string, string> enabledBy = new Dictionary <string, string>(); var providerCollection = Extensions.ToProviders(providers); foreach (EventPipeProvider providerCollectionProvider in providerCollection) { enabledBy[providerCollectionProvider.Name] = "--providers "; } if (profile.Length != 0) { var selectedProfile = ListProfilesCommandHandler.DotNETRuntimeProfiles .FirstOrDefault(p => p.Name.Equals(profile, StringComparison.OrdinalIgnoreCase)); if (selectedProfile == null) { Console.Error.WriteLine($"Invalid profile name: {profile}"); return(ErrorCodes.ArgumentError); } Profile.MergeProfileAndProviders(selectedProfile, providerCollection, enabledBy); } // Parse --clrevents parameter if (clrevents.Length != 0) { // Ignore --clrevents if CLR event provider was already specified via --profile or --providers command. if (enabledBy.ContainsKey(Extensions.CLREventProviderName)) { Console.WriteLine($"The argument --clrevents {clrevents} will be ignored because the CLR provider was configured via either --profile or --providers command."); } else { var clrProvider = Extensions.ToCLREventPipeProvider(clrevents, clreventlevel); providerCollection.Add(clrProvider); enabledBy[Extensions.CLREventProviderName] = "--clrevents"; } } if (providerCollection.Count <= 0) { Console.Error.WriteLine("No providers were specified to start a trace."); return(ErrorCodes.ArgumentError); } PrintProviders(providerCollection, enabledBy); DiagnosticsClient diagnosticsClient; Process process; DiagnosticsClientBuilder builder = new DiagnosticsClientBuilder("dotnet-trace", 10); bool shouldResumeRuntime = ProcessLauncher.Launcher.HasChildProc || !string.IsNullOrEmpty(diagnosticPort); var shouldExit = new ManualResetEvent(false); ct.Register(() => shouldExit.Set()); using (DiagnosticsClientHolder holder = await builder.Build(ct, processId, diagnosticPort, showChildIO: showchildio, printLaunchCommand: true)) { // if builder returned null, it means we received ctrl+C while waiting for clients to connect. Exit gracefully. if (holder == null) { return(await Task.FromResult(ret)); } diagnosticsClient = holder.Client; if (shouldResumeRuntime) { process = Process.GetProcessById(holder.EndpointInfo.ProcessId); } else { process = Process.GetProcessById(processId); } string processMainModuleFileName = ""; // Reading the process MainModule filename can fail if the target process closes // or isn't fully setup. Retry a few times to attempt to address the issue for (int attempts = 0; true; attempts++) { try { processMainModuleFileName = process.MainModule.FileName; break; } catch { if (attempts > 10) { Console.Error.WriteLine("Unable to examine process."); return(ErrorCodes.SessionCreationError); } Thread.Sleep(200); } } if (String.Equals(output.Name, DefaultTraceName, StringComparison.OrdinalIgnoreCase)) { DateTime now = DateTime.Now; var processMainModuleFileInfo = new FileInfo(processMainModuleFileName); output = new FileInfo($"{processMainModuleFileInfo.Name}_{now:yyyyMMdd}_{now:HHmmss}.nettrace"); } var shouldStopAfterDuration = duration != default(TimeSpan); var rundownRequested = false; System.Timers.Timer durationTimer = null; using (VirtualTerminalMode vTermMode = printStatusOverTime ? VirtualTerminalMode.TryEnable() : null) { EventPipeSession session = null; try { session = diagnosticsClient.StartEventPipeSession(providerCollection, true, (int)buffersize); if (shouldResumeRuntime) { diagnosticsClient.ResumeRuntime(); } } catch (DiagnosticsClientException e) { Console.Error.WriteLine($"Unable to start a tracing session: {e.ToString()}"); } if (session == null) { Console.Error.WriteLine("Unable to create session."); return(ErrorCodes.SessionCreationError); } if (shouldStopAfterDuration) { durationTimer = new System.Timers.Timer(duration.TotalMilliseconds); durationTimer.Elapsed += (s, e) => shouldExit.Set(); durationTimer.AutoReset = false; } var stopwatch = new Stopwatch(); durationTimer?.Start(); stopwatch.Start(); LineRewriter rewriter = null; using (var fs = new FileStream(output.FullName, FileMode.Create, FileAccess.Write)) { Console.Out.WriteLine($"Process : {processMainModuleFileName}"); Console.Out.WriteLine($"Output File : {fs.Name}"); if (shouldStopAfterDuration) { Console.Out.WriteLine($"Trace Duration : {duration.ToString(@"dd\:hh\:mm\:ss")}"); } Console.Out.WriteLine("\n\n"); var fileInfo = new FileInfo(output.FullName); Task copyTask = session.EventStream.CopyToAsync(fs); Task shouldExitTask = copyTask.ContinueWith((task) => shouldExit.Set()); if (printStatusOverTime) { rewriter = new LineRewriter { LineToClear = Console.CursorTop - 1 }; Console.CursorVisible = false; } Action printStatus = () => { if (printStatusOverTime) { rewriter?.RewriteConsoleLine(); fileInfo.Refresh(); Console.Out.WriteLine($"[{stopwatch.Elapsed.ToString(@"dd\:hh\:mm\:ss")}]\tRecording trace {GetSize(fileInfo.Length)}"); Console.Out.WriteLine("Press <Enter> or <Ctrl+C> to exit..."); } if (rundownRequested) { Console.Out.WriteLine("Stopping the trace. This may take up to minutes depending on the application being traced."); } }; while (!shouldExit.WaitOne(100) && !(cancelOnEnter && Console.KeyAvailable && Console.ReadKey(true).Key == ConsoleKey.Enter)) { printStatus(); } // if the CopyToAsync ended early (target program exited, etc.), the we don't need to stop the session. if (!copyTask.Wait(0)) { // Behavior concerning Enter moving text in the terminal buffer when at the bottom of the buffer // is different between Console/Terminals on Windows and Mac/Linux if (!RuntimeInformation.IsOSPlatform(OSPlatform.Windows) && printStatusOverTime && rewriter != null && Math.Abs(Console.CursorTop - Console.BufferHeight) == 1) { rewriter.LineToClear--; } collectionStopped = true; durationTimer?.Stop(); rundownRequested = true; session.Stop(); do { printStatus(); } while (!copyTask.Wait(100)); } // At this point the copyTask will have finished, so wait on the shouldExitTask in case it threw // an exception or had some other interesting behavior shouldExitTask.Wait(); } Console.Out.WriteLine($"\nTrace completed."); if (format != TraceFileFormat.NetTrace) { TraceFileFormatConverter.ConvertToFormat(format, output.FullName); } } if (!collectionStopped && !ct.IsCancellationRequested) { // If the process is shutting down by itself print the return code from the process. // Capture this before leaving the using, as the Dispose of the DiagnosticsClientHolder // may terminate the target process causing it to have the wrong error code if (ProcessLauncher.Launcher.HasChildProc && ProcessLauncher.Launcher.ChildProc.WaitForExit(5000)) { ret = ProcessLauncher.Launcher.ChildProc.ExitCode; Console.WriteLine($"Process exited with code '{ret}'."); collectionStopped = true; } } } } catch (Exception ex) { Console.Error.WriteLine($"[ERROR] {ex.ToString()}"); ret = ErrorCodes.TracingError; collectionStopped = true; } finally { if (printStatusOverTime) { if (console.GetTerminal() != null) { Console.CursorVisible = true; } } if (ProcessLauncher.Launcher.HasChildProc) { if (!collectionStopped || ct.IsCancellationRequested) { ret = ErrorCodes.TracingError; } // If we launched a child proc that hasn't exited yet, terminate it before we exit. if (!ProcessLauncher.Launcher.ChildProc.HasExited) { ProcessLauncher.Launcher.ChildProc.Kill(); } } } return(await Task.FromResult(ret)); }
public void ProcessEvents( string applicationName, string serviceName, int processId, string replicaName, IDictionary <string, string> metrics, CancellationToken cancellationToken) { var hasEventPipe = false; for (var i = 0; i < 10; ++i) { if (DiagnosticsClient.GetPublishedProcesses().Contains(processId)) { hasEventPipe = true; break; } if (cancellationToken.IsCancellationRequested) { return; } Thread.Sleep(500); } if (!hasEventPipe) { _logger.LogInformation("Process id {PID}, does not support event pipe", processId); return; } _logger.LogInformation("Listening for event pipe events for {ServiceName} on process id {PID}", replicaName, processId); // Create the logger factory for this replica using var loggerFactory = LoggerFactory.Create(builder => ConfigureLogging(serviceName, replicaName, builder)); var processor = new SimpleSpanProcessor(CreateSpanExporter(serviceName, replicaName)); var providers = new List <EventPipeProvider>() { // Runtime Metrics new EventPipeProvider( SystemRuntimeEventSourceName, EventLevel.Informational, (long)ClrTraceEventParser.Keywords.None, new Dictionary <string, string>() { { "EventCounterIntervalSec", "1" } } ), new EventPipeProvider( MicrosoftAspNetCoreHostingEventSourceName, EventLevel.Informational, (long)ClrTraceEventParser.Keywords.None, new Dictionary <string, string>() { { "EventCounterIntervalSec", "1" } } ), new EventPipeProvider( GrpcAspNetCoreServer, EventLevel.Informational, (long)ClrTraceEventParser.Keywords.None, new Dictionary <string, string>() { { "EventCounterIntervalSec", "1" } } ), // Application Metrics new EventPipeProvider( applicationName, EventLevel.Informational, (long)ClrTraceEventParser.Keywords.None, new Dictionary <string, string>() { { "EventCounterIntervalSec", "1" } } ), // Logging new EventPipeProvider( MicrosoftExtensionsLoggingProviderName, EventLevel.LogAlways, (long)(LoggingEventSource.Keywords.JsonMessage | LoggingEventSource.Keywords.FormattedMessage) ), // Distributed Tracing // Activity correlation new EventPipeProvider(TplEventSource, keywords: 0x80, eventLevel: EventLevel.LogAlways), // Diagnostic source events new EventPipeProvider(DiagnosticSourceEventSource, keywords: 0x1 | 0x2, eventLevel: EventLevel.Verbose, arguments: new Dictionary <string, string> { { "FilterAndPayloadSpecs", DiagnosticFilterString } }) }; while (!cancellationToken.IsCancellationRequested) { EventPipeSession session = null; var client = new DiagnosticsClient(processId); try { session = client.StartEventPipeSession(providers); } catch (EndOfStreamException) { break; } // If the process has already exited, a ServerNotAvailableException will be thrown. catch (ServerNotAvailableException) { break; } catch (Exception ex) { if (!cancellationToken.IsCancellationRequested) { _logger.LogDebug(0, ex, "Failed to start the event pipe session"); } // We can't even start the session, wait until the process boots up again to start another metrics thread break; } void StopSession() { try { session.Stop(); } catch (EndOfStreamException) { // If the app we're monitoring exits abruptly, this may throw in which case we just swallow the exception and exit gracefully. } // We may time out if the process ended before we sent StopTracing command. We can just exit in that case. catch (TimeoutException) { } // On Unix platforms, we may actually get a PNSE since the pipe is gone with the process, and Runtime Client Library // does not know how to distinguish a situation where there is no pipe to begin with, or where the process has exited // before dotnet-counters and got rid of a pipe that once existed. // Since we are catching this in StopMonitor() we know that the pipe once existed (otherwise the exception would've // been thrown in StartMonitor directly) catch (PlatformNotSupportedException) { } // If the process has already exited, a ServerNotAvailableException will be thrown. // This can always race with tye shutting down and a process being restarted on exiting. catch (ServerNotAvailableException) { } } using var _ = cancellationToken.Register(() => StopSession()); try { var source = new EventPipeEventSource(session.EventStream); // Distribued Tracing HandleDistributedTracingEvents(source, processor); // Metrics HandleEventCounters(source, metrics); // Logging HandleLoggingEvents(source, loggerFactory, replicaName); source.Process(); } catch (DiagnosticsClientException ex) { _logger.LogDebug(0, ex, "Failed to start the event pipe session"); } catch (Exception) { // This fails if stop is called or if the process dies } finally { session?.Dispose(); } } _logger.LogInformation("Event pipe collection completed for {ServiceName} on process id {PID}", replicaName, processId); }
public async Task ProcessEvents(int processId, CancellationToken cancellationToken) { var hasEventPipe = false; for (int i = 0; i < 10; ++i) { if (DiagnosticsClient.GetPublishedProcesses().Contains(processId)) { hasEventPipe = true; break; } cancellationToken.ThrowIfCancellationRequested(); await Task.Delay(500); } if (!hasEventPipe) { _logger.LogInformation("Process id {PID}, does not support event pipe", processId); return; } _logger.LogInformation("Listening for event pipe events for {ServiceName} on process id {PID}", _dimValues[1], processId); while (!cancellationToken.IsCancellationRequested) { EventPipeSession session = null; var client = new DiagnosticsClient(processId); try { session = client.StartEventPipeSession(_sourceConfig.GetProviders()); } catch (EndOfStreamException) { break; } catch (Exception ex) { if (!cancellationToken.IsCancellationRequested) { _logger.LogDebug(0, ex, "Failed to start the event pipe session"); } // We can't even start the session, wait until the process boots up again to start another metrics thread break; } void StopSession() { try { session.Stop(); } catch (EndOfStreamException) { // If the app we're monitoring exits abruptly, this may throw in which case we just swallow the exception and exit gracefully. } // We may time out if the process ended before we sent StopTracing command. We can just exit in that case. catch (TimeoutException) { } // On Unix platforms, we may actually get a PNSE since the pipe is gone with the process, and Runtime Client Library // does not know how to distinguish a situation where there is no pipe to begin with, or where the process has exited // before dotnet-counters and got rid of a pipe that once existed. // Since we are catching this in StopMonitor() we know that the pipe once existed (otherwise the exception would've // been thrown in StartMonitor directly) catch (PlatformNotSupportedException) { } } using var _ = cancellationToken.Register(() => StopSession()); try { var source = new EventPipeEventSource(session.EventStream); // Metrics HandleEventCounters(source); // Logging HandleLoggingEvents(source); source.Process(); } catch (DiagnosticsClientException ex) { _logger.LogDebug(0, ex, "Failed to start the event pipe session"); } catch (Exception) { // This fails if stop is called or if the process dies } finally { session?.Dispose(); } } _logger.LogInformation("Event pipe collection completed for {ServiceName} on process id {PID}", _dimValues[1], processId); }
public void Dispose() { _session?.Stop(); _session?.Dispose(); }
public static async Task <int> Collect(ICollection <Action <long> > sizeChangeCallbacks, CollectTrace.Tracing tracing, FileInfo output, TraceFileFormat format = TraceFileFormat.NetTrace) { var processId = Process.GetCurrentProcess().Id; var providerCollection = CreateProviderCollection(); var diagnosticsClient = new DiagnosticsClient(processId); EventPipeSession session = null; try { session = diagnosticsClient.StartEventPipeSession(providerCollection, true); } catch (DiagnosticsClientException e) { Console.Error.WriteLine($"Unable to start a tracing session: {e.ToString()}"); } if (session == null) { Console.Error.WriteLine("Unable to create session."); return(ErrorCodes.SessionCreationError); } var failed = false; var terminated = false; try { var collectingTask = new Task(() => { try { using (var fs = new FileStream(output.FullName, FileMode.Create, FileAccess.Write)) { var buffer = new byte[16 * 1024]; while (true) { int nBytesRead = session.EventStream.Read(buffer, 0, buffer.Length); if (nBytesRead <= 0) { break; } fs.Write(buffer, 0, nBytesRead); foreach (var sizeChangeCallback in sizeChangeCallbacks) { sizeChangeCallback(fs.Length); } } } } catch (Exception ex) { failed = true; Console.Error.WriteLine($"[ERROR] {ex.ToString()}"); } finally { terminated = true; } }); collectingTask.Start(); tracing.Wait(); session.Stop(); await collectingTask; //if (format != TraceFileFormat.NetTrace) // TraceFileFormatConverter.ConvertToFormat(format, output.FullName); return(failed ? ErrorCodes.TracingError : 0); } catch (Exception ex) { Console.Error.WriteLine($"[ERROR] {ex.ToString()}"); return(ErrorCodes.UnknownError); } }
private int Validate() { var isClean = EnsureCleanEnvironment(); if (!isClean) { return(-1); } // CollectTracing returns before EventPipe::Enable has returned, so the // the sources we want to listen for may not have been enabled yet. // We'll use this sentinel EventSource to check if Enable has finished ManualResetEvent sentinelEventReceived = new ManualResetEvent(false); var sentinelTask = new Task(() => { Logger.logger.Log("Started sending sentinel events..."); while (!sentinelEventReceived.WaitOne(50)) { SentinelEventSource.Log.SentinelEvent(); } Logger.logger.Log("Stopped sending sentinel events"); }); sentinelTask.Start(); int processId = Process.GetCurrentProcess().Id; object threadSync = new object(); // for locking eventpipeSession access Func <int> optionalTraceValidationCallback = null; DiagnosticsClient client = new DiagnosticsClient(processId); var readerTask = new Task(() => { Logger.logger.Log("Connecting to EventPipe..."); try { _eventPipeSession = client.StartEventPipeSession(_testProviders.Concat(_sentinelProviders)); } catch (DiagnosticsClientException ex) { Logger.logger.Log("Failed to connect to EventPipe!"); Logger.logger.Log(ex.ToString()); throw new ApplicationException("Failed to connect to EventPipe"); } using var eventPipeStream = new StreamProxy(_eventPipeSession.EventStream); Logger.logger.Log("Creating EventPipeEventSource..."); using EventPipeEventSource source = new EventPipeEventSource(eventPipeStream); Logger.logger.Log("EventPipeEventSource created"); source.Dynamic.All += (eventData) => { try { if (eventData.ProviderName == "SentinelEventSource") { if (!sentinelEventReceived.WaitOne(0)) { Logger.logger.Log("Saw sentinel event"); } sentinelEventReceived.Set(); } else if (_actualEventCounts.TryGetValue(eventData.ProviderName, out _)) { _actualEventCounts[eventData.ProviderName]++; } else { Logger.logger.Log($"Saw new provider '{eventData.ProviderName}'"); _actualEventCounts[eventData.ProviderName] = 1; } } catch (Exception e) { Logger.logger.Log("Exception in Dynamic.All callback " + e.ToString()); } }; Logger.logger.Log("Dynamic.All callback registered"); if (_optionalTraceValidator != null) { Logger.logger.Log("Running optional trace validator"); optionalTraceValidationCallback = _optionalTraceValidator(source); Logger.logger.Log("Finished running optional trace validator"); } Logger.logger.Log("Starting stream processing..."); try { source.Process(); _droppedEvents = source.EventsLost; } catch (Exception) { Logger.logger.Log($"Exception thrown while reading; dumping culprit stream to disk..."); eventPipeStream.DumpStreamToDisk(); // rethrow it to fail the test throw; } Logger.logger.Log("Stopping stream processing"); Logger.logger.Log($"Dropped {source.EventsLost} events"); }); readerTask.Start(); sentinelEventReceived.WaitOne(); Logger.logger.Log("Starting event generating action..."); _eventGeneratingAction(); Logger.logger.Log("Stopping event generating action"); // Should throw if the reader task throws any exceptions var tokenSource = new CancellationTokenSource(); CancellationToken ct = tokenSource.Token; readerTask.ContinueWith((task) => { // if our reader task died earlier, we need to break the infinite wait below. // We'll allow the AggregateException to be thrown and fail the test though. Logger.logger.Log($"Task stats: isFaulted: {task.IsFaulted}, Exception == null: {task.Exception == null}"); if (task.IsFaulted || task.Exception != null) { tokenSource.Cancel(); } return(task); }); var stopTask = Task.Run(() => { Logger.logger.Log("Sending StopTracing command..."); lock (threadSync) // eventpipeSession { _eventPipeSession.Stop(); } Logger.logger.Log("Finished StopTracing command"); }, ct); try { Task.WaitAll(new Task[] { readerTask, stopTask }, ct); } catch (OperationCanceledException) { Logger.logger.Log($"A task faulted"); Logger.logger.Log($"\treaderTask.IsFaulted = {readerTask.IsFaulted}"); if (readerTask.Exception != null) { throw readerTask.Exception; } return(-1); } Logger.logger.Log("Reader task finished"); Logger.logger.Log($"Dropped {_droppedEvents} events"); foreach (var(provider, expectedCount) in _expectedEventCounts) { if (_actualEventCounts.TryGetValue(provider, out var actualCount)) { if (!expectedCount.Validate(actualCount)) { return(Fail($"Event count mismatch for provider \"{provider}\": expected {expectedCount}, but saw {actualCount}")); } } else { return(Fail($"No events for provider \"{provider}\"")); } } if (optionalTraceValidationCallback != null) { Logger.logger.Log("Validating optional callback..."); // reader thread should be dead now, no need to lock return(optionalTraceValidationCallback()); } else { return(100); } }
/// <summary> /// Reports a stack trace /// </summary> /// <param name="ct">The cancellation token</param> /// <param name="console"></param> /// <param name="processId">The process to report the stack from.</param> /// <param name="name">The name of process to report the stack from.</param> /// <param name="output">The output path for the collected trace data.</param> /// <param name="duration">The duration of to trace the target for. </param> /// <returns></returns> private static async Task <int> Report(CancellationToken ct, IConsole console, int processId, string name, TimeSpan duration) { string tempNetTraceFilename = Path.GetRandomFileName() + ".nettrace"; string tempEtlxFilename = ""; try { // Either processName or processId has to be specified. if (!string.IsNullOrEmpty(name)) { if (processId != 0) { Console.WriteLine("Can only specify either --name or --process-id option."); return(-1); } processId = CommandUtils.FindProcessIdWithName(name); if (processId < 0) { return(-1); } } if (processId < 0) { console.Error.WriteLine("Process ID should not be negative."); return(-1); } else if (processId == 0) { console.Error.WriteLine("--process-id is required"); return(-1); } var client = new DiagnosticsClient(processId); var providers = new List <EventPipeProvider>() { new EventPipeProvider("Microsoft-DotNETCore-SampleProfiler", EventLevel.Informational) }; // collect a *short* trace with stack samples // the hidden '--duration' flag can increase the time of this trace in case 10ms // is too short in a given environment, e.g., resource constrained systems // N.B. - This trace INCLUDES rundown. For sufficiently large applications, it may take non-trivial time to collect // the symbol data in rundown. using (EventPipeSession session = client.StartEventPipeSession(providers)) using (FileStream fs = File.OpenWrite(tempNetTraceFilename)) { Task copyTask = session.EventStream.CopyToAsync(fs); await Task.Delay(duration); session.Stop(); // check if rundown is taking more than 5 seconds and add comment to report Task timeoutTask = Task.Delay(TimeSpan.FromSeconds(5)); Task completedTask = await Task.WhenAny(copyTask, timeoutTask); if (completedTask == timeoutTask) { console.Out.WriteLine($"# Sufficiently large applications can cause this command to take non-trivial amounts of time"); } await copyTask; } // using the generated trace file, symbolocate and compute stacks. tempEtlxFilename = TraceLog.CreateFromEventPipeDataFile(tempNetTraceFilename); using (var symbolReader = new SymbolReader(System.IO.TextWriter.Null) { SymbolPath = SymbolPath.MicrosoftSymbolServerPath }) using (var eventLog = new TraceLog(tempEtlxFilename)) { var stackSource = new MutableTraceEventStackSource(eventLog) { OnlyManagedCodeStacks = true }; var computer = new SampleProfilerThreadTimeComputer(eventLog, symbolReader); computer.GenerateThreadTimeStacks(stackSource); var samplesForThread = new Dictionary <int, List <StackSourceSample> >(); stackSource.ForEach((sample) => { var stackIndex = sample.StackIndex; while (!stackSource.GetFrameName(stackSource.GetFrameIndex(stackIndex), false).StartsWith("Thread (")) { stackIndex = stackSource.GetCallerIndex(stackIndex); } // long form for: int.Parse(threadFrame["Thread (".Length..^1)]) // Thread id is in the frame name as "Thread (<ID>)" string template = "Thread ("; string threadFrame = stackSource.GetFrameName(stackSource.GetFrameIndex(stackIndex), false); int threadId = int.Parse(threadFrame.Substring(template.Length, threadFrame.Length - (template.Length + 1))); if (samplesForThread.TryGetValue(threadId, out var samples)) { samples.Add(sample); } else { samplesForThread[threadId] = new List <StackSourceSample>() { sample }; } }); // For every thread recorded in our trace, print the first stack foreach (var(threadId, samples) in samplesForThread) { #if DEBUG console.Out.WriteLine($"Found {samples.Count} stacks for thread 0x{threadId:X}"); #endif PrintStack(console, threadId, samples[0], stackSource); } } } catch (Exception ex) { Console.Error.WriteLine($"[ERROR] {ex.ToString()}"); return(-1); } finally { if (File.Exists(tempNetTraceFilename)) { File.Delete(tempNetTraceFilename); } if (File.Exists(tempEtlxFilename)) { File.Delete(tempEtlxFilename); } } return(0); }
public static int RunTest() { bool success = true; int allTypesEventCount = 0; int arrayTypeEventCount = 0; int emptyEventCount = 0; int simpleEventCount = 0; try { List <EventPipeProvider> providers = new List <EventPipeProvider> { new EventPipeProvider("MySuperAwesomeEventPipeProvider", EventLevel.Verbose) }; using (EventPipeSession session = ProfilerControlHelpers.AttachEventPipeSessionToSelf(providers)) { TriggerMethod(); ManualResetEvent allEventsReceivedEvent = new ManualResetEvent(false); var source = new EventPipeEventSource(session.EventStream); source.Dynamic.All += (TraceEvent traceEvent) => { if (traceEvent.ProviderName != "MySuperAwesomeEventPipeProvider") { return; } if (traceEvent.EventName == "AllTypesEvent") { success &= ValidateAllTypesEvent(traceEvent); ++allTypesEventCount; } else if (traceEvent.EventName == "EmptyEvent") { success &= ValidateEmptyEvent(traceEvent); ++emptyEventCount; } else if (traceEvent.EventName == "SimpleEvent") { success &= ValidateSimpleEvent(traceEvent, simpleEventCount); ++simpleEventCount; } else if (traceEvent.EventName == "ArrayTypeEvent") { success &= ValidateArrayTypeEvent(traceEvent); ++arrayTypeEventCount; } if (AllEventsReceived(allTypesEventCount, arrayTypeEventCount, emptyEventCount, simpleEventCount)) { allEventsReceivedEvent.Set(); } }; Thread processingThread = new Thread(new ThreadStart(() => { source.Process(); })); processingThread.Start(); // The events are fired in the JITCompilationStarted callback for TriggerMethod, // so by the time we are here, all events should be fired. session.Stop(); allEventsReceivedEvent.WaitOne(TimeSpan.FromSeconds(90)); processingThread.Join(); } } catch (Exception e) { Console.WriteLine($"Exception {e.Message} when trying to attach"); success = false; } if (success && AllEventsReceived(allTypesEventCount, arrayTypeEventCount, emptyEventCount, simpleEventCount)) { return(100); } else { Console.WriteLine("Test validation failed (EventPipeClient.exe)"); Console.WriteLine($" success={success}"); Console.WriteLine($" allTypesEventCount={allTypesEventCount} "); Console.WriteLine($" arrayTypeEventCount={arrayTypeEventCount} "); Console.WriteLine($" emptyEventCount={emptyEventCount}"); Console.WriteLine($" simpleEventCount={simpleEventCount}"); return(-1); } }
public void ProcessEvents(string applicationName, string serviceName, int processId, string replicaName, ReplicaStatus replica, CancellationToken cancellationToken) { var hasEventPipe = false; for (int i = 0; i < 10; ++i) { if (DiagnosticsClient.GetPublishedProcesses().Contains(processId)) { hasEventPipe = true; break; } if (cancellationToken.IsCancellationRequested) { return; } Thread.Sleep(500); } if (!hasEventPipe) { _logger.LogInformation("Process id {PID}, does not support event pipe", processId); return; } _logger.LogInformation("Listening for event pipe events for {ServiceName} on process id {PID}", replicaName, processId); // Create the logger factory for this replica using var loggerFactory = LoggerFactory.Create(builder => ConfigureLogging(serviceName, replicaName, builder)); var processor = new SimpleSpanProcessor(CreateSpanExporter(serviceName, replicaName)); var providers = new List <EventPipeProvider>() { // Runtime Metrics new EventPipeProvider( SystemRuntimeEventSourceName, EventLevel.Informational, (long)ClrTraceEventParser.Keywords.None, new Dictionary <string, string>() { { "EventCounterIntervalSec", "1" } } ), new EventPipeProvider( MicrosoftAspNetCoreHostingEventSourceName, EventLevel.Informational, (long)ClrTraceEventParser.Keywords.None, new Dictionary <string, string>() { { "EventCounterIntervalSec", "1" } } ), new EventPipeProvider( GrpcAspNetCoreServer, EventLevel.Informational, (long)ClrTraceEventParser.Keywords.None, new Dictionary <string, string>() { { "EventCounterIntervalSec", "1" } } ), // Application Metrics new EventPipeProvider( applicationName, EventLevel.Informational, (long)ClrTraceEventParser.Keywords.None, new Dictionary <string, string>() { { "EventCounterIntervalSec", "1" } } ), // Logging new EventPipeProvider( MicrosoftExtensionsLoggingProviderName, EventLevel.LogAlways, (long)(LoggingEventSource.Keywords.JsonMessage | LoggingEventSource.Keywords.FormattedMessage) ), // Distributed Tracing // Activity correlation new EventPipeProvider(TplEventSource, keywords: 0x80, eventLevel: EventLevel.LogAlways), // Diagnostic source events new EventPipeProvider(DiagnosticSourceEventSource, keywords: 0x1 | 0x2, eventLevel: EventLevel.Verbose, arguments: new Dictionary <string, string> { { "FilterAndPayloadSpecs", DiagnosticFilterString } }) }; while (!cancellationToken.IsCancellationRequested) { EventPipeSession session = null; var client = new DiagnosticsClient(processId); try { session = client.StartEventPipeSession(providers); } catch (EndOfStreamException) { break; } catch (Exception ex) { if (!cancellationToken.IsCancellationRequested) { _logger.LogDebug(0, ex, "Failed to start the event pipe session"); } // We can't even start the session, wait until the process boots up again to start another metrics thread break; } void StopSession() { try { session.Stop(); } catch (EndOfStreamException) { // If the app we're monitoring exits abruptly, this may throw in which case we just swallow the exception and exit gracefully. } // We may time out if the process ended before we sent StopTracing command. We can just exit in that case. catch (TimeoutException) { } // On Unix platforms, we may actually get a PNSE since the pipe is gone with the process, and Runtime Client Library // does not know how to distinguish a situation where there is no pipe to begin with, or where the process has exited // before dotnet-counters and got rid of a pipe that once existed. // Since we are catching this in StopMonitor() we know that the pipe once existed (otherwise the exception would've // been thrown in StartMonitor directly) catch (PlatformNotSupportedException) { } } using var _ = cancellationToken.Register(() => StopSession()); try { var source = new EventPipeEventSource(session.EventStream); var activities = new Dictionary <string, ActivityItem>(); source.Dynamic.All += traceEvent => { try { // Uncomment to debug the diagnostics source event source //if (traceEvent.EventName == "Message") //{ // _logger.LogTrace("[" + replicaName + "]:" + traceEvent.PayloadValue(0)); //} //// Distributed tracing // else if (traceEvent.EventName == "Activity1Start/Start") { var listenerEventName = (string)traceEvent.PayloadByName("EventName"); if (traceEvent.PayloadByName("Arguments") is IDictionary <string, object>[] arguments) { string activityId = null; string parentId = null; string operationName = null; string httpMethod = null; string path = null; string spanId = null; string parentSpanId = null; string traceId = null; DateTime startTime = default; ActivityIdFormat idFormat = default; foreach (var arg in arguments) { var key = (string)arg["Key"]; var value = (string)arg["Value"]; if (key == "ActivityId") { activityId = value; } else if (key == "ActivityParentId") { parentId = value; } else if (key == "ActivityOperationName") { operationName = value; } else if (key == "ActivitySpanId") { spanId = value; } else if (key == "ActivityTraceId") { traceId = value; } else if (key == "ActivityParentSpanId") { parentSpanId = value; } else if (key == "Method") { httpMethod = value; } else if (key == "Path") { path = value; } else if (key == "ActivityStartTime") { startTime = new DateTime(long.Parse(value), DateTimeKind.Utc); } else if (key == "ActivityIdFormat") { idFormat = Enum.Parse <ActivityIdFormat>(value); } } if (string.IsNullOrEmpty(activityId)) { // Not a 3.1 application (we can detect this earlier) return; } if (idFormat == ActivityIdFormat.Hierarchical) { // We need W3C to make it work return; } // This is what open telemetry currently does // https://github.com/open-telemetry/opentelemetry-dotnet/blob/4ba732af062ddc2759c02aebbc91335aaa3f7173/src/OpenTelemetry.Collector.AspNetCore/Implementation/HttpInListener.cs#L65-L92 var item = new ActivityItem() { Name = path, SpanId = ActivitySpanId.CreateFromString(spanId), TraceId = ActivityTraceId.CreateFromString(traceId), ParentSpanId = parentSpanId == "0000000000000000" ? default : ActivitySpanId.CreateFromString(parentSpanId), StartTime = startTime, }; item.Attributes[SpanAttributeConstants.HttpMethodKey] = httpMethod; item.Attributes[SpanAttributeConstants.HttpPathKey] = path; activities[activityId] = item; } } else if (traceEvent.EventName == "Activity1Stop/Stop") { var listenerEventName = (string)traceEvent.PayloadByName("EventName"); if (traceEvent.PayloadByName("Arguments") is IDictionary <string, object>[] arguments) { string activityId = null; TimeSpan duration = default; int statusCode = 0; foreach (var arg in arguments) { var key = (string)arg["Key"]; var value = (string)arg["Value"]; if (key == "ActivityId") { activityId = value; } else if (key == "StatusCode") { statusCode = int.Parse(value); } else if (key == "ActivityDuration") { duration = new TimeSpan(long.Parse(value)); } } if (string.IsNullOrEmpty(activityId)) { // Not a 3.1 application (we can detect this earlier) return; } if (activities.TryGetValue(activityId, out var item)) { item.Attributes[SpanAttributeConstants.HttpStatusCodeKey] = statusCode; item.EndTime = item.StartTime + duration; var spanData = new SpanData(item.Name, new SpanContext(item.TraceId, item.SpanId, ActivityTraceFlags.Recorded), item.ParentSpanId, SpanKind.Server, item.StartTime, item.Attributes, Enumerable.Empty <Event>(), Enumerable.Empty <Link>(), null, Status.Ok, item.EndTime); processor.OnEnd(spanData); activities.Remove(activityId); } } } else if (traceEvent.EventName == "Activity2Start/Start") { var listenerEventName = (string)traceEvent.PayloadByName("EventName"); _logger.LogDebug("[" + replicaName + "]: " + listenerEventName + " fired"); } else if (traceEvent.EventName == "Activity2Stop/Stop") { var listenerEventName = (string)traceEvent.PayloadByName("EventName"); _logger.LogDebug("[" + replicaName + "]: " + listenerEventName + " fired"); } // Metrics else if (traceEvent.EventName.Equals("EventCounters")) { var payloadVal = (IDictionary <string, object>)traceEvent.PayloadValue(0); var eventPayload = (IDictionary <string, object>)payloadVal["Payload"]; ICounterPayload payload = CounterPayload.FromPayload(eventPayload); replica.Metrics[traceEvent.ProviderName + "/" + payload.Name] = payload.Value; } } catch (Exception ex) { _logger.LogError(ex, "Error processing counter for {ProviderName}:{EventName}", traceEvent.ProviderName, traceEvent.EventName); } }; // Logging string lastFormattedMessage = ""; var logActivities = new Dictionary <Guid, LogActivityItem>(); var stack = new Stack <Guid>(); source.Dynamic.AddCallbackForProviderEvent(MicrosoftExtensionsLoggingProviderName, "ActivityJsonStart/Start", (traceEvent) => { var factoryId = (int)traceEvent.PayloadByName("FactoryID"); var categoryName = (string)traceEvent.PayloadByName("LoggerName"); var argsJson = (string)traceEvent.PayloadByName("ArgumentsJson"); // TODO: Store this information by logger factory id var item = new LogActivityItem { ActivityID = traceEvent.ActivityID, ScopedObject = new LogObject(JsonDocument.Parse(argsJson).RootElement), }; if (stack.TryPeek(out var parentId) && logActivities.TryGetValue(parentId, out var parentItem)) { item.Parent = parentItem; } stack.Push(traceEvent.ActivityID); logActivities[traceEvent.ActivityID] = item; }); source.Dynamic.AddCallbackForProviderEvent(MicrosoftExtensionsLoggingProviderName, "ActivityJsonStop/Stop", (traceEvent) => { var factoryId = (int)traceEvent.PayloadByName("FactoryID"); var categoryName = (string)traceEvent.PayloadByName("LoggerName"); stack.Pop(); logActivities.Remove(traceEvent.ActivityID); }); source.Dynamic.AddCallbackForProviderEvent(MicrosoftExtensionsLoggingProviderName, "MessageJson", (traceEvent) => { // Level, FactoryID, LoggerName, EventID, EventName, ExceptionJson, ArgumentsJson var logLevel = (LogLevel)traceEvent.PayloadByName("Level"); var factoryId = (int)traceEvent.PayloadByName("FactoryID"); var categoryName = (string)traceEvent.PayloadByName("LoggerName"); var eventId = (int)traceEvent.PayloadByName("EventId"); var eventName = (string)traceEvent.PayloadByName("EventName"); var exceptionJson = (string)traceEvent.PayloadByName("ExceptionJson"); var argsJson = (string)traceEvent.PayloadByName("ArgumentsJson"); // There's a bug that causes some of the columns to get mixed up if (eventName.StartsWith("{")) { argsJson = exceptionJson; exceptionJson = eventName; eventName = null; } if (string.IsNullOrEmpty(argsJson)) { return; } Exception exception = null; var logger = loggerFactory.CreateLogger(categoryName); var scopes = new List <IDisposable>(); if (logActivities.TryGetValue(traceEvent.ActivityID, out var logActivityItem)) { // REVIEW: Does order matter here? We're combining everything anyways. while (logActivityItem != null) { scopes.Add(logger.BeginScope(logActivityItem.ScopedObject)); logActivityItem = logActivityItem.Parent; } } try { if (exceptionJson != "{}") { var exceptionMessage = JsonSerializer.Deserialize <JsonElement>(exceptionJson); exception = new LoggerException(exceptionMessage); } var message = JsonSerializer.Deserialize <JsonElement>(argsJson); if (message.TryGetProperty("{OriginalFormat}", out var formatElement)) { var formatString = formatElement.GetString(); var formatter = new LogValuesFormatter(formatString); object[] args = new object[formatter.ValueNames.Count]; for (int i = 0; i < args.Length; i++) { args[i] = message.GetProperty(formatter.ValueNames[i]).GetString(); } logger.Log(logLevel, new EventId(eventId, eventName), exception, formatString, args); } else { var obj = new LogObject(message, lastFormattedMessage); logger.Log(logLevel, new EventId(eventId, eventName), obj, exception, LogObject.Callback); } } catch (Exception ex) { _logger.LogDebug(ex, "Error processing log entry for {ServiceName}", replicaName); } finally { scopes.ForEach(d => d.Dispose()); } }); source.Dynamic.AddCallbackForProviderEvent(MicrosoftExtensionsLoggingProviderName, "FormattedMessage", (traceEvent) => { // Level, FactoryID, LoggerName, EventID, EventName, FormattedMessage var logLevel = (LogLevel)traceEvent.PayloadByName("Level"); var factoryId = (int)traceEvent.PayloadByName("FactoryID"); var categoryName = (string)traceEvent.PayloadByName("LoggerName"); var eventId = (int)traceEvent.PayloadByName("EventId"); var eventName = (string)traceEvent.PayloadByName("EventName"); var formattedMessage = (string)traceEvent.PayloadByName("FormattedMessage"); if (string.IsNullOrEmpty(formattedMessage)) { formattedMessage = eventName; eventName = ""; } lastFormattedMessage = formattedMessage; }); source.Process(); }
private async Task StartTracing(Action <string> log) { var providers = new List <EventPipeProvider>() { // Runtime Metrics new EventPipeProvider( "System.Runtime", EventLevel.Informational, 0, new Dictionary <string, string>() { { "EventCounterIntervalSec", "1" } } ), // new EventPipeProvider("Microsoft-DotNETCore-SampleProfiler", EventLevel.Informational), new EventPipeProvider("Microsoft-Windows-DotNETRuntime", EventLevel.Informational, 65536 | 32768),//ClrTraceEventParser.Keywords.Default) // Activity correlation new EventPipeProvider("System.Threading.Tasks.TplEventSource", keywords: 511, eventLevel: EventLevel.LogAlways), }; log($"Starting event pipe session for pid {Process.GetCurrentProcess().Id}"); EventPipeSession session = null; var client = new DiagnosticsClient(Process.GetCurrentProcess().Id); try { session = client.StartEventPipeSession(providers); } catch (EndOfStreamException) { } // If the process has already exited, a ServerNotAvailableException will be thrown. catch (ServerNotAvailableException) { } catch (Exception) { // We can't even start the session, wait until the process boots up again to start another metrics thread } void StopSession() { try { session.Stop(); } catch (EndOfStreamException) { // If the app we're monitoring exits abruptly, this may throw in which case we just swallow the exception and exit gracefully. } // We may time out if the process ended before we sent StopTracing command. We can just exit in that case. catch (TimeoutException) { } // On Unix platforms, we may actually get a PNSE since the pipe is gone with the process, and Runtime Client Library // does not know how to distinguish a situation where there is no pipe to begin with, or where the process has exited // before dotnet-counters and got rid of a pipe that once existed. // Since we are catching this in StopMonitor() we know that the pipe once existed (otherwise the exception would've // been thrown in StartMonitor directly) catch (PlatformNotSupportedException) { } // If the process has already exited, a ServerNotAvailableException will be thrown. // This can always race with tye shutting down and a process being restarted on exiting. catch (ServerNotAvailableException) { } } var _ = _cts.Token.Register(() => StopSession()); try { using var traceOutput = File.Create("trace.nettrace"); await session.EventStream.CopyToAsync(traceOutput); } catch (DiagnosticsClientException) { } catch (Exception) { // This fails if stop is called or if the process dies } finally { session?.Dispose(); } }
static async Task <int> Main(string[] args) { if (args.Length == 0 || args.Length > 1 || (args.Length == 1 && _helpFlags.Contains(args[0]))) { PrintUsage(); return(-1); } var pid = int.Parse(args[0]); var tempNetTraceFilename = Path.GetRandomFileName() + ".nettrace"; var tempEtlxFilename = ""; try { var client = new DiagnosticsClient(pid); var providers = new List <EventPipeProvider>() { new EventPipeProvider("Microsoft-DotNETCore-SampleProfiler", EventLevel.Informational) }; using (EventPipeSession session = client.StartEventPipeSession(providers)) using (FileStream fs = File.OpenWrite(tempNetTraceFilename)) { Task copyTask = session.EventStream.CopyToAsync(fs); await Task.Delay(10); session.Stop(); await copyTask; } tempEtlxFilename = TraceLog.CreateFromEventPipeDataFile(tempNetTraceFilename); using (var symbolReader = new SymbolReader(System.IO.TextWriter.Null) { SymbolPath = SymbolPath.MicrosoftSymbolServerPath }) using (var eventLog = new TraceLog(tempEtlxFilename)) { var stackSource = new MutableTraceEventStackSource(eventLog) { OnlyManagedCodeStacks = true }; var computer = new SampleProfilerThreadTimeComputer(eventLog, symbolReader); computer.GenerateThreadTimeStacks(stackSource); var samplesForThread = new Dictionary <string, List <StackSourceSample> >(); stackSource.ForEach((sample) => { var stackIndex = sample.StackIndex; while (!stackSource.GetFrameName(stackSource.GetFrameIndex(stackIndex), false).StartsWith("Thread (")) { stackIndex = stackSource.GetCallerIndex(stackIndex); } var threadName = stackSource.GetFrameName(stackSource.GetFrameIndex(stackIndex), false); if (samplesForThread.TryGetValue(threadName, out var samples)) { samples.Add(sample); } else { samplesForThread[threadName] = new List <StackSourceSample>() { sample }; } }); foreach (var(threadName, samples) in samplesForThread) { #if DEBUG Console.WriteLine($"Found {samples.Count} stacks for thread {threadName}"); #endif PrintStack(threadName, samples[0], stackSource); } } return(0); } catch (System.Exception e) { Console.WriteLine(e); return(-1); } finally { if (File.Exists(tempNetTraceFilename)) { File.Delete(tempNetTraceFilename); } if (File.Exists(tempEtlxFilename)) { File.Delete(tempEtlxFilename); } } }
/// <summary> /// Collects a diagnostic trace from a currently running process. /// </summary> /// <param name="ct">The cancellation token</param> /// <param name="console"></param> /// <param name="processId">The process to collect the trace from.</param> /// <param name="name">The name of process to collect the trace from.</param> /// <param name="output">The output path for the collected trace data.</param> /// <param name="buffersize">Sets the size of the in-memory circular buffer in megabytes.</param> /// <param name="providers">A list of EventPipe providers to be enabled. This is in the form 'Provider[,Provider]', where Provider is in the form: 'KnownProviderName[:Flags[:Level][:KeyValueArgs]]', and KeyValueArgs is in the form: '[key1=value1][;key2=value2]'</param> /// <param name="profile">A named pre-defined set of provider configurations that allows common tracing scenarios to be specified succinctly.</param> /// <param name="format">The desired format of the created trace file.</param> /// <param name="duration">The duration of trace to be taken. </param> /// <param name="clrevents">A list of CLR events to be emitted.</param> /// <param name="clreventlevel">The verbosity level of CLR events</param> /// <returns></returns> private static async Task <int> Collect(CancellationToken ct, IConsole console, int processId, FileInfo output, uint buffersize, string providers, string profile, TraceFileFormat format, TimeSpan duration, string clrevents, string clreventlevel, string name) { try { Debug.Assert(output != null); Debug.Assert(profile != null); // Either processName or processId has to be specified. if (name != null) { if (processId != 0) { Console.WriteLine("Can only specify either --name or --process-id option."); return(ErrorCodes.ArgumentError); } processId = CommandUtils.FindProcessIdWithName(name); if (processId < 0) { return(ErrorCodes.ArgumentError); } } if (processId < 0) { Console.Error.WriteLine("Process ID should not be negative."); return(ErrorCodes.ArgumentError); } else if (processId == 0) { Console.Error.WriteLine("--process-id is required"); return(ErrorCodes.ArgumentError); } if (profile.Length == 0 && providers.Length == 0 && clrevents.Length == 0) { Console.Out.WriteLine("No profile or providers specified, defaulting to trace profile 'cpu-sampling'"); profile = "cpu-sampling"; } Dictionary <string, string> enabledBy = new Dictionary <string, string>(); var providerCollection = Extensions.ToProviders(providers); foreach (EventPipeProvider providerCollectionProvider in providerCollection) { enabledBy[providerCollectionProvider.Name] = "--providers "; } if (profile.Length != 0) { var selectedProfile = ListProfilesCommandHandler.DotNETRuntimeProfiles .FirstOrDefault(p => p.Name.Equals(profile, StringComparison.OrdinalIgnoreCase)); if (selectedProfile == null) { Console.Error.WriteLine($"Invalid profile name: {profile}"); return(ErrorCodes.ArgumentError); } Profile.MergeProfileAndProviders(selectedProfile, providerCollection, enabledBy); } // Parse --clrevents parameter if (clrevents.Length != 0) { // Ignore --clrevents if CLR event provider was already specified via --profile or --providers command. if (enabledBy.ContainsKey(Extensions.CLREventProviderName)) { Console.WriteLine($"The argument --clrevents {clrevents} will be ignored because the CLR provider was configured via either --profile or --providers command."); } else { var clrProvider = Extensions.ToCLREventPipeProvider(clrevents, clreventlevel); providerCollection.Add(clrProvider); enabledBy[Extensions.CLREventProviderName] = "--clrevents"; } } if (providerCollection.Count <= 0) { Console.Error.WriteLine("No providers were specified to start a trace."); return(ErrorCodes.ArgumentError); } PrintProviders(providerCollection, enabledBy); var process = Process.GetProcessById(processId); var shouldExit = new ManualResetEvent(false); var shouldStopAfterDuration = duration != default(TimeSpan); var rundownRequested = false; System.Timers.Timer durationTimer = null; ct.Register(() => shouldExit.Set()); var diagnosticsClient = new DiagnosticsClient(processId); using (VirtualTerminalMode vTermMode = VirtualTerminalMode.TryEnable()) { EventPipeSession session = null; try { session = diagnosticsClient.StartEventPipeSession(providerCollection, true, (int)buffersize); } catch (DiagnosticsClientException e) { Console.Error.WriteLine($"Unable to start a tracing session: {e.ToString()}"); } if (session == null) { Console.Error.WriteLine("Unable to create session."); return(ErrorCodes.SessionCreationError); } if (shouldStopAfterDuration) { durationTimer = new System.Timers.Timer(duration.TotalMilliseconds); durationTimer.Elapsed += (s, e) => shouldExit.Set(); durationTimer.AutoReset = false; } var stopwatch = new Stopwatch(); durationTimer?.Start(); stopwatch.Start(); LineRewriter rewriter = null; using (var fs = new FileStream(output.FullName, FileMode.Create, FileAccess.Write)) { Console.Out.WriteLine($"Process : {process.MainModule.FileName}"); Console.Out.WriteLine($"Output File : {fs.Name}"); if (shouldStopAfterDuration) { Console.Out.WriteLine($"Trace Duration : {duration.ToString(@"dd\:hh\:mm\:ss")}"); } Console.Out.WriteLine("\n\n"); var fileInfo = new FileInfo(output.FullName); Task copyTask = session.EventStream.CopyToAsync(fs); if (!Console.IsOutputRedirected) { rewriter = new LineRewriter { LineToClear = Console.CursorTop - 1 }; Console.CursorVisible = false; } Action printStatus = () => { if (!Console.IsOutputRedirected) { rewriter?.RewriteConsoleLine(); } fileInfo.Refresh(); Console.Out.WriteLine($"[{stopwatch.Elapsed.ToString(@"dd\:hh\:mm\:ss")}]\tRecording trace {GetSize(fileInfo.Length)}"); Console.Out.WriteLine("Press <Enter> or <Ctrl+C> to exit..."); if (rundownRequested) { Console.Out.WriteLine("Stopping the trace. This may take up to minutes depending on the application being traced."); } }; while (!shouldExit.WaitOne(100) && !(!Console.IsInputRedirected && Console.KeyAvailable && Console.ReadKey(true).Key == ConsoleKey.Enter)) { printStatus(); } // Behavior concerning Enter moving text in the terminal buffer when at the bottom of the buffer // is different between Console/Terminals on Windows and Mac/Linux if (!RuntimeInformation.IsOSPlatform(OSPlatform.Windows) && !Console.IsOutputRedirected && rewriter != null && Math.Abs(Console.CursorTop - Console.BufferHeight) == 1) { rewriter.LineToClear--; } durationTimer?.Stop(); rundownRequested = true; session.Stop(); do { printStatus(); } while (!copyTask.Wait(100)); } Console.Out.WriteLine("\nTrace completed."); if (format != TraceFileFormat.NetTrace) { TraceFileFormatConverter.ConvertToFormat(format, output.FullName); } } } catch (Exception ex) { Console.Error.WriteLine($"[ERROR] {ex.ToString()}"); return(ErrorCodes.TracingError); } finally { if (console.GetTerminal() != null) { Console.CursorVisible = true; } } return(await Task.FromResult(0)); }
private int Validate() { // FIXME: This is a bandaid fix for a deadlock in EventPipeEventSource caused by // the lazy caching in the Regex library. The caching creates a ConcurrentDictionary // and because it is the first one in the process, it creates an EventSource which // results in a deadlock over a lock in EventPipe. These lines should be removed once the // underlying issue is fixed by forcing these events to try to be written _before_ we shutdown. // // see: https://github.com/dotnet/runtime/pull/1794 for details on the issue // var emptyConcurrentDictionary = new ConcurrentDictionary <string, string>(); emptyConcurrentDictionary["foo"] = "bar"; var __count = emptyConcurrentDictionary.Count; var isClean = IpcTraceTest.EnsureCleanEnvironment(); if (!isClean) { return(-1); } // CollectTracing returns before EventPipe::Enable has returned, so the // the sources we want to listen for may not have been enabled yet. // We'll use this sentinel EventSource to check if Enable has finished ManualResetEvent sentinelEventReceived = new ManualResetEvent(false); var sentinelTask = new Task(() => { Logger.logger.Log("Started sending sentinel events..."); while (!sentinelEventReceived.WaitOne(50)) { SentinelEventSource.Log.SentinelEvent(); } Logger.logger.Log("Stopped sending sentinel events"); }); sentinelTask.Start(); int processId = Process.GetCurrentProcess().Id; object threadSync = new object(); // for locking eventpipeSession access Func <int> optionalTraceValidationCallback = null; DiagnosticsClient client = new DiagnosticsClient(processId); #if DIAGNOSTICS_RUNTIME if (OperatingSystem.IsAndroid()) { client = new DiagnosticsClient(new IpcEndpointConfig("127.0.0.1:9000", IpcEndpointConfig.TransportType.TcpSocket, IpcEndpointConfig.PortType.Listen)); } #endif var readerTask = new Task(() => { Logger.logger.Log("Connecting to EventPipe..."); try { _eventPipeSession = client.StartEventPipeSession(_testProviders.Concat(_sentinelProviders)); } catch (DiagnosticsClientException ex) { Logger.logger.Log("Failed to connect to EventPipe!"); Logger.logger.Log(ex.ToString()); throw new ApplicationException("Failed to connect to EventPipe"); } using (var eventPipeStream = new StreamProxy(_eventPipeSession.EventStream)) { Logger.logger.Log("Creating EventPipeEventSource..."); using (EventPipeEventSource source = new EventPipeEventSource(eventPipeStream)) { Logger.logger.Log("EventPipeEventSource created"); source.Dynamic.All += (eventData) => { try { if (eventData.ProviderName == "SentinelEventSource") { if (!sentinelEventReceived.WaitOne(0)) { Logger.logger.Log("Saw sentinel event"); } sentinelEventReceived.Set(); } else if (_actualEventCounts.TryGetValue(eventData.ProviderName, out _)) { _actualEventCounts[eventData.ProviderName]++; } else { Logger.logger.Log($"Saw new provider '{eventData.ProviderName}'"); _actualEventCounts[eventData.ProviderName] = 1; } } catch (Exception e) { Logger.logger.Log("Exception in Dynamic.All callback " + e.ToString()); } }; Logger.logger.Log("Dynamic.All callback registered"); if (_optionalTraceValidator != null) { Logger.logger.Log("Running optional trace validator"); optionalTraceValidationCallback = _optionalTraceValidator(source); Logger.logger.Log("Finished running optional trace validator"); } Logger.logger.Log("Starting stream processing..."); try { source.Process(); } catch (Exception) { Logger.logger.Log($"Exception thrown while reading; dumping culprit stream to disk..."); eventPipeStream.DumpStreamToDisk(); // rethrow it to fail the test throw; } Logger.logger.Log("Stopping stream processing"); Logger.logger.Log($"Dropped {source.EventsLost} events"); } } }); var waitSentinelEventTask = new Task(() => { sentinelEventReceived.WaitOne(); }); readerTask.Start(); waitSentinelEventTask.Start(); // Will throw if the reader task throws any exceptions before signaling sentinelEventReceived. Task.WaitAny(readerTask, waitSentinelEventTask); Logger.logger.Log("Starting event generating action..."); _eventGeneratingAction(); Logger.logger.Log("Stopping event generating action"); var stopTask = Task.Run(() => { Logger.logger.Log("Sending StopTracing command..."); lock (threadSync) // eventpipeSession { _eventPipeSession.Stop(); } Logger.logger.Log("Finished StopTracing command"); }); // Should throw if the reader task throws any exceptions Task.WaitAll(readerTask, stopTask); Logger.logger.Log("Reader task finished"); foreach (var(provider, expectedCount) in _expectedEventCounts) { if (_actualEventCounts.TryGetValue(provider, out var actualCount)) { if (!expectedCount.Validate(actualCount)) { return(Fail($"Event count mismatch for provider \"{provider}\": expected {expectedCount}, but saw {actualCount}")); } } else { return(Fail($"No events for provider \"{provider}\"")); } } if (optionalTraceValidationCallback != null) { Logger.logger.Log("Validating optional callback..."); // reader thread should be dead now, no need to lock return(optionalTraceValidationCallback()); } else { return(100); } }