Add support for --delay and --duration (#12)

doc/readme.md

@@ -145,6 +145,8 @@ Usage: ultra profile [Options] <pid | -- execName arg0 arg1...>
                                       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

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<string> 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<System.Diagnostics.Process> processList = new List<System.Diagnostics.Process>();
         if (ultraProfilerOptions.ProcessIds.Count > 0)
         {
@@ -136,8 +155,8 @@ public async Task<string> 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<string> 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<Process> 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<string> 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<Process> 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<string> 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<string> Convert(string etlFile, List<int> pIds, EtwUltraProfilerOptions ultraProfilerOptions)

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<int> 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<string>? LogProgress;

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<int> 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 =>