/// <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)
{
}
