From 66f7ca0f8ecffd81a628a1d3cd1e6833993a5ef7 Mon Sep 17 00:00:00 2001 From: Mitchell Hwang <16830051+mdh1418@users.noreply.github.com> Date: Thu, 2 Nov 2023 19:07:01 -0400 Subject: [PATCH] [tools][trace] Add stopping event options to dotnet-trace (#4363) Fixes https://github.com/dotnet/diagnostics/issues/3125 This PR provides users another method to stop a dotnet-trace via a stopping event similar to that of dotnet-monitor, originally implemented in https://github.com/dotnet/dotnet-monitor/pull/2557. Three arguments are added to the `dotnet-trace collect` command to specify a stopping event: | Argument | Description | |----------|----------| |`--stopping-event-provider-name` | A string, parsed as-is, that will stop the trace upon hitting an event with the matching provider name. For a more specific stopping event, additionally provide `--stopping-event-event-name` and/or `--stopping-event-payload-filter`. | | `--stopping-event-event-name` | A string, parsed as-is, that will stop the trace upon hitting an event with the matching event name. Requires `--stopping-event-provider-name` to be set. For a more specific stopping event, additionally provide `--stopping-event-payload-filter`. | | `--stopping-event-payload-filter` | A string, parsed as [payload_field_name]:[payload_field_value] pairs separated by commas, that will stop the trace upon hitting an event with a matching payload. Requires `--stopping-event-provider-name` and `--stopping-event-event-name` to be set. | Note: Though technically `--stopping-event-payload-filter` can be set without needing a `--stopping-event-event-name`, this may lead to mismatched payloads should another `TraceEvent` under the same provider not have that particular payload field name. Until there is a good reason to stop a trace given a payload filter regardless of the event name, we require `--stopping-event-event-name` to be set whenever `--stopping-event-payload-filter` is provided. To stop a trace at a particular event, dotnet-monitor's [approach](https://github.com/dotnet/dotnet-monitor/blob/0820b6911f3ac47b6b5ec867ac906699e5c15787/src/Tools/dotnet-monitor/Trace/TraceUntilEventOperation.cs#L47) using an [EventMonitor](https://github.com/dotnet/diagnostics/blob/main/src/Microsoft.Diagnostics.Monitoring.EventPipe/EventMonitor.cs) is adopted. Upon hitting a TraceEvent with a matching ProviderName, EventName (if specified), and PayloadFilter (if specified), we trigger dotnet-trace's fallback logic to stop the EventPipeSession before the EventStream ends. Note: As the EventStream is being parsed asynchronously, there will be some events that pass through between the time a trace event matching the specified stopping event arguments is parsed and the EventPipeSession is stopped. In addition, this PR modifies `EventMonitor` to use the `ClrTraceEventParser` to parse `TraceEvent` objects under the `Microsoft-Windows-DotNETRuntime` provider, and the `DynamicTraceEventParser` otherwise. The `ClrTraceEventParser` is generated to understand the ETW event manifest for `Microsoft-Windows-DotNETRuntime` events. The previous implementation defaulting to `DynamicTraceEventParser` would not work on non-Windows platforms such as OSX which could not parse the payload to populate `PayloadNames` and `PayloadValue(i)` because there was no manifest available. On the other hand, Windows is able to locate manifest data for known events through the OS. ------------------- ## Testing With an Android App ``` C# private static void PrintA() { Console.WriteLine("A"); Thread.Sleep(1000); } ... private static void PrintK() { Console.WriteLine("K"); Thread.Sleep(1000); } public static void Main(string[] args) { Console.WriteLine("Hello, Android!"); // logcat PrintA(); PrintB(); PrintC(); PrintD(); PrintE(); PrintF(); PrintG(); PrintH(); PrintI(); PrintJ(); PrintK(); while (true) { Thread.Sleep(100); } } ``` Running dotnet-dsrouter to connect the diagnostic tooling with the android device `./artifacts/bin/dotnet-dsrouter/Debug/net6.0/dotnet-dsrouter android -v debug` Tracing with a stopping event args provided `./artifacts/bin/dotnet-trace/Debug/net6.0/dotnet-trace collect -p 16683 --providers Microsoft-Windows-DotNETRuntime:0x1F000080018:5 --stopping-event-provider-name Microsoft-Windows-DotNETRuntime --stopping-event-event-name Method/JittingStarted --stopping-event-payload-filter MethodName:PrintA` [dotnet-dsrouter_20231024_165648.nettrace.zip](https://github.com/dotnet/diagnostics/files/13147788/dotnet-dsrouter_20231024_165648.nettrace.zip) There are no `Method/JittingStarted` events with MethodName `PrintC` through `PrintK` in the `.nettrace`, showing that the trace was indeed stopped after seeing the `PrintA` event. The events after `PrintA` are an artifact of the second note above. Below is the JITStats of the .nettrace opened in perfview, showing that the last method was `PrintB`. JITStatsPrintA --- .../EventMonitor.cs | 14 ++- ...ft.Diagnostics.Monitoring.EventPipe.csproj | 1 + .../CommandLine/Commands/CollectCommand.cs | 102 +++++++++++++++++- src/Tools/dotnet-trace/dotnet-trace.csproj | 1 + 4 files changed, 111 insertions(+), 7 deletions(-) diff --git a/src/Microsoft.Diagnostics.Monitoring.EventPipe/EventMonitor.cs b/src/Microsoft.Diagnostics.Monitoring.EventPipe/EventMonitor.cs index 147167f5c6..5e773d2394 100644 --- a/src/Microsoft.Diagnostics.Monitoring.EventPipe/EventMonitor.cs +++ b/src/Microsoft.Diagnostics.Monitoring.EventPipe/EventMonitor.cs @@ -24,6 +24,8 @@ internal sealed class EventMonitor : IAsyncDisposable private readonly bool _leaveEventStreamOpen; private EventPipeEventSource _eventSource; + private TraceEventParser _eventParser; + private readonly string _providerName; private readonly string _eventName; @@ -78,8 +80,16 @@ public Task ProcessAsync(CancellationToken token) token.ThrowIfCancellationRequested(); using IDisposable registration = token.Register(() => _eventSource.Dispose()); - _eventSource.Dynamic.AddCallbackForProviderEvent(_providerName, _eventName, TraceEventCallback); + if (string.Equals(_providerName, "Microsoft-Windows-DotNETRuntime", StringComparison.Ordinal)) + { + _eventParser = _eventSource.Clr; + } + else + { + _eventParser = _eventSource.Dynamic; + } + _eventParser.AddCallbackForProviderEvent(_providerName, _eventName, TraceEventCallback); _eventSource.Process(); token.ThrowIfCancellationRequested(); }, token); @@ -91,7 +101,7 @@ public Task ProcessAsync(CancellationToken token) /// private void StopMonitoringForEvent() { - _eventSource?.Dynamic.RemoveCallback(TraceEventCallback); + _eventParser?.RemoveCallback(TraceEventCallback); } private void TraceEventCallback(TraceEvent obj) diff --git a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Microsoft.Diagnostics.Monitoring.EventPipe.csproj b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Microsoft.Diagnostics.Monitoring.EventPipe.csproj index c104003875..4558b2ed0c 100644 --- a/src/Microsoft.Diagnostics.Monitoring.EventPipe/Microsoft.Diagnostics.Monitoring.EventPipe.csproj +++ b/src/Microsoft.Diagnostics.Monitoring.EventPipe/Microsoft.Diagnostics.Monitoring.EventPipe.csproj @@ -40,6 +40,7 @@ + diff --git a/src/Tools/dotnet-trace/CommandLine/Commands/CollectCommand.cs b/src/Tools/dotnet-trace/CommandLine/Commands/CollectCommand.cs index 15eab9c799..720373be6d 100644 --- a/src/Tools/dotnet-trace/CommandLine/Commands/CollectCommand.cs +++ b/src/Tools/dotnet-trace/CommandLine/Commands/CollectCommand.cs @@ -12,6 +12,7 @@ using System.Runtime.InteropServices; using System.Threading; using System.Threading.Tasks; +using Microsoft.Diagnostics.Monitoring.EventPipe; using Microsoft.Diagnostics.NETCore.Client; using Microsoft.Internal.Common.Utils; using Microsoft.Tools.Common; @@ -31,7 +32,7 @@ private static void ConsoleWriteLine(string str) } } - private delegate Task CollectDelegate(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 port, bool showchildio, bool resumeRuntime); + private delegate Task CollectDelegate(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 port, bool showchildio, bool resumeRuntime, string stoppingEventProviderName, string stoppingEventEventName, string stoppingEventPayloadFilter); /// /// Collects a diagnostic trace from a currently running process or launch a child process and trace it. @@ -52,8 +53,11 @@ private static void ConsoleWriteLine(string str) /// Path to the diagnostic port to be used. /// Should IO from a child process be hidden. /// Resume runtime once session has been initialized. + /// A string, parsed as-is, that will stop the trace upon hitting an event with the matching provider name. For a more specific stopping event, additionally provide `--stopping-event-event-name` and/or `--stopping-event-payload-filter`. + /// A string, parsed as-is, that will stop the trace upon hitting an event with the matching event name. Requires `--stopping-event-provider-name` to be set. For a more specific stopping event, additionally provide `--stopping-event-payload-filter`. + /// A string, parsed as [payload_field_name]:[payload_field_value] pairs separated by commas, that will stop the trace upon hitting an event with a matching payload. Requires `--stopping-event-provider-name` and `--stopping-event-event-name` to be set. /// - private static async Task 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, bool resumeRuntime) + private static async Task 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, bool resumeRuntime, string stoppingEventProviderName, string stoppingEventEventName, string stoppingEventPayloadFilter) { bool collectionStopped = false; bool cancelOnEnter = true; @@ -159,6 +163,39 @@ private static async Task Collect(CancellationToken ct, IConsole console, i PrintProviders(providerCollection, enabledBy); + // Validate and parse stoppingEvent parameters: stoppingEventProviderName, stoppingEventEventName, stoppingEventPayloadFilter + + bool hasStoppingEventProviderName = !string.IsNullOrEmpty(stoppingEventProviderName); + bool hasStoppingEventEventName = !string.IsNullOrEmpty(stoppingEventEventName); + bool hasStoppingEventPayloadFilter = !string.IsNullOrEmpty(stoppingEventPayloadFilter); + if (!hasStoppingEventProviderName && (hasStoppingEventEventName || hasStoppingEventPayloadFilter)) + { + Console.Error.WriteLine($"`{nameof(stoppingEventProviderName)}` is required to stop tracing after a specific event for a particular `{nameof(stoppingEventEventName)}` event name or `{nameof(stoppingEventPayloadFilter)}` payload filter."); + return (int)ReturnCode.ArgumentError; + } + if (!hasStoppingEventEventName && hasStoppingEventPayloadFilter) + { + Console.Error.WriteLine($"`{nameof(stoppingEventEventName)}` is required to stop tracing after a specific event for a particular `{nameof(stoppingEventPayloadFilter)}` payload filter."); + return (int)ReturnCode.ArgumentError; + } + + Dictionary payloadFilter = new(); + if (hasStoppingEventPayloadFilter) + { + string[] payloadFieldNameValuePairs = stoppingEventPayloadFilter.Split(','); + foreach (string pair in payloadFieldNameValuePairs) + { + string[] payloadFieldNameValuePair = pair.Split(':'); + if (payloadFieldNameValuePair.Length != 2) + { + Console.Error.WriteLine($"`{nameof(stoppingEventPayloadFilter)}` does not have valid format. Ensure that it has `payload_field_name:payload_field_value` pairs separated by commas."); + return (int)ReturnCode.ArgumentError; + } + + payloadFilter[payloadFieldNameValuePair[0]] = payloadFieldNameValuePair[1]; + } + } + DiagnosticsClient diagnosticsClient; Process process = null; DiagnosticsClientBuilder builder = new("dotnet-trace", 10); @@ -220,7 +257,6 @@ private static async Task Collect(CancellationToken ct, IConsole console, i bool rundownRequested = false; System.Timers.Timer durationTimer = null; - using (VirtualTerminalMode vTermMode = printStatusOverTime ? VirtualTerminalMode.TryEnable() : null) { EventPipeSession session = null; @@ -281,7 +317,31 @@ private static async Task Collect(CancellationToken ct, IConsole console, i ConsoleWriteLine("\n\n"); FileInfo fileInfo = new(output.FullName); - Task copyTask = session.EventStream.CopyToAsync(fs); + EventMonitor eventMonitor = null; + Task copyTask = null; + if (hasStoppingEventProviderName) + { + eventMonitor = new( + stoppingEventProviderName, + stoppingEventEventName, + payloadFilter, + onEvent: (traceEvent) => + { + shouldExit.Set(); + }, + onPayloadFilterMismatch: (traceEvent) => + { + ConsoleWriteLine($"One or more field names specified in the payload filter for event '{traceEvent.ProviderName}/{traceEvent.EventName}' do not match any of the known field names: '{string.Join(' ', traceEvent.PayloadNames)}'. As a result the requested stopping event is unreachable; will continue to collect the trace for the remaining specified duration."); + }, + eventStream: new PassthroughStream(session.EventStream, fs, (int)buffersize, leaveDestinationStreamOpen: true), + callOnEventOnlyOnce: true); + + copyTask = eventMonitor.ProcessAsync(CancellationToken.None); + } + else + { + copyTask = session.EventStream.CopyToAsync(fs); + } Task shouldExitTask = copyTask.ContinueWith( (task) => shouldExit.Set(), CancellationToken.None, @@ -339,6 +399,11 @@ private static async Task Collect(CancellationToken ct, IConsole console, i { printStatus(); } while (!copyTask.Wait(100)); + + if (eventMonitor != null) + { + await eventMonitor.DisposeAsync().ConfigureAwait(false); + } } // 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 @@ -455,7 +520,10 @@ public static Command CollectCommand() => CommonOptions.NameOption(), DiagnosticPortOption(), ShowChildIOOption(), - ResumeRuntimeOption() + ResumeRuntimeOption(), + StoppingEventProviderNameOption(), + StoppingEventEventNameOption(), + StoppingEventPayloadFilterOption() }; private static uint DefaultCircularBufferSizeInMB() => 256; @@ -546,5 +614,29 @@ private static Option ResumeRuntimeOption() => { Argument = new Argument(name: "resumeRuntime", getDefaultValue: () => true) }; + + private static Option StoppingEventProviderNameOption() => + new( + alias: "--stopping-event-provider-name", + description: @"A string, parsed as-is, that will stop the trace upon hitting an event with the matching provider name. For a more specific stopping event, additionally provide `--stopping-event-event-name` and/or `--stopping-event-payload-filter`.") + { + Argument = new Argument(name: "stoppingEventProviderName", getDefaultValue: () => null) + }; + + private static Option StoppingEventEventNameOption() => + new( + alias: "--stopping-event-event-name", + description: @"A string, parsed as-is, that will stop the trace upon hitting an event with the matching event name. Requires `--stopping-event-provider-name` to be set. For a more specific stopping event, additionally provide `--stopping-event-payload-filter`.") + { + Argument = new Argument(name: "stoppingEventEventName", getDefaultValue: () => null) + }; + + private static Option StoppingEventPayloadFilterOption() => + new( + alias: "--stopping-event-payload-filter", + description: @"A string, parsed as [payload_field_name]:[payload_field_value] pairs separated by commas, that will stop the trace upon hitting an event with a matching payload. Requires `--stopping-event-provider-name` and `--stopping-event-event-name` to be set.") + { + Argument = new Argument(name: "stoppingEventPayloadFilter", getDefaultValue: () => null) + }; } } diff --git a/src/Tools/dotnet-trace/dotnet-trace.csproj b/src/Tools/dotnet-trace/dotnet-trace.csproj index 1beb21c32d..a4ed81dde4 100644 --- a/src/Tools/dotnet-trace/dotnet-trace.csproj +++ b/src/Tools/dotnet-trace/dotnet-trace.csproj @@ -17,6 +17,7 @@ +