diff --git a/doc/profile_mode_live.png b/doc/profile_mode_live.png new file mode 100644 index 0000000..ed7441e Binary files /dev/null and b/doc/profile_mode_live.png differ diff --git a/doc/readme.md b/doc/readme.md index b2133d7..d45f621 100644 --- a/doc/readme.md +++ b/doc/readme.md @@ -16,6 +16,22 @@ $ ultra.exe profile -- my_command.exe arg0 arg1 arg2... This will create a `ultra_my_command_..._.json.gz` trace file in the current directory. +By default, ultra won't show the stdout/stderr of the program launched. You can change this behavior by specifying the `--mode` option: + +- `silent` (default): won't mix program's output +- `raw`: will mix ultra and program output together in a raw output. Ultra output will be prefixed at the start of a line with `>>ultra::` +- `live`: will mix ultra and program output within a live table + +For example, a profile with `live` mode: + +```console +$ ultra.exe profile --mode live -- my_command.exe arg0 arg1 arg2... +``` + +will display the following live table when running your process: + +![Live ultra mode](profile_mode_live.png) + When attaching an existing process, you can pass directly a PID to ultra.exe: ```console @@ -116,11 +132,24 @@ Usage: ultra profile [Options] -h, -?, --help Show this message and exit --pid=PID The PID of the process to attach the profiler to. - --sampling-interval=VALUE The VALUE of the sample interval in ms. Default is 8190Hz = 0.122ms. - --symbol-path=VALUE The VALUE of symbol path. The default value is `;SRV*C:\Users\xoofx\AppData\Local\Temp\SymbolCache*https://msdl.microsoft.com/download/symbols;SRV*C:\Users\xoofx\AppData\Local\Temp\SymbolCache*https:// - symbols.nuget.org/download/symbols`. + --sampling-interval=VALUE The VALUE of the sample interval in ms. Default + is 8190Hz = 0.122ms. + --symbol-path=VALUE The VALUE of symbol path. The default value is `; + SRV*C:\Users\alexa\AppData\Local\Temp\ + SymbolCache*https://msdl.microsoft.com/download/ + symbols;SRV*C:\Users\alexa\AppData\Local\Temp\ + SymbolCache*https://symbols.nuget.org/download/ + symbols`. --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 + 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. ``` ## Convert @@ -134,6 +163,10 @@ Usage: ultra convert --pid xxx -h, -?, --help Show this message and exit --pid=PID The PID of the process - --symbol-path=VALUE The VALUE of symbol path. The default value is `;SRV*C:\Users\xoofx\AppData\Local\Temp\SymbolCache*https://msdl.microsoft.com/download/symbols;SRV*C:\Users\xoofx\AppData\Local\Temp\SymbolCache*https:// - symbols.nuget.org/download/symbols`. + --symbol-path=VALUE The VALUE of symbol path. The default value is `; + SRV*C:\Users\alexa\AppData\Local\Temp\ + SymbolCache*https://msdl.microsoft.com/download/ + symbols;SRV*C:\Users\alexa\AppData\Local\Temp\ + SymbolCache*https://symbols.nuget.org/download/ + symbols`. ``` diff --git a/src/Ultra.Core/EtwUltraProfiler.cs b/src/Ultra.Core/EtwUltraProfiler.cs index 5b72be1..b5f07f5 100644 --- a/src/Ultra.Core/EtwUltraProfiler.cs +++ b/src/Ultra.Core/EtwUltraProfiler.cs @@ -104,7 +104,7 @@ public async Task Run(EtwUltraProfilerOptions ultraProfilerOptions) // Append the pid for a single process that we are attaching to if (singleProcess is not null) { - baseName = $"{baseName}_{singleProcess.Id}"; + baseName = $"{baseName}_pid_{singleProcess.Id}"; } var options = new TraceEventProviderOptions() @@ -181,23 +181,14 @@ public async Task Run(EtwUltraProfilerOptions ultraProfilerOptions) // Start a command line process if needed if (ultraProfilerOptions.ProgramPath is not null) { - var startInfo = new ProcessStartInfo + var processState = StartProcess(ultraProfilerOptions); + processList.Add(processState.Process); + // Append the pid for a single process that we are attaching to + if (singleProcess is null) { - FileName = ultraProfilerOptions.ProgramPath, - UseShellExecute = true, - CreateNoWindow = true, - WindowStyle = ProcessWindowStyle.Hidden - }; - - foreach (var arg in ultraProfilerOptions.Arguments) - { - startInfo.ArgumentList.Add(arg); + baseName = $"{baseName}_pid_{processState.Process.Id}"; } - - ultraProfilerOptions.LogProgress?.Invoke($"Starting Process {startInfo.FileName} {string.Join(" ", startInfo.ArgumentList)}"); - var process = System.Diagnostics.Process.Start(startInfo)!; - processList.Add(process); - singleProcess ??= process; + singleProcess ??= processState.Process; } foreach (var process in processList) @@ -391,6 +382,97 @@ private async Task WaitForStaleFile(string file, EtwUltraProfilerOptions options } } + + private static ProcessState StartProcess(EtwUltraProfilerOptions ultraProfilerOptions) + { + var mode = ultraProfilerOptions.ConsoleMode; + + var process = new Process(); + + var startInfo = process.StartInfo; + startInfo.FileName = ultraProfilerOptions.ProgramPath; + + foreach (var arg in ultraProfilerOptions.Arguments) + { + startInfo.ArgumentList.Add(arg); + } + + ultraProfilerOptions.LogProgress?.Invoke($"Starting Process {startInfo.FileName} {string.Join(" ", startInfo.ArgumentList)}"); + + if (mode == EtwUltraProfilerConsoleMode.Silent) + { + startInfo.UseShellExecute = true; + startInfo.CreateNoWindow = true; + startInfo.WindowStyle = ProcessWindowStyle.Hidden; + + process.Start(); + } + else + { + startInfo.UseShellExecute = false; + startInfo.CreateNoWindow = true; + startInfo.RedirectStandardOutput = true; + startInfo.RedirectStandardError = true; + startInfo.RedirectStandardInput = true; + + process.OutputDataReceived += (sender, args) => + { + if (args.Data != null) + { + ultraProfilerOptions.ProgramLogStdout?.Invoke(args.Data); + } + }; + + process.ErrorDataReceived += (sender, args) => + { + if (args.Data != null) + { + ultraProfilerOptions.ProgramLogStderr?.Invoke(args.Data); + } + }; + + process.Start(); + + process.BeginOutputReadLine(); + process.BeginErrorReadLine(); + } + + var state = new ProcessState(process); + + // Make sure to call WaitForExit + var thread = new Thread(() => + { + try + { + process.WaitForExit(); + state.HasExited = true; + } + catch + { + // ignore + } + }) + { + Name = "Ultra-ProcessWaitForExit", + IsBackground = true + }; + thread.Start(); + + return state; + } + + private class ProcessState + { + public ProcessState(Process process) + { + Process = process; + } + + public readonly Process Process; + + public bool HasExited; + } + public void Dispose() { _userSession?.Dispose(); diff --git a/src/Ultra.Core/EtwUltraProfilerConsoleMode.cs b/src/Ultra.Core/EtwUltraProfilerConsoleMode.cs new file mode 100644 index 0000000..922ca75 --- /dev/null +++ b/src/Ultra.Core/EtwUltraProfilerConsoleMode.cs @@ -0,0 +1,26 @@ +// 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. + +namespace Ultra.Core; + +/// +/// The mode of the console output. +/// +public enum EtwUltraProfilerConsoleMode +{ + /// + /// No console output from the program started. + /// + Silent, + + /// + /// Redirect the console output from the program started to the current console, but live progress using Spectre.Console is disabled. + /// + Raw, + + /// + /// Redirect the last lines of the console output from the program started to the live progress using Spectre.Console. + /// + Live, +} \ No newline at end of file diff --git a/src/Ultra.Core/EtwUltraProfilerOptions.cs b/src/Ultra.Core/EtwUltraProfilerOptions.cs index acd5383..d7547f1 100644 --- a/src/Ultra.Core/EtwUltraProfilerOptions.cs +++ b/src/Ultra.Core/EtwUltraProfilerOptions.cs @@ -30,6 +30,8 @@ public EtwUltraProfilerOptions() public int TimeOutAfterInMs { get; set; } + public EtwUltraProfilerConsoleMode ConsoleMode { get; set; } + public Action? LogProgress; public Action? LogStepProgress; @@ -38,6 +40,10 @@ public EtwUltraProfilerOptions() public Action? WaitingFileToCompleteTimeOut; + public Action? ProgramLogStdout; + + public Action? ProgramLogStderr; + public bool KeepEtlIntermediateFiles { get; set; } public bool KeepMergedEtl { get; set; } diff --git a/src/Ultra.Example/Program.cs b/src/Ultra.Example/Program.cs index 0129a0c..ec3ed27 100644 --- a/src/Ultra.Example/Program.cs +++ b/src/Ultra.Example/Program.cs @@ -9,6 +9,10 @@ for (int i = 0; i < countBenchMarkdig; i++) { var html = Markdig.Markdown.ToHtml(md); + if (i % 100 == 0 && i > 0) + { + Console.WriteLine($"Markdig {i} conversions done"); + } } }; @@ -24,6 +28,11 @@ for (int i = 0; i < countBenchScriban; i++) { var text = template.Render(new { values = values }); + + if (i % 1000 == 0 && i > 0) + { + Console.WriteLine($"Scriban {i} conversions done"); + } } }; diff --git a/src/Ultra/Program.cs b/src/Ultra/Program.cs index 399bbda..20c29d0 100644 --- a/src/Ultra/Program.cs +++ b/src/Ultra/Program.cs @@ -3,9 +3,11 @@ 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; @@ -42,7 +44,23 @@ static async Task Main(string[] args) { "symbol-path=", $"The {{VALUE}} of symbol path. The default value is `{options.GetCachedSymbolPath()}`.", v => options.SymbolPathText = v }, { "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 }, - // Action for the commit commandd + { "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 => + { + if ("raw".Equals(v, StringComparison.OrdinalIgnoreCase)) + { + options.ConsoleMode = EtwUltraProfilerConsoleMode.Raw; + } + else if ("live".Equals(v, StringComparison.OrdinalIgnoreCase)) + { + options.ConsoleMode = EtwUltraProfilerConsoleMode.Live; + } + else + { + options.ConsoleMode = EtwUltraProfilerConsoleMode.Silent; + } + } + }, + // Action for the commit command async (ctx, arguments) => { if (arguments.Length == 0 && pidList.Count == 0) @@ -59,76 +77,176 @@ static async Task Main(string[] args) string? fileOutput = null; - await AnsiConsole.Status() - .Spinner(Spinner.Known.Default) - .SpinnerStyle(Style.Parse("red")) - .StartAsync("Profiling", async statusCtx => + + // Add the pid passed as options + options.ProcessIds.AddRange(pidList); + + if (arguments.Length == 1 && int.TryParse(arguments[0], out var pid)) + { + options.ProcessIds.Add(pid); + } + else if (arguments.Length > 0) + { + options.ProgramPath = arguments[0]; + options.Arguments.AddRange(arguments.AsSpan().Slice(1)); + } + + var etwProfiler = new EtwUltraProfiler(); + Console.CancelKeyPress += (sender, eventArgs) => + { + AnsiConsole.WriteLine(); + AnsiConsole.MarkupLine("[darkorange]Cancelled via CTRL+C[/]"); + eventArgs.Cancel = true; + // ReSharper disable once AccessToDisposedClosure + if (etwProfiler.Cancel()) + { + AnsiConsole.MarkupLine("[red]Stopped via CTRL+C[/]"); + } + }; + + if (options.ConsoleMode == EtwUltraProfilerConsoleMode.Silent) + { + await AnsiConsole.Status() + .Spinner(Spinner.Known.Default) + .SpinnerStyle(Style.Parse("red")) + .StartAsync("Profiling", async statusCtx => + { + string? previousText = null; + + options.LogStepProgress = (text) => + { + if (verbose && previousText is not null && previousText != text) + { + AnsiConsole.MarkupLine($"{Markup.Escape(previousText)} [green]\u2713[/]"); + previousText = text; + } + + statusCtx.Status(Markup.Escape(text)); + }; + options.LogProgress = (text) => + { + if (verbose && previousText != null && previousText != text) + { + AnsiConsole.MarkupLine($"{Markup.Escape(previousText)} [green]\u2713[/]"); + } + + statusCtx.Status(Markup.Escape(text)); + previousText = text; + }; + options.WaitingFileToComplete = (file) => { statusCtx.Status($"Waiting for {Markup.Escape(file)} to complete"); }; + options.WaitingFileToCompleteTimeOut = (file) => { statusCtx.Status($"Timeout waiting for {Markup.Escape(file)} to complete"); }; + + try + { + fileOutput = await etwProfiler.Run(options); + } + finally + { + etwProfiler.Dispose(); + } + + if (verbose) + { + options.LogProgress.Invoke("Profiling Done"); + } + } + ); + } + else if (options.ConsoleMode == EtwUltraProfilerConsoleMode.Raw) + { + options.LogStepProgress = s => AnsiConsole.WriteLine($">>ultra::{s}"); + options.LogProgress = s => AnsiConsole.WriteLine($">>ultra::{s}"); + options.WaitingFileToComplete = (file) => { AnsiConsole.WriteLine($">>ultra::Waiting for {Markup.Escape(file)} to complete"); }; + options.WaitingFileToCompleteTimeOut = (file) => { AnsiConsole.WriteLine($">>ultra::Timeout waiting for {Markup.Escape(file)} to complete"); }; + options.ProgramLogStdout = AnsiConsole.WriteLine; + options.ProgramLogStderr = AnsiConsole.WriteLine; + + try + { + fileOutput = await etwProfiler.Run(options); + } + finally + { + etwProfiler.Dispose(); + } + } + else if (options.ConsoleMode == EtwUltraProfilerConsoleMode.Live) + { + var statusTable = new StatusTable(); + + await AnsiConsole.Live(statusTable.Table) + // .AutoClear(true) // No auto clear to keep the output (e.g. in case the program shows errors in its stdout/stderr) + .StartAsync(async liveCtx => { string? previousText = null; - + options.LogStepProgress = (text) => { if (verbose && previousText is not null && previousText != text) { - AnsiConsole.MarkupLine($"{Markup.Escape(previousText)} [green]\u2713[/]"); + statusTable.LogText($"{Markup.Escape(previousText)} [green]\u2713[/]"); previousText = text; } - statusCtx.Status(Markup.Escape(text)); + statusTable.Status(Markup.Escape(text)); + + statusTable.UpdateTable(); + liveCtx.Refresh(); }; + options.LogProgress = (text) => { if (verbose && previousText != null && previousText != text) { - AnsiConsole.MarkupLine($"{Markup.Escape(previousText)} [green]\u2713[/]"); + statusTable.LogText($"{Markup.Escape(previousText)} [green]\u2713[/]"); } - statusCtx.Status(Markup.Escape(text)); + statusTable.Status(Markup.Escape(text)); previousText = text; + + statusTable.UpdateTable(); + liveCtx.Refresh(); }; - options.WaitingFileToComplete = (file) => { statusCtx.Status($"Waiting for {Markup.Escape(file)} to complete"); }; - options.WaitingFileToCompleteTimeOut = (file) => { statusCtx.Status($"Timeout waiting for {Markup.Escape(file)} to complete"); }; - // Add the pid passed as options - options.ProcessIds.AddRange(pidList); - - if (arguments.Length == 1 && int.TryParse(arguments[0], out var pid)) + options.WaitingFileToComplete = (file) => { - options.ProcessIds.Add(pid); - } - else if (arguments.Length > 0) + statusTable.Status($"Waiting for {Markup.Escape(file)} to complete"); + statusTable.UpdateTable(); + liveCtx.Refresh(); + }; + + options.WaitingFileToCompleteTimeOut = (file) => { - options.ProgramPath = arguments[0]; - options.Arguments.AddRange(arguments.AsSpan().Slice(1)); - } + statusTable.Status($"Timeout waiting for {Markup.Escape(file)} to complete"); + statusTable.UpdateTable(); + liveCtx.Refresh(); + }; + + options.ProgramLogStdout = (text) => + { + statusTable.LogText(text); + statusTable.UpdateTable(); + liveCtx.Refresh(); + }; + + options.ProgramLogStderr = (text) => + { + statusTable.LogText(text); + statusTable.UpdateTable(); + liveCtx.Refresh(); + }; - var etwProfiler = new EtwUltraProfiler(); try { - Console.CancelKeyPress += (sender, eventArgs) => - { - AnsiConsole.WriteLine(); - AnsiConsole.MarkupLine("[darkorange]Cancelled via CTRL+C[/]"); - eventArgs.Cancel = true; - if (etwProfiler.Cancel()) - { - AnsiConsole.MarkupLine("[red]Stopped via CTRL+C[/]"); - } - }; - fileOutput = await etwProfiler.Run(options); } finally { etwProfiler.Dispose(); } - - if (verbose) - { - options.LogProgress.Invoke("Profiling Done"); - } } ); + } if (fileOutput != null) { @@ -255,4 +373,61 @@ await AnsiConsole.Status() return 1; } } + + private class StatusTable + { + private string? _statusText; + private readonly Queue _logLines = new(); + private const int MaxLogLines = 10; + private int _spinnerStep; + private readonly Style _spinnerStyle; + + public StatusTable() + { + Table = new Table(); + Table.AddColumn(new TableColumn("Status")); + _spinnerStyle = Style.Parse("red"); + } + + public Table Table { get; } + + public void LogText(string text) + { + if (_logLines.Count > MaxLogLines) + { + _logLines.Dequeue(); + } + + _logLines.Enqueue(text); + } + + public void Status(string text) + { + _statusText = text; + } + + public void UpdateTable() + { + Table.Rows.Clear(); + + if (_logLines.Count > 0) + { + var rows = new Rows(_logLines.Select(x => new Markup(x))); + Table.AddRow(rows); + } + + if (_statusText != null) + { + var tableColumn = Table.Columns[0]; + + var spinnerStep = _spinnerStep; + var spinnerText = Spinner.Known.Default.Frames[spinnerStep]; + _spinnerStep = (_spinnerStep + 1) % Spinner.Known.Default.Frames.Count; + + tableColumn.Header = new Markup($"[red]{spinnerText}[/] Status"); + tableColumn.Footer = new Markup(_statusText); + Table.ShowFooters = true; + } + } + } } \ No newline at end of file