| | | 1 | | // ----------------------------------------------------------------------- |
| | | 2 | | // <copyright file="PerformanceLogger.cs" company="Stéphane ANDRE"> |
| | | 3 | | // Copyright (c) Stéphane ANDRE. All rights reserved. |
| | | 4 | | // </copyright> |
| | | 5 | | // ----------------------------------------------------------------------- |
| | | 6 | | |
| | | 7 | | using System; |
| | | 8 | | using System.Collections.Concurrent; |
| | | 9 | | using System.Collections.Generic; |
| | | 10 | | using System.Diagnostics; |
| | | 11 | | using System.Diagnostics.CodeAnalysis; |
| | | 12 | | using System.Linq; |
| | | 13 | | using System.Threading; |
| | | 14 | | using Microsoft.Extensions.Logging; |
| | | 15 | | |
| | | 16 | | namespace MyNet.Utilities.Logging; |
| | | 17 | | |
| | | 18 | | /// <summary> |
| | | 19 | | /// A utility class for logging the performance of code blocks. It uses a stack to manage nested performance loggers and |
| | | 20 | | /// </summary> |
| | | 21 | | public sealed class PerformanceLogger : IDisposable |
| | | 22 | | { |
| | 6 | 23 | | private static readonly AsyncLocal<Stack<PerformanceLogger>?> CurrentStack = new(); |
| | | 24 | | |
| | 138 | 25 | | private static Stack<PerformanceLogger> Stack => CurrentStack.Value ??= new(); |
| | | 26 | | |
| | | 27 | | private readonly ILogger _logger; |
| | | 28 | | private readonly string _title; |
| | | 29 | | private readonly Stopwatch _stopwatch; |
| | | 30 | | private readonly IDisposable? _scope; |
| | 27 | 31 | | private readonly ConcurrentDictionary<string, RegisteredTime> _registeredTimes = new(); |
| | | 32 | | private readonly Func<TimeSpan, LogLevel> _provideLogLevel; |
| | | 33 | | private bool _disposed; |
| | | 34 | | |
| | | 35 | | /// <summary> |
| | | 36 | | /// Initializes a new instance of the <see cref="PerformanceLogger"/> class with the specified logger, title, log le |
| | | 37 | | /// </summary> |
| | | 38 | | /// <param name="logger">The logger to use for logging performance messages.</param> |
| | | 39 | | /// <param name="title">The title of the performance logger, used in log messages.</param> |
| | | 40 | | /// <param name="level">The log level to use for logging performance messages.</param> |
| | | 41 | | /// <param name="showStartMessage">Whether to show a start message when the performance logger is created.</param> |
| | | 42 | | /// <param name="showEndMessage">Whether to show an end message when the performance logger is disposed.</param> |
| | | 43 | | public PerformanceLogger(ILogger logger, string title, LogLevel level = LogLevel.Trace, bool showStartMessage = fals |
| | 24 | 44 | | : this(logger, title, _ => level, showStartMessage, showEndMessage) |
| | | 45 | | { |
| | 24 | 46 | | } |
| | | 47 | | |
| | | 48 | | /// <summary> |
| | | 49 | | /// Initializes a new instance of the <see cref="PerformanceLogger"/> class with the specified logger, title, functi |
| | | 50 | | /// </summary> |
| | | 51 | | /// <param name="logger">The logger to use for logging performance messages.</param> |
| | | 52 | | /// <param name="title">The title of the performance logger, used in log messages.</param> |
| | | 53 | | /// <param name="provideLogLevel">A function that determines the log level based on the elapsed time.</param> |
| | | 54 | | /// <param name="showStartMessage">Whether to show a start message when the performance logger is created.</param> |
| | | 55 | | /// <param name="showEndMessage">Whether to show an end message when the performance logger is disposed.</param> |
| | | 56 | | public PerformanceLogger(ILogger logger, string title, Func<TimeSpan, LogLevel> provideLogLevel, bool showStartMessa |
| | | 57 | | { |
| | 27 | 58 | | _logger = logger ?? throw new ArgumentNullException(nameof(logger)); |
| | 27 | 59 | | _title = title ?? throw new ArgumentNullException(nameof(title)); |
| | 27 | 60 | | _provideLogLevel = provideLogLevel ?? throw new ArgumentNullException(nameof(provideLogLevel)); |
| | | 61 | | |
| | 27 | 62 | | Stack.Push(this); |
| | | 63 | | |
| | 27 | 64 | | _scope = _logger.BeginScope(_title); |
| | | 65 | | |
| | 27 | 66 | | if (showStartMessage) |
| | | 67 | | { |
| | 3 | 68 | | _logger.LogStart(_title); |
| | | 69 | | } |
| | | 70 | | |
| | 27 | 71 | | _stopwatch = Stopwatch.StartNew(); |
| | | 72 | | |
| | | 73 | | ShowEndMessage = showEndMessage; |
| | 27 | 74 | | } |
| | | 75 | | |
| | | 76 | | /// <summary> |
| | | 77 | | /// Gets the current performance logger from the stack. If there are no performance loggers in the stack, it returns |
| | | 78 | | /// </summary> |
| | 0 | 79 | | public static PerformanceLogger? Current => Stack.Count == 0 ? null : Stack.Peek(); |
| | | 80 | | |
| | | 81 | | /// <summary> |
| | | 82 | | /// Gets a value indicating whether to show an end message when the performance logger is disposed. This property is |
| | | 83 | | /// </summary> |
| | | 84 | | public bool ShowEndMessage { get; } |
| | | 85 | | |
| | | 86 | | /// <summary> |
| | | 87 | | /// Gets the elapsed time since the performance logger was created. This property returns the total time that has pa |
| | | 88 | | /// </summary> |
| | 39 | 89 | | public TimeSpan Elapsed => _stopwatch.Elapsed; |
| | | 90 | | |
| | | 91 | | /// <summary> |
| | | 92 | | /// Formats a TimeSpan into a human-readable string with appropriate units (days, hours, minutes, seconds, milliseco |
| | | 93 | | /// </summary> |
| | | 94 | | /// <param name="time">The TimeSpan to format.</param> |
| | | 95 | | /// <returns>A formatted string representing the TimeSpan.</returns> |
| | | 96 | | private static string FormatTimeSpan(TimeSpan time) => |
| | 21 | 97 | | time.TotalDays >= 1 |
| | 21 | 98 | | ? $"{time.TotalDays:F2}d" |
| | 21 | 99 | | : time.TotalHours >= 1 |
| | 21 | 100 | | ? $"{time.TotalHours:F2}h" |
| | 21 | 101 | | : time.TotalMinutes >= 1 |
| | 21 | 102 | | ? $"{time.TotalMinutes:F2}m" |
| | 21 | 103 | | : time.TotalSeconds >= 1 |
| | 21 | 104 | | ? $"{time.TotalSeconds:F2}s" |
| | 21 | 105 | | : time.TotalMilliseconds >= 1 |
| | 21 | 106 | | ? $"{time.TotalMilliseconds:F2}ms" |
| | 21 | 107 | | : $"{time.TotalMicroseconds:F2}μs"; |
| | | 108 | | |
| | | 109 | | /// <summary> |
| | | 110 | | /// Disposes the performance logger, stopping the stopwatch and logging the elapsed time along with any registered t |
| | | 111 | | /// </summary> |
| | | 112 | | public void Dispose() |
| | | 113 | | { |
| | 27 | 114 | | if (_disposed) |
| | | 115 | | { |
| | 0 | 116 | | return; |
| | | 117 | | } |
| | | 118 | | |
| | 27 | 119 | | _disposed = true; |
| | | 120 | | |
| | 27 | 121 | | _stopwatch.Stop(); |
| | | 122 | | |
| | 27 | 123 | | var elapsed = _stopwatch.Elapsed; |
| | | 124 | | |
| | 27 | 125 | | if (ShowEndMessage) |
| | | 126 | | { |
| | 3 | 127 | | if (_logger.IsEnabled(LogLevel.Trace)) |
| | | 128 | | { |
| | 3 | 129 | | _logger.LogEnd(_title, FormatTimeSpan(elapsed)); |
| | | 130 | | } |
| | | 131 | | } |
| | | 132 | | |
| | 27 | 133 | | PerformanceLogger? parent = null; |
| | | 134 | | |
| | 27 | 135 | | if (Stack.Count > 0 && ReferenceEquals(Stack.Peek(), this)) |
| | | 136 | | { |
| | 27 | 137 | | Stack.Pop(); |
| | | 138 | | } |
| | | 139 | | |
| | 27 | 140 | | if (Stack.Count > 0) |
| | | 141 | | { |
| | 3 | 142 | | parent = Stack.Peek(); |
| | | 143 | | } |
| | | 144 | | |
| | 27 | 145 | | if (parent is null) |
| | | 146 | | { |
| | 24 | 147 | | TraceTimes(); |
| | | 148 | | } |
| | | 149 | | else |
| | | 150 | | { |
| | 3 | 151 | | var level = _provideLogLevel(elapsed); |
| | | 152 | | |
| | 3 | 153 | | parent.AddTime(_title, elapsed, level); |
| | 3 | 154 | | parent.MergeTimes(this); |
| | | 155 | | } |
| | | 156 | | |
| | 27 | 157 | | _scope?.Dispose(); |
| | 27 | 158 | | } |
| | | 159 | | |
| | | 160 | | /// <summary> |
| | | 161 | | /// Adds a registered time to the performance logger with the specified key, time, and log level. This method allows |
| | | 162 | | /// </summary> |
| | | 163 | | /// <param name="key">The key associated with the registered time.</param> |
| | | 164 | | /// <param name="time">The time span to register.</param> |
| | | 165 | | /// <param name="level">The log level for the registered time.</param> |
| | | 166 | | public void AddTime(string key, TimeSpan time, LogLevel level) |
| | 3 | 167 | | => _registeredTimes.AddOrUpdate(key, _ => new(level, time), (_, existing) => new(level, existing.Time + time)); |
| | | 168 | | |
| | | 169 | | /// <summary> |
| | | 170 | | /// Merges the registered times from a child performance logger into the current performance logger. This method is |
| | | 171 | | /// </summary> |
| | | 172 | | /// <param name="child">The child performance logger whose registered times are to be merged.</param> |
| | | 173 | | private void MergeTimes(PerformanceLogger child) |
| | | 174 | | { |
| | 6 | 175 | | foreach (var item in child._registeredTimes) |
| | | 176 | | { |
| | 0 | 177 | | AddTime( |
| | 0 | 178 | | $"{child._title} -> {item.Key}", |
| | 0 | 179 | | item.Value.Time, |
| | 0 | 180 | | item.Value.Level); |
| | | 181 | | } |
| | 3 | 182 | | } |
| | | 183 | | |
| | | 184 | | /// <summary> |
| | | 185 | | /// Logs the total elapsed time and any registered times in a structured format. If there are no registered times, i |
| | | 186 | | /// </summary> |
| | | 187 | | [SuppressMessage("Performance", "CA1848:Use the LoggerMessage delegates", Justification = "The number of messages is |
| | | 188 | | [SuppressMessage("ReSharper", "DuplicateItemInLoggerTemplate", Justification = "The log messages are dynamic and do |
| | | 189 | | private void TraceTimes() |
| | | 190 | | { |
| | 24 | 191 | | var totalLevel = _provideLogLevel(Elapsed); |
| | | 192 | | |
| | 24 | 193 | | if (_registeredTimes.IsEmpty) |
| | | 194 | | { |
| | 21 | 195 | | if (_logger.IsEnabled(totalLevel)) |
| | 12 | 196 | | _logger.Log(totalLevel, "{Title} completed in {Elapsed}", _title, FormatTimeSpan(Elapsed)); |
| | | 197 | | |
| | 21 | 198 | | return; |
| | | 199 | | } |
| | | 200 | | |
| | | 201 | | const string separator = "********************"; |
| | | 202 | | |
| | 3 | 203 | | if (_logger.IsEnabled(totalLevel)) |
| | 3 | 204 | | _logger.Log(totalLevel, "{} {Title} {Separator}", separator, _title, separator); |
| | | 205 | | |
| | 12 | 206 | | foreach (var item in _registeredTimes.OrderByDescending(x => x.Value.Time)) |
| | | 207 | | { |
| | 3 | 208 | | if (_logger.IsEnabled(item.Value.Level)) |
| | 3 | 209 | | _logger.Log(item.Value.Level, "{Key} - {Elapsed}", item.Key, FormatTimeSpan(item.Value.Time)); |
| | | 210 | | } |
| | | 211 | | |
| | 3 | 212 | | if (_logger.IsEnabled(totalLevel)) |
| | 3 | 213 | | _logger.Log(totalLevel, "Total Time : {Elapsed}", FormatTimeSpan(Elapsed)); |
| | | 214 | | |
| | 3 | 215 | | if (_logger.IsEnabled(totalLevel)) |
| | 3 | 216 | | _logger.Log(totalLevel, "{Separator} {Title} {Separator}", separator, _title, separator); |
| | 3 | 217 | | } |
| | | 218 | | |
| | | 219 | | /// <summary> |
| | | 220 | | /// A record representing a registered time measurement with an associated log level. This record is used to store t |
| | | 221 | | /// </summary> |
| | | 222 | | /// <param name="Level">The log level associated with the registered time.</param> |
| | | 223 | | /// <param name="Time">The time span of the registered time.</param> |
| | | 224 | | private sealed record RegisteredTime(LogLevel Level, TimeSpan Time); |
| | | 225 | | } |
| | | 226 | | |