From 2868266714f3b52bb568ba2afc8864312c9aa38a Mon Sep 17 00:00:00 2001 From: Alexandre Mutel Date: Wed, 27 Nov 2024 21:35:56 +0100 Subject: [PATCH] Add support for --delay and --duration (#12) --- doc/readme.md | 2 + src/Ultra.Core/EtwUltraProfiler.cs | 119 +++++++++++++++++----- src/Ultra.Core/EtwUltraProfilerOptions.cs | 6 ++ src/Ultra/Program.cs | 10 +- 4 files changed, 108 insertions(+), 29 deletions(-) diff --git a/doc/readme.md b/doc/readme.md index fdb8a65..de16dc3 100644 --- a/doc/readme.md +++ b/doc/readme.md @@ -145,6 +145,8 @@ Usage: ultra profile [Options] Users\alexa\AppData\Local\Temp\SymbolCache*https://symbols.nuget.org/download/ symbols`. --paused Launch the profiler paused and wait for SPACE or ENTER keys to be pressed. + --delay=VALUE Starts profiling after a specific delay (seconds). Default is 0s. + --duration=VALUE Run the profiler for a maximum duration (seconds). Default is 120s --keep-merged-etl-file Keep the merged ETL file. --keep-intermediate-etl-files Keep the intermediate ETL files before merging. --mode=VALUE Defines how the stdout/stderr of a program explicitly started by ultra should be diff --git a/src/Ultra.Core/EtwUltraProfiler.cs b/src/Ultra.Core/EtwUltraProfiler.cs index 1b89e36..bfaa004 100644 --- a/src/Ultra.Core/EtwUltraProfiler.cs +++ b/src/Ultra.Core/EtwUltraProfiler.cs @@ -20,6 +20,15 @@ public class EtwUltraProfiler : IDisposable private bool _cancelRequested; private ManualResetEvent? _cleanCancel; private bool _stopRequested; + private readonly Stopwatch _profilerClock; + private TimeSpan _lastTimeProgress; + + + public EtwUltraProfiler() + { + _profilerClock = new Stopwatch(); + } + public bool Cancel() { @@ -61,7 +70,17 @@ public async Task Run(EtwUltraProfilerOptions ultraProfilerOptions) { throw new ArgumentException("ShouldStartProfiling is required when Paused is set to true"); } - + + if (ultraProfilerOptions.DurationInSeconds < 0) + { + throw new ArgumentException("DurationInSeconds must be greater or equal to 0"); + } + + if (ultraProfilerOptions.DelayInSeconds < 0) + { + throw new ArgumentException("DelayInSeconds must be greater or equal to 0"); + } + List processList = new List(); if (ultraProfilerOptions.ProcessIds.Count > 0) { @@ -136,8 +155,8 @@ public async Task Run(EtwUltraProfilerOptions ultraProfilerOptions) var kernelFileName = $"{baseName}.kernel.etl"; var userFileName = $"{baseName}.user.etl"; - var clock = Stopwatch.StartNew(); - var lastTime = clock.Elapsed; + _profilerClock.Restart(); + _lastTimeProgress = _profilerClock.Elapsed; _userSession = new TraceEventSession($"{baseName}-user", userFileName); _kernelSession = new TraceEventSession($"{baseName}-kernel", kernelFileName); @@ -147,24 +166,28 @@ public async Task Run(EtwUltraProfilerOptions ultraProfilerOptions) using (_userSession) using (_kernelSession) { - if (!ultraProfilerOptions.Paused) + var startTheRequestedProgramIfRequired = () => { - EnableProfiling(options, ultraProfilerOptions); - } + // Start a command line process if needed + if (ultraProfilerOptions.ProgramPath is not null) + { + var processState = StartProcess(ultraProfilerOptions); + processList.Add(processState.Process); + // Append the pid for a single process that we are attaching to + if (singleProcess is null) + { + baseName = $"{baseName}_pid_{processState.Process.Id}"; + } - HashSet exitedProcessList = new(); + singleProcess ??= processState.Process; + } + }; - // Start a command line process if needed - if (ultraProfilerOptions.ProgramPath is not null) + // If we have a delay, or we are asked to start paused, we start the process before the profiling starts + bool hasExplicitProgramHasStarted = ultraProfilerOptions.DelayInSeconds != 0.0 || ultraProfilerOptions.Paused; + if (hasExplicitProgramHasStarted) { - var processState = StartProcess(ultraProfilerOptions); - processList.Add(processState.Process); - // Append the pid for a single process that we are attaching to - if (singleProcess is null) - { - baseName = $"{baseName}_pid_{processState.Process.Id}"; - } - singleProcess ??= processState.Process; + startTheRequestedProgramIfRequired(); } // Wait for the process to start @@ -179,28 +202,42 @@ public async Task Run(EtwUltraProfilerOptions ultraProfilerOptions) { throw new InvalidOperationException("CTRL+C requested"); } - - EnableProfiling(options, ultraProfilerOptions); } + await EnableProfiling(options, ultraProfilerOptions); + + // If we haven't started the program yet, we start it now (for explicit program path) + if (!hasExplicitProgramHasStarted) + { + startTheRequestedProgramIfRequired(); + } + foreach (var process in processList) { ultraProfilerOptions.LogProgress?.Invoke($"Start Profiling Process {process.ProcessName} ({process.Id})"); } // Collect the data until all processes have exited or there is a cancel request + HashSet exitedProcessList = new(); while (!_cancelRequested) { - if (clock.Elapsed.TotalMilliseconds - lastTime.TotalMilliseconds > ultraProfilerOptions.UpdateLogAfterInMs) + // Exit if we have reached the duration + if (_profilerClock.Elapsed.TotalSeconds > ultraProfilerOptions.DurationInSeconds) + { + ultraProfilerOptions.LogProgress?.Invoke($"Stopping profiling, max duration reached at {ultraProfilerOptions.DurationInSeconds}s"); + break; + } + + if (_profilerClock.Elapsed.TotalMilliseconds - _lastTimeProgress.TotalMilliseconds > ultraProfilerOptions.UpdateLogAfterInMs) { var userFileNameLength = new FileInfo(userFileName).Length; var kernelFileNameLength = new FileInfo(kernelFileName).Length; var totalFileNameLength = userFileNameLength + kernelFileNameLength; ultraProfilerOptions.LogStepProgress?.Invoke(singleProcess is not null - ? $"Profiling Process {singleProcess.ProcessName} ({singleProcess.Id}) - {(int)clock.Elapsed.TotalSeconds}s - {ByteSize.FromBytes(totalFileNameLength)}" - : $"Profiling {processList.Count} Processes - {(int)clock.Elapsed.TotalSeconds}s - {ByteSize.FromBytes(totalFileNameLength)}"); - lastTime = clock.Elapsed; + ? $"Profiling Process {singleProcess.ProcessName} ({singleProcess.Id}) - {(int)_profilerClock.Elapsed.TotalSeconds}s - {ByteSize.FromBytes(totalFileNameLength)}" + : $"Profiling {processList.Count} Processes - {(int)_profilerClock.Elapsed.TotalSeconds}s - {ByteSize.FromBytes(totalFileNameLength)}"); + _lastTimeProgress = _profilerClock.Elapsed; } await Task.Delay(ultraProfilerOptions.CheckDeltaTimeInMs); @@ -314,8 +351,38 @@ public async Task Run(EtwUltraProfilerOptions ultraProfilerOptions) return jsonFinalFile; } - private void EnableProfiling(TraceEventProviderOptions options, EtwUltraProfilerOptions ultraProfilerOptions) + private async Task EnableProfiling(TraceEventProviderOptions options, EtwUltraProfilerOptions ultraProfilerOptions) { + _profilerClock.Restart(); + while (!_cancelRequested) + { + var deltaInSecondsBeforeProfilingCanStart = ultraProfilerOptions.DelayInSeconds - _profilerClock.Elapsed.TotalSeconds; + + if (deltaInSecondsBeforeProfilingCanStart <= 0) + { + break; + } + + if (_profilerClock.Elapsed.TotalMilliseconds - _lastTimeProgress.TotalMilliseconds > ultraProfilerOptions.UpdateLogAfterInMs) + { + ultraProfilerOptions.LogStepProgress?.Invoke($"Delay before starting the profiler {deltaInSecondsBeforeProfilingCanStart:0.0}s"); + _lastTimeProgress = _profilerClock.Elapsed; + } + + // We don't handle the case of the process being killed during the delay + // As it complicates the check when we start the process right after enabling the profiling + + // The loop checking for the process to be killed will happen after anyway + + await Task.Delay(ultraProfilerOptions.CheckDeltaTimeInMs); + } + + // In case of a cancel request during the delay, we assume that it is a CTRL+C and not a stop of the profiler, as we haven't started profiling yet + if (_cancelRequested) + { + throw new InvalidOperationException("CTRL+C requested"); + } + _kernelSession.StopOnDispose = true; _kernelSession.CircularBufferMB = 0; _kernelSession.CpuSampleIntervalMSec = ultraProfilerOptions.CpuSamplingIntervalInMs; @@ -349,6 +416,10 @@ private void EnableProfiling(TraceEventProviderOptions options, EtwUltraProfiler ClrTraceEventParser.ProviderGuid, TraceEventLevel.Verbose, // For call stacks. (ulong)jitEvents, options); + + + // Reset the clock to account for the duration of the profiler + _profilerClock.Restart(); } public async Task Convert(string etlFile, List pIds, EtwUltraProfilerOptions ultraProfilerOptions) diff --git a/src/Ultra.Core/EtwUltraProfilerOptions.cs b/src/Ultra.Core/EtwUltraProfilerOptions.cs index 65588af..86f43ab 100644 --- a/src/Ultra.Core/EtwUltraProfilerOptions.cs +++ b/src/Ultra.Core/EtwUltraProfilerOptions.cs @@ -16,6 +16,8 @@ public EtwUltraProfilerOptions() CpuSamplingIntervalInMs = 1000.0f / 8190.0f; KeepMergedEtl = false; KeepEtlIntermediateFiles = false; + DelayInSeconds = 0.0; // 0 seconds + DurationInSeconds = 120.0; // 120 seconds } public List ProcessIds { get; } = new(); @@ -32,6 +34,10 @@ public EtwUltraProfilerOptions() public bool Paused { get; set; } + public double DelayInSeconds { get; set; } + + public double DurationInSeconds { get; set; } + public EtwUltraProfilerConsoleMode ConsoleMode { get; set; } public Action? LogProgress; diff --git a/src/Ultra/Program.cs b/src/Ultra/Program.cs index 3349c9c..ca6a51d 100644 --- a/src/Ultra/Program.cs +++ b/src/Ultra/Program.cs @@ -1,13 +1,11 @@ -using System; -using System.Diagnostics.Tracing; +// Copyright (c) Alexandre Mutel. All rights reserved. +// Licensed under the BSD-Clause 2 license. +// See license.txt file in the project root for full license information. using System.Text; using ByteSizeLib; -using Microsoft.Extensions.Options; -using Microsoft.Extensions.Primitives; using Spectre.Console; using Ultra.Core; using XenoAtom.CommandLine; -using static System.Net.Mime.MediaTypeNames; namespace Ultra; @@ -44,6 +42,8 @@ static async Task Main(string[] args) { "sampling-interval=", $"The {{VALUE}} of the sample interval in ms. Default is 8190Hz = {options.CpuSamplingIntervalInMs:0.000}ms.", (float v) => options.CpuSamplingIntervalInMs = v }, { "symbol-path=", $"The {{VALUE}} of symbol path. The default value is `{options.GetCachedSymbolPath()}`.", v => options.SymbolPathText = v }, { "paused", "Launch the profiler paused and wait for SPACE or ENTER keys to be pressed.", v => options.Paused = v is not null }, + { "delay=", $"Starts profiling after a specific delay (seconds). Default is {options.DelayInSeconds}s.", (double delay) => options.DelayInSeconds = delay }, + { "duration=", $"Run the profiler for a maximum duration (seconds). Default is {options.DurationInSeconds}s", (double duration) => options.DurationInSeconds = duration }, { "keep-merged-etl-file", "Keep the merged ETL file.", v => options.KeepMergedEtl = v is not null }, { "keep-intermediate-etl-files", "Keep the intermediate ETL files before merging.", v => options.KeepEtlIntermediateFiles = v is not null }, { "mode=", "Defines how the stdout/stderr of a program explicitly started by ultra should be integrated in its output. Default is `silent` which will not mix program's output. The other options are: `raw` is going to mix ultra and program output together in a raw output. `live` is going to mix ultra and program output within a live table.", v =>