From 528237436044fd56b05c366bf012a0d343f099a2 Mon Sep 17 00:00:00 2001 From: William Sossamon <3278433+WillSoss@users.noreply.github.com> Date: Wed, 7 Feb 2024 16:39:52 -0600 Subject: [PATCH] New and improved console output --- src/Diagnostics/DiagnosticJob.cs | 6 +- src/Diagnostics/Diagnostics.csproj | 2 +- .../Properties/launchSettings.json | 8 + src/Runly/Execution.cs | 64 ++++- src/Runly/Hosting/RunAction.cs | 264 ++++++++++++++++-- src/Runly/JobHost.cs | 51 +++- src/Runly/Runly.csproj | 1 + src/Runly/Testing/Average.cs | 67 +++++ src/Runly/Testing/DataPoint.cs | 10 + src/Runly/Testing/Metric.cs | 27 ++ test/Runly.Tests.Cli/TestJob.cs | 6 +- test/Runly.Tests/Runly.Tests.csproj | 2 +- 12 files changed, 474 insertions(+), 34 deletions(-) create mode 100644 src/Diagnostics/Properties/launchSettings.json create mode 100644 src/Runly/Testing/Average.cs create mode 100644 src/Runly/Testing/DataPoint.cs create mode 100644 src/Runly/Testing/Metric.cs diff --git a/src/Diagnostics/DiagnosticJob.cs b/src/Diagnostics/DiagnosticJob.cs index d89bf4d..4fe2dee 100644 --- a/src/Diagnostics/DiagnosticJob.cs +++ b/src/Diagnostics/DiagnosticJob.cs @@ -87,10 +87,10 @@ public override Task GetItemIdAsync(DiagnosticItem item) return Task.FromResult(item.Id); } - public override Task ProcessAsync(DiagnosticItem item) + public override async Task ProcessAsync(DiagnosticItem item) { if (Config.MillisecondDelayPerItem > 0) - Thread.Sleep(Config.MillisecondDelayPerItem); + await Task.Delay(Config.MillisecondDelayPerItem); if (Config.WaitForSignalInProcessAsync) signal.WaitOne(); @@ -104,7 +104,7 @@ public override Task ProcessAsync(DiagnosticItem item) if (Config.ThrowExceptionInProcessAsync) throw new DiagnosticJobException(JobMethod.ProcessAsync, "Exception thrown because Config.ThrowExceptionInProcess is true."); - return Task.FromResult(item.IsSuccessful ? Result.Success(item.Category) : Result.Failure(item.Category)); + return item.IsSuccessful ? Result.Success(item.Category) : Result.Failure(item.Category); } public override Task FinalizeAsync(Disposition disposition) diff --git a/src/Diagnostics/Diagnostics.csproj b/src/Diagnostics/Diagnostics.csproj index f11c327..66ffb0d 100644 --- a/src/Diagnostics/Diagnostics.csproj +++ b/src/Diagnostics/Diagnostics.csproj @@ -1,7 +1,7 @@  - netcoreapp3.1 + net8.0 Exe Runly.Diagnostics Runly.Diagnostics diff --git a/src/Diagnostics/Properties/launchSettings.json b/src/Diagnostics/Properties/launchSettings.json new file mode 100644 index 0000000..05c75f6 --- /dev/null +++ b/src/Diagnostics/Properties/launchSettings.json @@ -0,0 +1,8 @@ +{ + "profiles": { + "Diagnostics": { + "commandName": "Project", + "commandLineArgs": "diagnosticjob --milliseconddelayperitem 10 --numberofitems 5000" + } + } +} \ No newline at end of file diff --git a/src/Runly/Execution.cs b/src/Runly/Execution.cs index 7bcd334..48b6596 100644 --- a/src/Runly/Execution.cs +++ b/src/Runly/Execution.cs @@ -1,4 +1,5 @@ -using System; +using Runly.Testing; +using System; using System.Collections.Concurrent; using System.Collections.Generic; using System.Threading; @@ -12,9 +13,44 @@ namespace Runly public abstract class Execution { /// - /// Event raised when execution of a job starts. + /// Gets the overall and last minute average time for an item to be processed. /// - public event Func Started; + public Average ItemProcessingTime { get; } = new Average("Item Processing Time"); + + /// + /// Gets a list of MethodOutcomes for each method of a job, excluding methods executed per item. + /// + public Dictionary Methods { get; } = new Dictionary(); + + /// + /// Gets the for InitializeAsync. + /// + public MethodOutcome InitializeAsync => Methods.ValueOrDefault(JobMethod.InitializeAsync); + + /// + /// Gets the for GetItemsAsync. + /// + public MethodOutcome GetItemsAsync => Methods.ValueOrDefault(JobMethod.GetItemsAsync); + + /// + /// Gets the for Count. + /// + public MethodOutcome Count => Methods.ValueOrDefault(JobMethod.Count); + + /// + /// Gets the for GetEnumerator. + /// + public MethodOutcome GetEnumerator => Methods.ValueOrDefault(JobMethod.GetEnumerator); + + /// + /// Gets the for FinalizeAsync. + /// + public MethodOutcome FinalizeAsync => Methods.ValueOrDefault(JobMethod.FinalizeAsync); + + /// + /// Event raised when execution of a job starts. + /// + public event Func Started; /// /// Event raised when the state of the job changes. @@ -237,7 +273,9 @@ protected void SetState(ExecutionState state) /// protected void CompleteMethod(JobMethod method, TimeSpan duration, Exception exception) { - events.Enqueue(new MethodOutcome(method, duration, exception)); + var mo = new MethodOutcome(method, duration, exception); + Methods.Add(method, mo); + events.Enqueue(mo); } /// @@ -273,10 +311,16 @@ private async Task RunEventPump(CancellationToken cancellationToken) while (!cancellationToken.IsCancellationRequested) { await PublishEvents(); + + ItemProcessingTime.Purge(); - await Task.Delay(100); + await Task.Delay(50); } - } + + await PublishEvents(); + + ItemProcessingTime.Purge(); + } private async Task PublishEvents() { @@ -286,6 +330,14 @@ private async Task PublishEvents() { try { + if (@event is ItemResult r) + { + if (r.IsSuccessful) + ItemProcessingTime.RecordSuccess(r.ProcessAsync.Duration); + else + ItemProcessingTime.RecordError(); + } + await (@event switch { ItemResult result => ItemCompleted != null ? ItemCompleted(result) : Task.CompletedTask, diff --git a/src/Runly/Hosting/RunAction.cs b/src/Runly/Hosting/RunAction.cs index ae275e8..c4ea359 100644 --- a/src/Runly/Hosting/RunAction.cs +++ b/src/Runly/Hosting/RunAction.cs @@ -1,13 +1,17 @@ using Microsoft.Extensions.Logging; using Runly.Client; using Runly.Client.Models; +using Spectre.Console; +using Spectre.Console.Rendering; using System; using System.Collections.Generic; using System.Diagnostics; using System.IO; using System.Linq; +using System.Text; using System.Threading; using System.Threading.Tasks; +using System.Xml; namespace Runly.Hosting { @@ -30,7 +34,15 @@ public RunAction(Execution execution, Config config, ILogger logger, } public async Task RunAsync(CancellationToken token) - { + { + Console.OutputEncoding = Encoding.UTF8; + Console.InputEncoding = Encoding.UTF8; + + AnsiConsole.MarkupLine($"Running [blue]{config.Job.Type}[/]"); + AnsiConsole.WriteLine(); + AnsiConsole.MarkupLine($"[dim]Press 'c' to cancel[/]"); + AnsiConsole.WriteLine(); + if (debug) AttachDebugger(); @@ -102,34 +114,183 @@ public async Task RunAsync(CancellationToken token) if (useApi) pinging = PingApi(channel, pingCancellation.Token); - while (!executing.IsCompleted && config.Execution.ResultsToConsole) + if (config.Execution.ResultsToConsole) { - Console.Write($"\rRunning {execution.Job.GetType().Name}: {execution.CompletedItemCount} items{(execution.TotalItemCount.HasValue ? " of " + execution.TotalItemCount.Value : string.Empty)} processed. {(!jobCancellation.IsCancellationRequested ? "Press 'q' to quit." : "Quitting... ")}"); - - while (!jobCancellation.IsCancellationRequested && !Console.IsInputRedirected && Console.KeyAvailable) + await AnsiConsole.Status() + .Spinner(Spinner.Known.Dots) + .SpinnerStyle(Style.Parse("yellow bold")) + .StartAsync("Starting...", async ctx => + { + AnsiConsole.Markup("Starting..."); + + while (execution.State == ExecutionState.NotStarted || + execution.State == ExecutionState.Initializing) + await Task.Delay(10); + + if (execution.InitializeAsync.IsSuccessful) + { + AnsiConsole.MarkupLine("[green]Success[/]"); + + AnsiConsole.Markup("Getting items..."); + + while (execution.State == ExecutionState.GettingItemsToProcess) + await Task.Delay(10); + + if (execution.GetItemsAsync.IsSuccessful && execution.GetEnumerator.IsSuccessful && execution.Count.IsSuccessful) + { + AnsiConsole.MarkupLine("[green]Success[/]"); + } + else + { + AnsiConsole.MarkupLine("[red]Failed[/]"); + AnsiConsole.WriteLine(); + AnsiConsole.WriteException(execution.GetItemsAsync.Exception ?? execution.GetEnumerator.Exception ?? execution.Count.Exception); + AnsiConsole.WriteLine(); + } + } + else + { + AnsiConsole.MarkupLine("[red]Failed[/]"); + AnsiConsole.WriteLine(); + AnsiConsole.WriteException(execution.InitializeAsync.Exception); + AnsiConsole.WriteLine(); + } + + }); + + if (execution.Disposition != Disposition.Failed) { - var key = Console.ReadKey(); + var isIndeterminate = !execution.TotalItemCount.HasValue; - if (key.KeyChar == 'q' || key.KeyChar == 'Q') - jobCancellation.Cancel(); + var cols = isIndeterminate ? + new ProgressColumn[] + { + new TaskDescriptionColumn(), + new AverageTimeColumn(execution), + new AverageTimeLastMinColumn(execution), + new ElapsedTimeColumn() { Style = Style.Parse("dim") }, + new SpinnerColumn(Spinner.Known.Dots), + } : + new ProgressColumn[] + { + new TaskDescriptionColumn(), + new AverageTimeColumn(execution), + new AverageTimeLastMinColumn(execution), + new PercentageColumn(), + new ElapsedTimeColumn() { Style = Style.Parse("dim") }, + new SpinnerColumn(Spinner.Known.Dots), + }; + + await AnsiConsole.Progress() + .Columns(cols) + .StartAsync(async ctx => + { + var process = ctx.AddTask(isIndeterminate ? "Processing items:" : $"Processing {execution.TotalItemCount:N0} items:", maxValue: execution.TotalItemCount ?? double.MaxValue); + + process.IsIndeterminate = isIndeterminate; + + while (execution.State == ExecutionState.Processing) + { + process.Value = execution.CompletedItemCount; + + await Task.Delay(100); + + if (!Console.IsInputRedirected) + { + while (Console.KeyAvailable) + { + var key = Console.ReadKey(); + + if (key.KeyChar == 'c' || key.KeyChar == 'C') + jobCancellation.Cancel(); + } + } + } + + await Task.Delay(100); + ctx.Refresh(); + + process.Value = execution.CompletedItemCount; + process.StopTask(); + }); } - await Task.Delay(100); - } - - // Execution.RunAsync will ensure all event handlers have completed before exiting - await executing; + await AnsiConsole.Status() + .Spinner(Spinner.Known.Dots) + .SpinnerStyle(Style.Parse("yellow bold")) + .StartAsync("Wrapping up...", async ctx => + { + if (log.Categories.Any()) + { + AnsiConsole.MarkupLine("[dim]Item results:[/]"); + + var grid = new Grid(); + grid.AddColumn(); + grid.AddColumn(); + + foreach (var c in log.Categories) + { + grid.AddRow(new Markup[] + { + new Markup($"{c.Count}"), + new Markup($"{(c.IsSuccessful ? "" : "[red]")}{c.Category}{(c.IsSuccessful ? "" : "[/]")}") + }); + } + + AnsiConsole.Write(grid); + AnsiConsole.WriteLine(); + } + + if (log.FailedItemCount > 0) + { + foreach (var failure in log.FailedItemsThatThrewExceptions.Take(10)) + { + AnsiConsole.MarkupLine($"Item '{failure.Id ?? "Unknown"}' threw an exception:"); + AnsiConsole.WriteException(failure.ProcessAsync?.Exception ?? failure.EnumeratorCurrent?.Exception ?? failure.EnumeratorMoveNext?.Exception); + } + + AnsiConsole.WriteLine(); + } + + AnsiConsole.Markup("Finalizing..."); + + while (execution.State == ExecutionState.Finalizing) + await Task.Delay(10); + + if (execution.FinalizeAsync.IsSuccessful) + AnsiConsole.MarkupLine("[green]Success[/]"); + else + { + AnsiConsole.MarkupLine("[red]Failed[/]"); + AnsiConsole.WriteLine(); + AnsiConsole.WriteException(execution.FinalizeAsync.Exception); + AnsiConsole.WriteLine(); + } + }); + } + + + + // Execution.RunAsync will ensure all event handlers have completed before exiting + await executing; pingCancellation.Cancel(); if (config.Execution.ResultsToConsole) - { - Console.Write("\r" + new string(' ', 80)); - Console.WriteLine(); - Console.WriteLine(log); - } + { + AnsiConsole.WriteLine(); + + if (execution.Disposition == Disposition.Successful) + AnsiConsole.MarkupLine($"[bold green]JOB SUCCESSFUL[/]"); + else if (execution.Disposition == Disposition.Cancelled) + AnsiConsole.MarkupLine($"[bold darkorange]JOB CANCELLED[/]"); + else + AnsiConsole.MarkupLine($"[bold red invert]JOB FAILED[/]"); + + AnsiConsole.WriteLine(); + } - if (config.Execution.ResultsToFile) + if (config.Execution.ResultsToFile) { using var writer = new StreamWriter(File.Open(config.Execution.ResultsFilePath, FileMode.Create)); @@ -271,4 +432,69 @@ private void AttachDebugger() } } } + + internal class ValueColumn : ProgressColumn + { + protected override bool NoWrap => true; + + /// + /// Gets or sets the style of the remaining time text. + /// + public Style Style { get; set; } = Color.Blue; + + /// + public override IRenderable Render(RenderOptions options, ProgressTask task, TimeSpan deltaTime) + { + if (task.IsIndeterminate) + return new Text($"{task.Value:N0}", Style ?? Style.Plain); + else + return new Text($"{task.Value:N0}/{task.MaxValue:N0}", Style ?? Style.Plain); + } + } + + internal class AverageTimeColumn : ProgressColumn + { + private readonly Execution _execution; + + public AverageTimeColumn(Execution execution) + { + _execution = execution; + } + + protected override bool NoWrap => true; + + /// + /// Gets or sets the style of the remaining time text. + /// + public Style Style { get; set; } = Color.Blue; + + /// + public override IRenderable Render(RenderOptions options, ProgressTask task, TimeSpan deltaTime) + { + return new Markup($"[blue]{_execution.ItemProcessingTime.AllTime.Count:N0}[/] [dim]({_execution.ItemProcessingTime.AllTime.Average.TotalMilliseconds}ms avg)[/]"); + } + } + + internal class AverageTimeLastMinColumn : ProgressColumn + { + private readonly Execution _execution; + + public AverageTimeLastMinColumn(Execution execution) + { + _execution = execution; + } + + protected override bool NoWrap => true; + + /// + /// Gets or sets the style of the remaining time text. + /// + public Style Style { get; set; } = Color.Blue; + + /// + public override IRenderable Render(RenderOptions options, ProgressTask task, TimeSpan deltaTime) + { + return new Markup($"Last min: [blue]{_execution.ItemProcessingTime.LastMinuteAverage.Count:N0}[/] [dim]({_execution.ItemProcessingTime.LastMinuteAverage.Average.TotalMilliseconds}ms avg)[/]"); + } + } } diff --git a/src/Runly/JobHost.cs b/src/Runly/JobHost.cs index ce49ba1..aff2587 100644 --- a/src/Runly/JobHost.cs +++ b/src/Runly/JobHost.cs @@ -1,11 +1,13 @@ using System.IO; using System.Reflection; +using System.Runtime.InteropServices; using System.Threading; using System.Threading.Tasks; using Microsoft.Extensions.Configuration; using Microsoft.Extensions.DependencyInjection; using Microsoft.Extensions.Hosting; using Microsoft.Extensions.Logging; +using Microsoft.Extensions.Logging.EventLog; using Runly.Hosting; namespace Runly @@ -63,7 +65,54 @@ public static IHostBuilder CreateDefaultBuilder(string[] args, params Assembly[] { return Host .CreateDefaultBuilder() - .ConfigureServices(services => services.AddRunlyJobs(args, jobAssemblies)); + .ConfigureServices((hostingContext, services) => + { + services.AddLogging(logging => + { + // We need to remove the console logger that Host.CreateDefaultBuilder() + // adds, so we'll ClearProviders then redo everything, minus the console logger. + logging.ClearProviders(); + + bool isWindows = +#if NETCOREAPP + OperatingSystem.IsWindows(); +#elif NETFRAMEWORK + Environment.OSVersion.Platform == PlatformID.Win32NT; +#else + RuntimeInformation.IsOSPlatform(OSPlatform.Windows); +#endif + + // IMPORTANT: This needs to be added *before* configuration is loaded, this lets + // the defaults be overridden by the configuration. + if (isWindows) + { + // Default the EventLogLoggerProvider to warning or above + logging.AddFilter(level => level >= LogLevel.Warning); + } + + logging.AddConfiguration(hostingContext.Configuration.GetSection("Logging")); + + logging.AddDebug(); + logging.AddEventSourceLogger(); + + if (isWindows) + { + // Add the EventLogLoggerProvider on windows machines + logging.AddEventLog(); + } + + logging.Configure(options => + { + options.ActivityTrackingOptions = + ActivityTrackingOptions.SpanId | + ActivityTrackingOptions.TraceId | + ActivityTrackingOptions.ParentId; + }); + }); + + services.AddRunlyJobs(args, jobAssemblies); + + }); } /// diff --git a/src/Runly/Runly.csproj b/src/Runly/Runly.csproj index f93eb80..9a24d2f 100644 --- a/src/Runly/Runly.csproj +++ b/src/Runly/Runly.csproj @@ -42,6 +42,7 @@ + diff --git a/src/Runly/Testing/Average.cs b/src/Runly/Testing/Average.cs new file mode 100644 index 0000000..16f9704 --- /dev/null +++ b/src/Runly/Testing/Average.cs @@ -0,0 +1,67 @@ +using System; +using System.Collections.Concurrent; +using System.Threading; + +namespace Runly.Testing +{ + public class Average + { + private readonly ConcurrentQueue _dataPoints = new ConcurrentQueue(); + private long _errorCount; + public string Name { get; } = string.Empty; + public Metric AllTime { get; } = new Metric(); + public Metric LastMinuteAverage { get; } = new Metric(); + public decimal ErrorRate => AllTime.Count > 0 ? _errorCount / (decimal)AllTime.Count : 0; + public long ErrorCount => _errorCount; + + public Average(string name) + { + Name = name; + } + + public void RecordSuccess(TimeSpan duration) + { + var dp = new DataPoint + { + Time = DateTimeOffset.Now, + Milliseconds = (long)duration.TotalMilliseconds + }; + + _dataPoints.Enqueue(dp); + + AllTime.Add(dp); + LastMinuteAverage.Add(dp); + } + + public void RecordError() + { + Interlocked.Increment(ref _errorCount); + } + + public void Purge() + { + DataPoint dp; + + while (_dataPoints.TryPeek(out dp)) + { + if (dp.Time > DateTimeOffset.Now.AddMinutes(-1)) + return; + + if (_dataPoints.TryDequeue(out dp)) + LastMinuteAverage.Subtract(dp!); + } + } + + public override string ToString() + { + return $@" +{Name} +---------------------------- +Last Min: {LastMinuteAverage.Count}/{LastMinuteAverage.Average.TotalMilliseconds}ms avg +Total: {AllTime.Count}/{AllTime.Average.TotalMilliseconds}ms avg +Errors: {ErrorCount}/{string.Format("{0:P2}", ErrorRate)} + +"; + } + } +} diff --git a/src/Runly/Testing/DataPoint.cs b/src/Runly/Testing/DataPoint.cs new file mode 100644 index 0000000..574176f --- /dev/null +++ b/src/Runly/Testing/DataPoint.cs @@ -0,0 +1,10 @@ +using System; + +namespace Runly.Testing +{ + public class DataPoint + { + public DateTimeOffset Time { get; set; } + public long Milliseconds { get; set; } + } +} diff --git a/src/Runly/Testing/Metric.cs b/src/Runly/Testing/Metric.cs new file mode 100644 index 0000000..3594f91 --- /dev/null +++ b/src/Runly/Testing/Metric.cs @@ -0,0 +1,27 @@ +using System; +using System.Threading; + +namespace Runly.Testing +{ + public class Metric + { + private long _count; + private long _total; + + public long Count => _count; + public long Total => _total; + public TimeSpan Average => _count > 0 ? TimeSpan.FromMilliseconds(_total / _count) : TimeSpan.Zero; + + public void Add(DataPoint data) + { + Interlocked.Increment(ref _count); + Interlocked.Add(ref _total, data.Milliseconds); + } + + public void Subtract(DataPoint data) + { + Interlocked.Decrement(ref _count); + Interlocked.Add(ref _total, -data.Milliseconds); + } + } +} diff --git a/test/Runly.Tests.Cli/TestJob.cs b/test/Runly.Tests.Cli/TestJob.cs index c49ea18..27a2821 100644 --- a/test/Runly.Tests.Cli/TestJob.cs +++ b/test/Runly.Tests.Cli/TestJob.cs @@ -4,10 +4,10 @@ public class TestJob : Job public TestJob(Config config) : base(config) { } - public override Task ProcessAsync() + public override async Task ProcessAsync() { - Console.WriteLine("TestJob is running"); + await Task.Delay(2000); - return Task.FromResult(Result.Success()); + return Result.Success(); } } diff --git a/test/Runly.Tests/Runly.Tests.csproj b/test/Runly.Tests/Runly.Tests.csproj index e307a39..37b807f 100644 --- a/test/Runly.Tests/Runly.Tests.csproj +++ b/test/Runly.Tests/Runly.Tests.csproj @@ -1,7 +1,7 @@  - netcoreapp3.1 + net8.0 false