using System; using System.Diagnostics; namespace Umbraco.Core.Logging { /// /// Starts the timer and invokes a callback upon disposal. Provides a simple way of timing an operation by wrapping it in a using (C#) statement. /// public class DisposableTimer : DisposableObjectSlim { private readonly ILogger _logger; private readonly LogLevel _level; private readonly Type _loggerType; private readonly int _thresholdMilliseconds; private readonly IDisposable _profilerStep; private readonly string _endMessage; private string _failMessage; private Exception _failException; private bool _failed; private readonly string _timingId; // internal - created by profiling logger internal DisposableTimer(ILogger logger, LogLevel level, IProfiler profiler, Type loggerType, string startMessage, string endMessage, string failMessage = null, int thresholdMilliseconds = 0) { _logger = logger ?? throw new ArgumentNullException(nameof(logger)); _level = level; _loggerType = loggerType ?? throw new ArgumentNullException(nameof(loggerType)); _endMessage = endMessage; _failMessage = failMessage; _thresholdMilliseconds = thresholdMilliseconds < 0 ? 0 : thresholdMilliseconds; _timingId = Guid.NewGuid().ToString("N").Substring(0, 7); // keep it short-ish if (thresholdMilliseconds == 0) { switch (_level) { case LogLevel.Debug: logger.Debug(loggerType, "{StartMessage} [Timing {TimingId}]", startMessage, _timingId); break; case LogLevel.Information: logger.Info(loggerType, "{StartMessage} [Timing {TimingId}]", startMessage, _timingId); break; default: throw new ArgumentOutOfRangeException(nameof(level)); } } // else aren't logging the start message, this is output to the profiler but not the log, // we just want the log to contain the result if it's more than the minimum ms threshold. _profilerStep = profiler?.Step(loggerType, startMessage); } /// /// Reports a failure. /// /// The fail message. /// The exception. /// Completion of the timer will be reported as an error, with the specified message and exception. public void Fail(string failMessage = null, Exception exception = null) { _failed = true; _failMessage = failMessage ?? _failMessage ?? "Failed."; _failException = exception; } public Stopwatch Stopwatch { get; } = Stopwatch.StartNew(); /// ///Disposes resources. /// /// Overrides abstract class which handles required locking. protected override void DisposeResources() { Stopwatch.Stop(); _profilerStep?.Dispose(); if ((Stopwatch.ElapsedMilliseconds >= _thresholdMilliseconds || _failed) && _loggerType != null && _logger != null && (string.IsNullOrWhiteSpace(_endMessage) == false || _failed)) { if (_failed) { _logger.Error(_loggerType, _failException, "{FailMessage} ({Duration}ms) [Timing {TimingId}]", _failMessage, Stopwatch.ElapsedMilliseconds, _timingId); } else switch (_level) { case LogLevel.Debug: _logger.Debug(_loggerType, "{EndMessage} ({Duration}ms) [Timing {TimingId}]", _endMessage, Stopwatch.ElapsedMilliseconds, _timingId); break; case LogLevel.Information: _logger.Info(_loggerType, "{EndMessage} ({Duration}ms) [Timing {TimingId}]", _endMessage, Stopwatch.ElapsedMilliseconds, _timingId); break; // filtered in the ctor //default: // throw new Exception(); } } } } }