diff --git a/src/Microsoft.AspNet.Mvc.Core/Infrastructure/MvcRouteHandler.cs b/src/Microsoft.AspNet.Mvc.Core/Infrastructure/MvcRouteHandler.cs index b685d54325..0b4a44d334 100644 --- a/src/Microsoft.AspNet.Mvc.Core/Infrastructure/MvcRouteHandler.cs +++ b/src/Microsoft.AspNet.Mvc.Core/Infrastructure/MvcRouteHandler.cs @@ -87,7 +87,7 @@ namespace Microsoft.AspNet.Mvc.Infrastructure { _logger.ExecutingAction(actionDescriptor); - var startTime = Environment.TickCount; + var startTimestamp = _logger.IsEnabled(LogLevel.Information) ? Stopwatch.GetTimestamp() : 0; var actionContext = new ActionContext(httpContext, routeData, actionDescriptor); if (_actionContextAccessor != null) @@ -105,7 +105,7 @@ namespace Microsoft.AspNet.Mvc.Infrastructure await invoker.InvokeAsync(); - _logger.ExecutedAction(actionDescriptor, startTime); + _logger.ExecutedAction(actionDescriptor, startTimestamp); } } finally diff --git a/src/Microsoft.AspNet.Mvc.Core/Logging/MvcRouteHandlerLoggerExtensions.cs b/src/Microsoft.AspNet.Mvc.Core/Logging/MvcRouteHandlerLoggerExtensions.cs index 6ad08e96d9..11db7286ee 100644 --- a/src/Microsoft.AspNet.Mvc.Core/Logging/MvcRouteHandlerLoggerExtensions.cs +++ b/src/Microsoft.AspNet.Mvc.Core/Logging/MvcRouteHandlerLoggerExtensions.cs @@ -3,6 +3,7 @@ using System; using System.Collections.Generic; +using System.Diagnostics; using Microsoft.AspNet.Mvc.Abstractions; using Microsoft.Extensions.Logging; @@ -10,6 +11,8 @@ namespace Microsoft.AspNet.Mvc.Logging { internal static class MvcRouteHandlerLoggerExtensions { + private static readonly double TimestampToTicks = Stopwatch.Frequency / 10000000.0; + private static readonly Action _actionExecuting; private static readonly Action _actionExecuted; @@ -36,10 +39,16 @@ namespace Microsoft.AspNet.Mvc.Logging _actionExecuting(logger, action.DisplayName, null); } - public static void ExecutedAction(this ILogger logger, ActionDescriptor action, int startTicks) + public static void ExecutedAction(this ILogger logger, ActionDescriptor action, long startTimestamp) { - var elapsed = new TimeSpan(Environment.TickCount - startTicks); - _actionExecuted(logger, action.DisplayName, elapsed.TotalMilliseconds, null); + // Don't log if logging wasn't enabled at start of request as time will be wildly wrong. + if (startTimestamp != 0) + { + var currentTimestamp = Stopwatch.GetTimestamp(); + var elapsed = new TimeSpan((long)(TimestampToTicks * (currentTimestamp - startTimestamp))); + + _actionExecuted(logger, action.DisplayName, elapsed.TotalMilliseconds, null); + } } public static void NoActionsMatched(this ILogger logger) diff --git a/src/Microsoft.AspNet.Mvc.ViewFeatures/Logging/DefaultViewComponentInvokerLoggerExtensions.cs b/src/Microsoft.AspNet.Mvc.ViewFeatures/Logging/DefaultViewComponentInvokerLoggerExtensions.cs index e2280c19db..d19159523c 100644 --- a/src/Microsoft.AspNet.Mvc.ViewFeatures/Logging/DefaultViewComponentInvokerLoggerExtensions.cs +++ b/src/Microsoft.AspNet.Mvc.ViewFeatures/Logging/DefaultViewComponentInvokerLoggerExtensions.cs @@ -3,6 +3,7 @@ using System; using System.Collections.Generic; +using System.Diagnostics; using Microsoft.AspNet.Mvc.ViewComponents; using Microsoft.Extensions.Logging; @@ -10,6 +11,7 @@ namespace Microsoft.AspNet.Mvc.ViewFeatures.Logging { public static class DefaultViewComponentInvokerLoggerExtensions { + private static readonly double TimestampToTicks = Stopwatch.Frequency / 10000000.0; private static readonly string[] EmptyArguments = #if NET451 new string[0]; @@ -66,16 +68,22 @@ namespace Microsoft.AspNet.Mvc.ViewFeatures.Logging public static void ViewComponentExecuted( this ILogger logger, ViewComponentContext context, - int startTime, + long startTimestamp, object result) { - var elapsed = new TimeSpan(Environment.TickCount - startTime); - _viewComponentExecuted( - logger, - context.ViewComponentDescriptor.DisplayName, - elapsed.TotalMilliseconds, - Convert.ToString(result), - null); + // Don't log if logging wasn't enabled at start of request as time will be wildly wrong. + if (startTimestamp != 0) + { + var currentTimestamp = Stopwatch.GetTimestamp(); + var elapsed = new TimeSpan((long)(TimestampToTicks * (currentTimestamp - startTimestamp))); + + _viewComponentExecuted( + logger, + context.ViewComponentDescriptor.DisplayName, + elapsed.TotalMilliseconds, + Convert.ToString(result), + null); + } } private class ViewComponentLogScope : ILogValues diff --git a/src/Microsoft.AspNet.Mvc.ViewFeatures/ViewComponents/DefaultViewComponentInvoker.cs b/src/Microsoft.AspNet.Mvc.ViewFeatures/ViewComponents/DefaultViewComponentInvoker.cs index f0aad1a660..4a32265cd6 100644 --- a/src/Microsoft.AspNet.Mvc.ViewFeatures/ViewComponents/DefaultViewComponentInvoker.cs +++ b/src/Microsoft.AspNet.Mvc.ViewFeatures/ViewComponents/DefaultViewComponentInvoker.cs @@ -124,11 +124,11 @@ namespace Microsoft.AspNet.Mvc.ViewComponents _diagnosticSource.BeforeViewComponent(context, component); _logger.ViewComponentExecuting(context, arguments); - var startTime = Environment.TickCount; + var startTimestamp = _logger.IsEnabled(LogLevel.Debug) ? Stopwatch.GetTimestamp() : 0; var result = await ControllerActionExecutor.ExecuteAsync(method, component, arguments); var viewComponentResult = CoerceToViewComponentResult(result); - _logger.ViewComponentExecuted(context, startTime, viewComponentResult); + _logger.ViewComponentExecuted(context, startTimestamp, viewComponentResult); _diagnosticSource.AfterViewComponent(context, viewComponentResult, component); return viewComponentResult; @@ -149,7 +149,7 @@ namespace Microsoft.AspNet.Mvc.ViewComponents _diagnosticSource.BeforeViewComponent(context, component); _logger.ViewComponentExecuting(context, arguments); - var startTime = Environment.TickCount; + var startTimestamp = _logger.IsEnabled(LogLevel.Debug) ? Stopwatch.GetTimestamp() : 0; object result; try { @@ -164,7 +164,7 @@ namespace Microsoft.AspNet.Mvc.ViewComponents } var viewComponentResult = CoerceToViewComponentResult(result); - _logger.ViewComponentExecuted(context, startTime, viewComponentResult); + _logger.ViewComponentExecuted(context, startTimestamp, viewComponentResult); _diagnosticSource.AfterViewComponent(context, viewComponentResult, component); return viewComponentResult;