Correct and more accurate timestamp

As per https://github.com/aspnet/Hosting/pull/543
Resolves  #3849

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

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<ILogger, string, Exception> _actionExecuting;
         private static readonly Action<ILogger, string, double, Exception> _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);
+            // Don't log if logging wasn't enabled at start of request as time will be wildly wrong.
-            _actionExecuted(logger, action.DisplayName, elapsed.TotalMilliseconds, null);
+            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)

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);
+            // Don't log if logging wasn't enabled at start of request as time will be wildly wrong.
-            _viewComponentExecuted(
+            if (startTimestamp != 0)
-                logger,
+            {
-                context.ViewComponentDescriptor.DisplayName,
+                var currentTimestamp = Stopwatch.GetTimestamp();
-                elapsed.TotalMilliseconds,
+                var elapsed = new TimeSpan((long)(TimestampToTicks * (currentTimestamp - startTimestamp)));
-                Convert.ToString(result),
+
-                null);
+                _viewComponentExecuted(
+                    logger,
+                    context.ViewComponentDescriptor.DisplayName,
+                    elapsed.TotalMilliseconds,
+                    Convert.ToString(result),
+                    null);
+            }
         }
 
         private class ViewComponentLogScope : ILogValues

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;