Correct and more accurate timestamp

As per aspnet/Hosting#543 Resolves aspnet#3849
benaadams · Jan 1, 2016 · a591797 · a591797
1 parent ba5fe60
commit a591797
Show file tree

Hide file tree

Showing 4 changed files with 42 additions and 17 deletions.
diff --git a/src/Microsoft.AspNet.Mvc.Core/Infrastructure/MvcRouteHandler.cs b/src/Microsoft.AspNet.Mvc.Core/Infrastructure/MvcRouteHandler.cs
@@ -87,7 +87,7 @@ private async Task InvokeActionAsync(HttpContext httpContext, ActionDescriptor a
                 {
                     _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 @@ private async Task InvokeActionAsync(HttpContext httpContext, ActionDescriptor a
 
                     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
@@ -3,13 +3,16 @@
 
 using System;
 using System.Collections.Generic;
+using System.Diagnostics;
 using Microsoft.AspNet.Mvc.Abstractions;
 using Microsoft.Extensions.Logging;
 
 namespace Microsoft.AspNet.Mvc.Logging
 {
     internal static class MvcRouteHandlerLoggerExtensions
     {
+        private static readonly double TimestampToTicks = Stopwatch.Frequency / 10000000.0;
+
         private static readonly Action<ILogger, string, Exception> _actionExecuting;
         private static readonly Action<ILogger, string, double, Exception> _actionExecuted;
 
@@ -36,10 +39,20 @@ public static void ExecutingAction(this ILogger logger, ActionDescriptor action)
             _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 (logger.IsEnabled(LogLevel.Information) && startTimestamp != 0)
+            {
+                var currentTimestamp = Stopwatch.GetTimestamp();
+
+                // Calculate taking into account timestamp wrapping
+                var elapsed = new TimeSpan((long)(TimestampToTicks * (currentTimestamp < startTimestamp ?
+                        (long.MaxValue - startTimestamp) + (currentTimestamp - long.MinValue) :
+                        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
@@ -3,13 +3,15 @@
 
 using System;
 using System.Collections.Generic;
+using System.Diagnostics;
 using Microsoft.AspNet.Mvc.ViewComponents;
 using Microsoft.Extensions.Logging;
 
 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,26 @@ private static string[] GetFormattedArguments(object[] arguments)
         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 (logger.IsEnabled(LogLevel.Debug) && startTimestamp != 0)
+            {
+                var currentTimestamp = Stopwatch.GetTimestamp();
+
+                // Calculate taking into account timestamp wrapping
+                var elapsed = new TimeSpan((long)(TimestampToTicks * (currentTimestamp < startTimestamp ?
+                        (long.MaxValue - startTimestamp) + (currentTimestamp - long.MinValue) :
+                        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
@@ -124,11 +124,11 @@ private async Task<IViewComponentResult> InvokeAsyncCore(ViewComponentContext co
                 _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 @@ private IViewComponentResult InvokeSyncCore(ViewComponentContext context)
                 _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 @@ private IViewComponentResult InvokeSyncCore(ViewComponentContext context)
                 }
 
                 var viewComponentResult = CoerceToViewComponentResult(result);
-                _logger.ViewComponentExecuted(context, startTime, viewComponentResult);
+                _logger.ViewComponentExecuted(context, startTimestamp, viewComponentResult);
                 _diagnosticSource.AfterViewComponent(context, viewComponentResult, component);
 
                 return viewComponentResult;