From ec2abc8ae0a6f54cc56f9a681046fb79b7c9f8a0 Mon Sep 17 00:00:00 2001
From: Ryan Nowak <nowakra@gmail.com>
Date: Thu, 22 Oct 2015 16:26:48 -0700
Subject: [PATCH] Add logging of elapsed time for the action.

---
 .../Infrastructure/MvcRouteHandler.cs         |  7 ++--
 .../MvcRouteHandlerLoggerExtensions.cs        | 32 +++++++++++++++++++
 .../Infrastructure/MvcRouteHandlerTests.cs    | 18 +++++++----
 3 files changed, 49 insertions(+), 8 deletions(-)

diff --git a/src/Microsoft.AspNet.Mvc.Core/Infrastructure/MvcRouteHandler.cs b/src/Microsoft.AspNet.Mvc.Core/Infrastructure/MvcRouteHandler.cs
index a94d0ef719..0ad69d3d2d 100644
--- a/src/Microsoft.AspNet.Mvc.Core/Infrastructure/MvcRouteHandler.cs
+++ b/src/Microsoft.AspNet.Mvc.Core/Infrastructure/MvcRouteHandler.cs
@@ -59,7 +59,7 @@ namespace Microsoft.AspNet.Mvc.Infrastructure
             var actionDescriptor = await _actionSelector.SelectAsync(context);
             if (actionDescriptor == null)
             {
-                _logger.LogVerbose("No actions matched the current request.");
+                _logger.NoActionsMatched();
                 return;
             }
 
@@ -90,10 +90,13 @@ namespace Microsoft.AspNet.Mvc.Infrastructure
 
                 using (_logger.ActionScope(actionDescriptor))
                 {
-                    _logger.LogVerbose("Executing action {ActionDisplayName}", actionDescriptor.DisplayName);
+                    _logger.ExecutingAction(actionDescriptor);
 
+                    var startTime = Environment.TickCount;
                     await InvokeActionAsync(context, actionDescriptor);
                     context.IsHandled = true;
+
+                    _logger.ExecutedAction(actionDescriptor, startTime);
                 }
             }
             finally
diff --git a/src/Microsoft.AspNet.Mvc.Core/Logging/MvcRouteHandlerLoggerExtensions.cs b/src/Microsoft.AspNet.Mvc.Core/Logging/MvcRouteHandlerLoggerExtensions.cs
index 35ac249513..f6a3fee07f 100644
--- a/src/Microsoft.AspNet.Mvc.Core/Logging/MvcRouteHandlerLoggerExtensions.cs
+++ b/src/Microsoft.AspNet.Mvc.Core/Logging/MvcRouteHandlerLoggerExtensions.cs
@@ -10,11 +10,43 @@ namespace Microsoft.AspNet.Mvc.Logging
 {
     internal static class MvcRouteHandlerLoggerExtensions
     {
+        private static Action<ILogger, string, Exception> _actionExecuting;
+        private static Action<ILogger, string, double, Exception> _actionExecuted;
+
+        static MvcRouteHandlerLoggerExtensions()
+        {
+            _actionExecuting = LoggerMessage.Define<string>(
+                LogLevel.Verbose,
+                1,
+                "Executing action {ActionName}");
+
+            _actionExecuted = LoggerMessage.Define<string, double>(
+                LogLevel.Information,
+                2,
+                "Executed action {ActionName} in {ElapsedMilliseconds}ms");
+        }
+
         public static IDisposable ActionScope(this ILogger logger, ActionDescriptor action)
         {
             return logger.BeginScopeImpl(new ActionLogScope(action));
         }
 
+        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)
+        {
+            var elapsed = new TimeSpan(Environment.TickCount - startTicks);
+            _actionExecuted(logger, action.DisplayName, elapsed.TotalMilliseconds, null);
+        }
+
+        public static void NoActionsMatched(this ILogger logger)
+        {
+            logger.LogVerbose(3, "No actions matched the current request");
+        }
+
         private class ActionLogScope : ILogValues
         {
             private readonly ActionDescriptor _action;
diff --git a/test/Microsoft.AspNet.Mvc.Core.Test/Infrastructure/MvcRouteHandlerTests.cs b/test/Microsoft.AspNet.Mvc.Core.Test/Infrastructure/MvcRouteHandlerTests.cs
index ec55496f83..21e730a109 100644
--- a/test/Microsoft.AspNet.Mvc.Core.Test/Infrastructure/MvcRouteHandlerTests.cs
+++ b/test/Microsoft.AspNet.Mvc.Core.Test/Infrastructure/MvcRouteHandlerTests.cs
@@ -25,13 +25,16 @@ namespace Microsoft.AspNet.Mvc.Infrastructure
             // Arrange
             var sink = new TestSink();
             var loggerFactory = new TestLoggerFactory(sink, enabled: true);
+
             var displayName = "A.B.C";
             var actionDescriptor = new Mock<ActionDescriptor>();
-            actionDescriptor.SetupGet(ad => ad.DisplayName)
-                            .Returns(displayName);
+            actionDescriptor
+                .SetupGet(ad => ad.DisplayName)
+                .Returns(displayName);
+
             var context = CreateRouteContext(actionDescriptor: actionDescriptor.Object, loggerFactory: loggerFactory);
+
             var handler = new MvcRouteHandler();
-            var expectedMessage = $"Executing action {displayName}";
 
             // Act
             await handler.RouteAsync(context);
@@ -39,8 +42,11 @@ namespace Microsoft.AspNet.Mvc.Infrastructure
             // Assert
             Assert.Single(sink.Scopes);
             Assert.Equal(displayName, sink.Scopes[0].Scope?.ToString());
-            Assert.Single(sink.Writes);
-            Assert.Equal(expectedMessage, sink.Writes[0].State?.ToString());
+
+            Assert.Equal(2, sink.Writes.Count);
+            Assert.Equal($"Executing action {displayName}", sink.Writes[0].State?.ToString());
+            // This message has the execution time embedded, which we don't want to verify.
+            Assert.StartsWith($"Executed action {displayName} ", sink.Writes[1].State?.ToString());
         }
 
         [Fact]
@@ -59,7 +65,7 @@ namespace Microsoft.AspNet.Mvc.Infrastructure
                 loggerFactory: loggerFactory);
 
             var handler = new MvcRouteHandler();
-            var expectedMessage = "No actions matched the current request.";
+            var expectedMessage = "No actions matched the current request";
 
             // Act
             await handler.RouteAsync(context);