Add INFO level logging (#7314)

Addresses #7171

build/dependencies.props

@@ -70,6 +70,7 @@
     <MicrosoftExtensionsPropertyHelperSourcesPackageVersion>2.1.0-preview2-28169</MicrosoftExtensionsPropertyHelperSourcesPackageVersion>
     <MicrosoftExtensionsSecurityHelperSourcesPackageVersion>2.1.0-preview2-28169</MicrosoftExtensionsSecurityHelperSourcesPackageVersion>
     <MicrosoftExtensionsTypeNameHelperSourcesPackageVersion>2.1.0-preview2-28169</MicrosoftExtensionsTypeNameHelperSourcesPackageVersion>
+    <MicrosoftExtensionsValueStopwatchSourcesPackageVersion>2.1.0-preview2-28169</MicrosoftExtensionsValueStopwatchSourcesPackageVersion>
     <MicrosoftExtensionsWebEncodersPackageVersion>2.1.0-preview2-28169</MicrosoftExtensionsWebEncodersPackageVersion>
     <MicrosoftNETCoreApp20PackageVersion>2.0.0</MicrosoftNETCoreApp20PackageVersion>
     <MicrosoftNETCoreApp21PackageVersion>2.1.0-preview1-26122-01</MicrosoftNETCoreApp21PackageVersion>

src/Microsoft.AspNetCore.Mvc.Core/Internal/ControllerActionInvoker.cs

@@ -346,7 +346,7 @@ namespace Microsoft.AspNetCore.Mvc.Internal
                     arguments,
                     controller);
                 logger.ActionMethodExecuting(controllerContext, orderedArguments);
-
+                var stopwatch = ValueStopwatch.StartNew();
                 var actionResultValueTask = actionMethodExecutor.Execute(objectMethodExecutor, controller, orderedArguments);
                 if (actionResultValueTask.IsCompletedSuccessfully)
                 {
@@ -358,7 +358,7 @@ namespace Microsoft.AspNetCore.Mvc.Internal
                 }
 
                 _result = result;
-                logger.ActionMethodExecuted(controllerContext, result);
+                logger.ActionMethodExecuted(controllerContext, result, stopwatch.GetElapsedTime());
             }
             finally
             {

src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreLoggerExtensions.cs

@@ -8,6 +8,7 @@ using System.Diagnostics;
 using System.Linq;
 using System.Reflection;
 using System.Security.Claims;
+using System.Text;
 using Microsoft.AspNetCore.Mvc.Abstractions;
 using Microsoft.AspNetCore.Mvc.ActionConstraints;
 using Microsoft.AspNetCore.Mvc.ApplicationModels;
@@ -29,15 +30,16 @@ namespace Microsoft.AspNetCore.Mvc.Internal
 
         private static readonly double TimestampToTicks = TimeSpan.TicksPerSecond / (double)Stopwatch.Frequency;
 
-        private static readonly Action<ILogger, string, Exception> _actionExecuting;
+        private static readonly Action<ILogger, string, string, Exception> _actionExecuting;
         private static readonly Action<ILogger, string, double, Exception> _actionExecuted;
 
         private static readonly Action<ILogger, string[], Exception> _challengeResultExecuting;
 
         private static readonly Action<ILogger, string, Exception> _contentResultExecuting;
 
-        private static readonly Action<ILogger, string, string[], ModelValidationState, Exception> _actionMethodExecuting;
+        private static readonly Action<ILogger, string, ModelValidationState, Exception> _actionMethodExecuting;
-        private static readonly Action<ILogger, string, string, Exception> _actionMethodExecuted;
+        private static readonly Action<ILogger, string, string[], ModelValidationState, Exception> _actionMethodExecutingWithArguments;
+        private static readonly Action<ILogger, string, string, double, Exception> _actionMethodExecuted;
 
         private static readonly Action<ILogger, string, string[], Exception> _logFilterExecutionPlan;
         private static readonly Action<ILogger, string, string, Type, Exception> _beforeExecutingMethodOnFilter;
@@ -143,10 +145,10 @@ namespace Microsoft.AspNetCore.Mvc.Internal
 
         static MvcCoreLoggerExtensions()
         {
-            _actionExecuting = LoggerMessage.Define<string>(
+            _actionExecuting = LoggerMessage.Define<string, string>(
-                LogLevel.Debug,
+                LogLevel.Information,
                 1,
-                "Executing action {ActionName}");
+                "Route matched with {RouteData}. Executing action {ActionName}");
 
             _actionExecuted = LoggerMessage.Define<string, double>(
                 LogLevel.Information,
@@ -163,15 +165,20 @@ namespace Microsoft.AspNetCore.Mvc.Internal
                 1,
                 "Executing ContentResult with HTTP Response ContentType of {ContentType}");
 
-            _actionMethodExecuting = LoggerMessage.Define<string, string[], ModelValidationState>(
+            _actionMethodExecuting = LoggerMessage.Define<string, ModelValidationState>(
                 LogLevel.Information,
                 1,
-                "Executing action method {ActionName} with arguments ({Arguments}) - ModelState is {ValidationState}");
+                "Executing action method {ActionName} - Validation state: {ValidationState}");
 
-            _actionMethodExecuted = LoggerMessage.Define<string, string>(
+            _actionMethodExecutingWithArguments = LoggerMessage.Define<string, string[], ModelValidationState>(
-                LogLevel.Debug,
+                LogLevel.Information,
+                1,
+                "Executing action method {ActionName} with arguments ({Arguments}) - Validation state: {ValidationState}");
+
+            _actionMethodExecuted = LoggerMessage.Define<string, string, double>(
+                LogLevel.Information,
                 2,
-                "Executed action method {ActionName}, returned result {ActionResult}.");
+                "Executed action method {ActionName}, returned result {ActionResult} in {ElapsedMilliseconds}ms.");
 
             _logFilterExecutionPlan = LoggerMessage.Define<string, string[]>(
                 LogLevel.Debug,
@@ -645,7 +652,26 @@ namespace Microsoft.AspNetCore.Mvc.Internal
 
         public static void ExecutingAction(this ILogger logger, ActionDescriptor action)
         {
-            _actionExecuting(logger, action.DisplayName, null);
+            if (logger.IsEnabled(LogLevel.Information))
+            {
+                var routeKeys = action.RouteValues.Keys.ToArray();
+                var routeValues = action.RouteValues.Values.ToArray();
+                var stringBuilder = new StringBuilder();
+                stringBuilder.Append("{");
+                for (var i = 0; i < routeValues.Length; i++)
+                {
+                    if (i == routeValues.Length - 1)
+                    {
+                        stringBuilder.Append($"{routeKeys[i]} = \"{routeValues[i]}\"}}");
+                    }
+                    else
+                    {
+                        stringBuilder.Append($"{routeKeys[i]} = \"{routeValues[i]}\", ");
+                    }
+                }
+
+                _actionExecuting(logger, stringBuilder.ToString(), action.DisplayName, null);
+            }
         }
 
         public static void AuthorizationFiltersExecutionPlan(this ILogger logger, IEnumerable<IFilterMetadata> filters)
@@ -721,18 +747,12 @@ namespace Microsoft.AspNetCore.Mvc.Internal
             _afterExecutingMethodOnFilter(logger, filterType, methodName, filter.GetType(), null);
         }
 
-        public static void ExecutedAction(this ILogger logger, ActionDescriptor action, long startTimestamp)
+        public static void ExecutedAction(this ILogger logger, ActionDescriptor action, TimeSpan timeSpan)
         {
             // Don't log if logging wasn't enabled at start of request as time will be wildly wrong.
             if (logger.IsEnabled(LogLevel.Information))
             {
-                if (startTimestamp != 0)
+                _actionExecuted(logger, action.DisplayName, timeSpan.TotalMilliseconds, null);
-                {
-                    var currentTimestamp = Stopwatch.GetTimestamp();
-                    var elapsed = new TimeSpan((long)(TimestampToTicks * (currentTimestamp - startTimestamp)));
-
-                    _actionExecuted(logger, action.DisplayName, elapsed.TotalMilliseconds, null);
-                }
             }
         }
 
@@ -780,10 +800,12 @@ namespace Microsoft.AspNetCore.Mvc.Internal
             {
                 var actionName = context.ActionDescriptor.DisplayName;
 
+                var validationState = context.ModelState.ValidationState;
+
                 string[] convertedArguments;
                 if (arguments == null)
                 {
-                    convertedArguments = null;
+                    _actionMethodExecuting(logger, actionName, validationState, null);
                 }
                 else
                 {
@@ -792,20 +814,18 @@ namespace Microsoft.AspNetCore.Mvc.Internal
                     {
                         convertedArguments[i] = Convert.ToString(arguments[i]);
                     }
+
+                    _actionMethodExecutingWithArguments(logger, actionName, convertedArguments, validationState, null);
                 }
-
-                var validationState = context.ModelState.ValidationState;
-
-                _actionMethodExecuting(logger, actionName, convertedArguments, validationState, null);
             }
         }
 
-        public static void ActionMethodExecuted(this ILogger logger, ControllerContext context, IActionResult result)
+        public static void ActionMethodExecuted(this ILogger logger, ControllerContext context, IActionResult result, TimeSpan timeSpan)
         {
-            if (logger.IsEnabled(LogLevel.Debug))
+            if (logger.IsEnabled(LogLevel.Information))
             {
                 var actionName = context.ActionDescriptor.DisplayName;
-                _actionMethodExecuted(logger, actionName, Convert.ToString(result), null);
+                _actionMethodExecuted(logger, actionName, Convert.ToString(result), timeSpan.TotalMilliseconds, null);
             }
         }
 

src/Microsoft.AspNetCore.Mvc.Core/Internal/ResourceInvoker.cs

@@ -9,6 +9,7 @@ using System.Threading.Tasks;
 using Microsoft.AspNetCore.Mvc.Core;
 using Microsoft.AspNetCore.Mvc.Filters;
 using Microsoft.AspNetCore.Mvc.ModelBinding;
+using Microsoft.Extensions.Internal;
 using Microsoft.Extensions.Logging;
 
 namespace Microsoft.AspNetCore.Mvc.Internal
@@ -69,7 +70,7 @@ namespace Microsoft.AspNetCore.Mvc.Internal
                     _logger.ExceptionFiltersExecutionPlan(_filters);
                     _logger.ResultFiltersExecutionPlan(_filters);
 
-                    var startTimestamp = _logger.IsEnabled(LogLevel.Information) ? Stopwatch.GetTimestamp() : 0;
+                    var stopwatch = ValueStopwatch.StartNew();
 
                     try
                     {
@@ -78,7 +79,7 @@ namespace Microsoft.AspNetCore.Mvc.Internal
                     finally
                     {
                         ReleaseResources();
-                        _logger.ExecutedAction(_actionContext.ActionDescriptor, startTimestamp);
+                        _logger.ExecutedAction(_actionContext.ActionDescriptor, stopwatch.GetElapsedTime());
                     }
                 }
             }

src/Microsoft.AspNetCore.Mvc.Core/Microsoft.AspNetCore.Mvc.Core.csproj

@@ -38,6 +38,7 @@ Microsoft.AspNetCore.Mvc.RouteAttribute</Description>
     <PackageReference Include="Microsoft.Extensions.PropertyHelper.Sources" PrivateAssets="All" Version="$(MicrosoftExtensionsPropertyHelperSourcesPackageVersion)" />
     <PackageReference Include="Microsoft.Extensions.SecurityHelper.Sources" PrivateAssets="All" Version="$(MicrosoftExtensionsSecurityHelperSourcesPackageVersion)" />
     <PackageReference Include="Microsoft.Extensions.TypeNameHelper.Sources" PrivateAssets="All" Version="$(MicrosoftExtensionsTypeNameHelperSourcesPackageVersion)" />
+    <PackageReference Include="Microsoft.Extensions.ValueStopwatch.Sources" PrivateAssets="All" Version="$(MicrosoftExtensionsValueStopwatchSourcesPackageVersion)" />
     <PackageReference Include="System.Diagnostics.DiagnosticSource" Version="$(SystemDiagnosticsDiagnosticSourcePackageVersion)" />
     <PackageReference Include="System.Threading.Tasks.Extensions" Version="$(SystemThreadingTasksExtensionsPackageVersion)" />
   </ItemGroup>

src/Microsoft.AspNetCore.Mvc.ViewFeatures/Internal/MvcViewFeaturesLoggerExtensions.cs

@@ -18,16 +18,18 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures.Internal
         private static readonly Action<ILogger, string, string[], Exception> _viewComponentExecuting;
         private static readonly Action<ILogger, string, double, string, Exception> _viewComponentExecuted;
 
-        private static readonly Action<ILogger, string, Exception> _partialViewFound;
+        private static readonly Action<ILogger, string, double, Exception> _partialViewFound;
         private static readonly Action<ILogger, string, IEnumerable<string>, Exception> _partialViewNotFound;
         private static readonly Action<ILogger, string, Exception> _partialViewResultExecuting;
+        private static readonly Action<ILogger, string, double, Exception> _partialViewResultExecuted;
 
         private static readonly Action<ILogger, string, Exception> _antiforgeryTokenInvalid;
 
         private static readonly Action<ILogger, string, Exception> _viewComponentResultExecuting;
 
         private static readonly Action<ILogger, string, Exception> _viewResultExecuting;
-        private static readonly Action<ILogger, string, Exception> _viewFound;
+        private static readonly Action<ILogger, string, double, Exception> _viewResultExecuted;
+        private static readonly Action<ILogger, string, double, Exception> _viewFound;
         private static readonly Action<ILogger, string, IEnumerable<string>, Exception> _viewNotFound;
 
         private static readonly Action<ILogger, string, Exception> _tempDataCookieNotFound;
@@ -52,18 +54,23 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures.Internal
             _partialViewResultExecuting = LoggerMessage.Define<string>(
                 LogLevel.Information,
                 1,
-                "Executing PartialViewResult, running view at path {Path}.");
+                "Executing PartialViewResult, running view {PartialViewName}.");
 
-            _partialViewFound = LoggerMessage.Define<string>(
+            _partialViewFound = LoggerMessage.Define<string, double>(
                 LogLevel.Debug,
                 2,
-                "The partial view '{PartialViewName}' was found.");
+                "The partial view path '{PartialViewFilePath}' was found in {ElapsedMilliseconds}ms.");
 
             _partialViewNotFound = LoggerMessage.Define<string, IEnumerable<string>>(
                 LogLevel.Error,
                 3,
                 "The partial view '{PartialViewName}' was not found. Searched locations: {SearchedViewLocations}");
 
+            _partialViewResultExecuted = LoggerMessage.Define<string, double>(
+                LogLevel.Information,
+                4,
+                "Executed PartialViewResult - view {PartialViewName} executed in {ElapsedMilliseconds}ms.");
+
             _antiforgeryTokenInvalid = LoggerMessage.Define<string>(
                 LogLevel.Information,
                 1,
@@ -77,18 +84,23 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures.Internal
             _viewResultExecuting = LoggerMessage.Define<string>(
                 LogLevel.Information,
                 1,
-                "Executing ViewResult, running view at path {Path}.");
+                "Executing ViewResult, running view {ViewName}.");
 
-            _viewFound = LoggerMessage.Define<string>(
+            _viewFound = LoggerMessage.Define<string, double>(
                 LogLevel.Debug,
                 2,
-                "The view '{ViewName}' was found.");
+                "The view path '{ViewFilePath}' was found in {ElapsedMilliseconds}ms.");
 
             _viewNotFound = LoggerMessage.Define<string, IEnumerable<string>>(
                 LogLevel.Error,
                 3,
                 "The view '{ViewName}' was not found. Searched locations: {SearchedViewLocations}");
 
+            _viewResultExecuted = LoggerMessage.Define<string, double>(
+                LogLevel.Information,
+                4,
+                "Executed ViewResult - view {ViewName} executed in {ElapsedMilliseconds}ms.");
+
             _tempDataCookieNotFound = LoggerMessage.Define<string>(
                 LogLevel.Debug,
                 1,
@@ -143,29 +155,24 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures.Internal
         public static void ViewComponentExecuted(
             this ILogger logger,
             ViewComponentContext context,
-            long startTimestamp,
+            TimeSpan timespan,
             object result)
         {
             // Don't log if logging wasn't enabled at start of request as time will be wildly wrong.
-            if (startTimestamp != 0)
+            _viewComponentExecuted(
-            {
+                logger,
-                var currentTimestamp = Stopwatch.GetTimestamp();
+                context.ViewComponentDescriptor.DisplayName,
-                var elapsed = new TimeSpan((long)(TimestampToTicks * (currentTimestamp - startTimestamp)));
+                timespan.TotalMilliseconds,
-
+                Convert.ToString(result),
-                _viewComponentExecuted(
+                null);
-                    logger,
-                    context.ViewComponentDescriptor.DisplayName,
-                    elapsed.TotalMilliseconds,
-                    Convert.ToString(result),
-                    null);
-            }
         }
 
         public static void PartialViewFound(
             this ILogger logger,
-            string partialViewName)
+            IView view,
+            TimeSpan timespan)
         {
-            _partialViewFound(logger, partialViewName, null);
+            _partialViewFound(logger, view.Path, timespan.TotalMilliseconds, null);
         }
 
         public static void PartialViewNotFound(
@@ -176,9 +183,14 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures.Internal
             _partialViewNotFound(logger, partialViewName, searchedLocations, null);
         }
 
-        public static void PartialViewResultExecuting(this ILogger logger, IView view)
+        public static void PartialViewResultExecuting(this ILogger logger, string partialViewName)
         {
-            _partialViewResultExecuting(logger, view.Path, null);
+            _partialViewResultExecuting(logger, partialViewName, null);
+        }
+
+        public static void PartialViewResultExecuted(this ILogger logger, string partialViewName, TimeSpan timespan)
+        {
+            _partialViewResultExecuted(logger, partialViewName, timespan.TotalMilliseconds, null);
         }
 
         public static void AntiforgeryTokenInvalid(this ILogger logger, string message, Exception exception)
@@ -202,14 +214,19 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures.Internal
             }
         }
 
-        public static void ViewResultExecuting(this ILogger logger, IView view)
+        public static void ViewResultExecuting(this ILogger logger, string viewName)
         {
-            _viewResultExecuting(logger, view.Path, null);
+            _viewResultExecuting(logger, viewName, null);
         }
 
-        public static void ViewFound(this ILogger logger, string viewName)
+        public static void ViewResultExecuted(this ILogger logger, string viewName, TimeSpan timespan)
         {
-            _viewFound(logger, viewName, null);
+            _viewResultExecuted(logger, viewName, timespan.TotalMilliseconds, null);
+        }
+
+        public static void ViewFound(this ILogger logger, IView view, TimeSpan timespan)
+        {
+            _viewFound(logger, view.Path, timespan.TotalMilliseconds, null);
         }
 
         public static void ViewNotFound(this ILogger logger, string viewName,

src/Microsoft.AspNetCore.Mvc.ViewFeatures/Microsoft.AspNetCore.Mvc.ViewFeatures.csproj

@@ -28,6 +28,7 @@ Microsoft.AspNetCore.Mvc.ViewComponent</Description>
     <PackageReference Include="Microsoft.Extensions.HashCodeCombiner.Sources" PrivateAssets="All" Version="$(MicrosoftExtensionsHashCodeCombinerSourcesPackageVersion)" />
     <PackageReference Include="Microsoft.Extensions.PropertyActivator.Sources" PrivateAssets="All" Version="$(MicrosoftExtensionsPropertyActivatorSourcesPackageVersion)" />
     <PackageReference Include="Microsoft.Extensions.PropertyHelper.Sources" PrivateAssets="All" Version="$(MicrosoftExtensionsPropertyHelperSourcesPackageVersion)" />
+    <PackageReference Include="Microsoft.Extensions.ValueStopwatch.Sources" PrivateAssets="All" Version="$(MicrosoftExtensionsValueStopwatchSourcesPackageVersion)" />
     <PackageReference Include="Microsoft.Extensions.WebEncoders" Version="$(MicrosoftExtensionsWebEncodersPackageVersion)" />
     <PackageReference Include="Newtonsoft.Json.Bson" Version="$(NewtonsoftJsonBsonPackageVersion)" />
   </ItemGroup>

src/Microsoft.AspNetCore.Mvc.ViewFeatures/ViewComponents/DefaultViewComponentInvoker.cs

@@ -105,7 +105,7 @@ namespace Microsoft.AspNetCore.Mvc.ViewComponents
                 _diagnosticSource.BeforeViewComponent(context, component);
                 _logger.ViewComponentExecuting(context, arguments);
 
-                var startTimestamp = _logger.IsEnabled(LogLevel.Debug) ? Stopwatch.GetTimestamp() : 0;
+                var stopwatch = ValueStopwatch.StartNew();
 
                 object resultAsObject;
                 var returnType = executor.MethodReturnType;
@@ -128,7 +128,7 @@ namespace Microsoft.AspNetCore.Mvc.ViewComponents
                 }
 
                 var viewComponentResult = CoerceToViewComponentResult(resultAsObject);
-                _logger.ViewComponentExecuted(context, startTimestamp, viewComponentResult);
+                _logger.ViewComponentExecuted(context, stopwatch.GetElapsedTime(), viewComponentResult);
                 _diagnosticSource.AfterViewComponent(context, viewComponentResult, component);
 
                 _viewComponentFactory.ReleaseViewComponent(context, component);
@@ -148,7 +148,7 @@ namespace Microsoft.AspNetCore.Mvc.ViewComponents
                 _diagnosticSource.BeforeViewComponent(context, component);
                 _logger.ViewComponentExecuting(context, arguments);
 
-                var startTimestamp = _logger.IsEnabled(LogLevel.Debug) ? Stopwatch.GetTimestamp() : 0;
+                var stopwatch = ValueStopwatch.StartNew();
                 object result;
 
                 try
@@ -161,7 +161,7 @@ namespace Microsoft.AspNetCore.Mvc.ViewComponents
                 }
 
                 var viewComponentResult = CoerceToViewComponentResult(result);
-                _logger.ViewComponentExecuted(context, startTimestamp, viewComponentResult);
+                _logger.ViewComponentExecuted(context, stopwatch.GetElapsedTime(), viewComponentResult);
                 _diagnosticSource.AfterViewComponent(context, viewComponentResult, component);
 
                 _viewComponentFactory.ReleaseViewComponent(context, component);

src/Microsoft.AspNetCore.Mvc.ViewFeatures/ViewFeatures/PartialViewResultExecutor.cs

@@ -7,10 +7,10 @@ using System.Diagnostics;
 using System.Linq;
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Mvc.Infrastructure;
-using Microsoft.AspNetCore.Mvc.Internal;
 using Microsoft.AspNetCore.Mvc.ModelBinding;
 using Microsoft.AspNetCore.Mvc.ViewEngines;
 using Microsoft.AspNetCore.Mvc.ViewFeatures.Internal;
+using Microsoft.Extensions.Internal;
 using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
 
@@ -77,6 +77,8 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures
             var viewEngine = viewResult.ViewEngine ?? ViewEngine;
             var viewName = viewResult.ViewName ?? GetActionName(actionContext);
 
+            var stopwatch = ValueStopwatch.StartNew();
+
             var result = viewEngine.GetView(executingFilePath: null, viewPath: viewName, isMainPage: false);
             var originalResult = result;
             if (!result.Success)
@@ -84,6 +86,7 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures
                 result = viewEngine.FindView(actionContext, viewName, isMainPage: false);
             }
 
+            Logger.PartialViewResultExecuting(result.ViewName);
             if (!result.Success)
             {
                 if (originalResult.SearchedLocations.Any())
@@ -112,7 +115,7 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures
                     viewName: viewName,
                     view: result.View);
 
-                Logger.PartialViewFound(viewName);
+                Logger.PartialViewFound(result.View, stopwatch.GetElapsedTime());
             }
             else
             {
@@ -153,8 +156,6 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures
                 throw new ArgumentNullException(nameof(viewResult));
             }
 
-            Logger.PartialViewResultExecuting(view);
-
             return ExecuteAsync(
                 actionContext,
                 view,
@@ -177,6 +178,8 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures
                 throw new ArgumentNullException(nameof(result));
             }
 
+            var stopwatch = ValueStopwatch.StartNew();
+
             var viewEngineResult = FindView(context, result);
             viewEngineResult.EnsureSuccessful(originalLocations: null);
 
@@ -185,6 +188,8 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures
             {
                 await ExecuteAsync(context, view, result);
             }
+
+            Logger.PartialViewResultExecuted(result.ViewName, stopwatch.GetElapsedTime());
         }
 
         private static string GetActionName(ActionContext context)

src/Microsoft.AspNetCore.Mvc.ViewFeatures/ViewFeatures/ViewResultExecutor.cs

@@ -7,10 +7,10 @@ using System.Diagnostics;
 using System.Linq;
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Mvc.Infrastructure;
-using Microsoft.AspNetCore.Mvc.Internal;
 using Microsoft.AspNetCore.Mvc.ModelBinding;
 using Microsoft.AspNetCore.Mvc.ViewEngines;
 using Microsoft.AspNetCore.Mvc.ViewFeatures.Internal;
+using Microsoft.Extensions.Internal;
 using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
 
@@ -78,6 +78,8 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures
 
             var viewName = viewResult.ViewName ?? GetActionName(actionContext);
 
+            var stopwatch = ValueStopwatch.StartNew();
+
             var result = viewEngine.GetView(executingFilePath: null, viewPath: viewName, isMainPage: true);
             var originalResult = result;
             if (!result.Success)
@@ -85,6 +87,7 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures
                 result = viewEngine.FindView(actionContext, viewName, isMainPage: true);
             }
 
+            Logger.ViewResultExecuting(result.ViewName);
             if (!result.Success)
             {
                 if (originalResult.SearchedLocations.Any())
@@ -120,7 +123,7 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures
                         });
                 }
 
-                Logger.ViewFound(viewName);
+                Logger.ViewFound(result.View, stopwatch.GetElapsedTime());
             }
             else
             {
@@ -156,13 +159,14 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures
                 throw new ArgumentNullException(nameof(result));
             }
 
+            var stopwatch = ValueStopwatch.StartNew();
+
             var viewEngineResult = FindView(context, result);
             viewEngineResult.EnsureSuccessful(originalLocations: null);
 
             var view = viewEngineResult.View;
             using (view as IDisposable)
             {
-                Logger.ViewResultExecuting(view);
 
                 await ExecuteAsync(
                     context,
@@ -172,6 +176,8 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures
                     result.ContentType,
                     result.StatusCode);
             }
+
+            Logger.ViewResultExecuted(viewEngineResult.ViewName, stopwatch.GetElapsedTime());
         }
 
         private static string GetActionName(ActionContext context)