/// <inheritdoc cref="LongOperationLoggingStopwatch"/> /// <param name="identifier"> /// String to identify in the logs what operation was timed. /// A unique identifier will be generated in addition to this, so that multiple executions are distinguishable. /// </param> /// <param name="logger"> /// Logger object to perform the logging when complete /// </param> /// <param name="loggingSettings"> /// Override the defaults for how the inner operations get logged. /// </param> public LongOperationLoggingStopwatch(string identifier, IStopwatchLogger logger, LongLoggingSettings loggingSettings = null) : base(identifier, logger) { settings?.Validate(); settings = loggingSettings ?? new LongLoggingSettings(); LogInitiationMessage(); innerTimingHandler = new InnerOperationExecutionTimer(this); base.timer.Start(); // Zero out the time taken in this ctor, since the end of the base ctor. }
// This is deliberately static, so that we're forced to explicitly pass in captured // values and can't use instance fields that might have been updated by other threads. // This is to ensure that it is fully threadsafe. private static void LogPerExecutionMessageIfAppropriate(LongLoggingSettings settings, int newCompletedCount, Stopwatch outerStopwatch, Action <string> logAction) { if (newCompletedCount % settings.InnerOperationLoggingPeriod == 0) { try { var elapsedOuterTime_MS = outerStopwatch.ElapsedMilliseconds; //Dont pass in just the ElapsedMillis, since that's not completely trivial for it to calculate. var logMessage = $"Progress: ({newCompletedCount}) operations completed."; if (settings.ExpectedNumberOfIterations.HasValue) { var completionPercentage = Decimal.Divide(newCompletedCount, settings.ExpectedNumberOfIterations.Value); if (settings.ReportPercentageCompletion) { logMessage += $"|{completionPercentage:0.00%}"; } if (settings.ReportProjectedCompletionTime) { var remainingPercentage = 1 - completionPercentage; var remainingMultiplier = remainingPercentage / completionPercentage; var projectedTotalTimeRemaining_MS = elapsedOuterTime_MS * remainingMultiplier; var projectedOuterCompletionTime = DateTime.UtcNow.AddMilliseconds((double)projectedTotalTimeRemaining_MS); logMessage += $"|Projected completion time: {projectedOuterCompletionTime}Z (UTC)"; } } logAction(logMessage); } catch (Exception e) { // We really don't expect exceptions above, but if anything goes // wrong we don't want it to bring down the calling operation. logAction("Swallowing exception in LoggingStopwatch: " + e.ToString()); } } }
//Note if you copy-paste this code, feel free to delete this if you don't want the Microsoft.Extensions.Logging dependency. /// <inheritdoc/> /// <param name="identifier">Defers to Inherited paramDoc</param> /// <param name="microsoftLogger">Accepts an <see cref="ILogger"/> and logs to it at the <see cref="LogLevel.Information"/> level.</param> /// <param name="logAtStart">Defers to Inherited paramDoc</param> public LongOperationLoggingStopwatch(string identifier, ILogger microsoftLogger, LongLoggingSettings settings = null) : this(identifier, new MicrosoftLoggerWrapper(microsoftLogger), settings) { }
/// <inheritdoc/> /// <param name="identifier">Defers to Inherited paramDoc</param> /// <param name="loggingAction">Method to call whenever some text should be logged.</param> /// <param name="settings">Defers to Inherited paramDoc</param> public LongOperationLoggingStopwatch(string identifier, Action <string> loggingAction, LongLoggingSettings settings = null) : this(identifier, new LambdaLogger(loggingAction), settings) { }