diff --git a/build/dependencies.props b/build/dependencies.props index d1b7c91209..e4237af6a9 100644 --- a/build/dependencies.props +++ b/build/dependencies.props @@ -70,6 +70,7 @@ 2.1.0-preview2-28169 2.1.0-preview2-28169 2.1.0-preview2-28169 + 2.1.0-preview2-28169 2.1.0-preview2-28169 2.0.0 2.1.0-preview1-26122-01 diff --git a/src/Microsoft.AspNetCore.Mvc.Core/Internal/ControllerActionInvoker.cs b/src/Microsoft.AspNetCore.Mvc.Core/Internal/ControllerActionInvoker.cs index 3dd9a5c339..b068cdd6da 100644 --- a/src/Microsoft.AspNetCore.Mvc.Core/Internal/ControllerActionInvoker.cs +++ b/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 { diff --git a/src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreLoggerExtensions.cs b/src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreLoggerExtensions.cs index 54162d0b2c..8fe2fe37b5 100644 --- a/src/Microsoft.AspNetCore.Mvc.Core/Internal/MvcCoreLoggerExtensions.cs +++ b/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 _actionExecuting; + private static readonly Action _actionExecuting; private static readonly Action _actionExecuted; private static readonly Action _challengeResultExecuting; private static readonly Action _contentResultExecuting; - private static readonly Action _actionMethodExecuting; - private static readonly Action _actionMethodExecuted; + private static readonly Action _actionMethodExecuting; + private static readonly Action _actionMethodExecutingWithArguments; + private static readonly Action _actionMethodExecuted; private static readonly Action _logFilterExecutionPlan; private static readonly Action _beforeExecutingMethodOnFilter; @@ -143,10 +145,10 @@ namespace Microsoft.AspNetCore.Mvc.Internal static MvcCoreLoggerExtensions() { - _actionExecuting = LoggerMessage.Define( - LogLevel.Debug, + _actionExecuting = LoggerMessage.Define( + LogLevel.Information, 1, - "Executing action {ActionName}"); + "Route matched with {RouteData}. Executing action {ActionName}"); _actionExecuted = LoggerMessage.Define( LogLevel.Information, @@ -163,15 +165,20 @@ namespace Microsoft.AspNetCore.Mvc.Internal 1, "Executing ContentResult with HTTP Response ContentType of {ContentType}"); - _actionMethodExecuting = LoggerMessage.Define( + _actionMethodExecuting = LoggerMessage.Define( LogLevel.Information, 1, - "Executing action method {ActionName} with arguments ({Arguments}) - ModelState is {ValidationState}"); + "Executing action method {ActionName} - Validation state: {ValidationState}"); - _actionMethodExecuted = LoggerMessage.Define( - LogLevel.Debug, + _actionMethodExecutingWithArguments = LoggerMessage.Define( + LogLevel.Information, + 1, + "Executing action method {ActionName} with arguments ({Arguments}) - Validation state: {ValidationState}"); + + _actionMethodExecuted = LoggerMessage.Define( + LogLevel.Information, 2, - "Executed action method {ActionName}, returned result {ActionResult}."); + "Executed action method {ActionName}, returned result {ActionResult} in {ElapsedMilliseconds}ms."); _logFilterExecutionPlan = LoggerMessage.Define( 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 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) - { - var currentTimestamp = Stopwatch.GetTimestamp(); - var elapsed = new TimeSpan((long)(TimestampToTicks * (currentTimestamp - startTimestamp))); - - _actionExecuted(logger, action.DisplayName, elapsed.TotalMilliseconds, null); - } + _actionExecuted(logger, action.DisplayName, timeSpan.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); } } diff --git a/src/Microsoft.AspNetCore.Mvc.Core/Internal/ResourceInvoker.cs b/src/Microsoft.AspNetCore.Mvc.Core/Internal/ResourceInvoker.cs index 8b3a48ba0e..8cf4a65ea2 100644 --- a/src/Microsoft.AspNetCore.Mvc.Core/Internal/ResourceInvoker.cs +++ b/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()); } } } diff --git a/src/Microsoft.AspNetCore.Mvc.Core/Microsoft.AspNetCore.Mvc.Core.csproj b/src/Microsoft.AspNetCore.Mvc.Core/Microsoft.AspNetCore.Mvc.Core.csproj index c858003fff..f5263f4479 100644 --- a/src/Microsoft.AspNetCore.Mvc.Core/Microsoft.AspNetCore.Mvc.Core.csproj +++ b/src/Microsoft.AspNetCore.Mvc.Core/Microsoft.AspNetCore.Mvc.Core.csproj @@ -38,6 +38,7 @@ Microsoft.AspNetCore.Mvc.RouteAttribute + diff --git a/src/Microsoft.AspNetCore.Mvc.ViewFeatures/Internal/MvcViewFeaturesLoggerExtensions.cs b/src/Microsoft.AspNetCore.Mvc.ViewFeatures/Internal/MvcViewFeaturesLoggerExtensions.cs index 7d4f11c24e..7f77416b12 100644 --- a/src/Microsoft.AspNetCore.Mvc.ViewFeatures/Internal/MvcViewFeaturesLoggerExtensions.cs +++ b/src/Microsoft.AspNetCore.Mvc.ViewFeatures/Internal/MvcViewFeaturesLoggerExtensions.cs @@ -18,16 +18,18 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures.Internal private static readonly Action _viewComponentExecuting; private static readonly Action _viewComponentExecuted; - private static readonly Action _partialViewFound; + private static readonly Action _partialViewFound; private static readonly Action, Exception> _partialViewNotFound; private static readonly Action _partialViewResultExecuting; + private static readonly Action _partialViewResultExecuted; private static readonly Action _antiforgeryTokenInvalid; private static readonly Action _viewComponentResultExecuting; private static readonly Action _viewResultExecuting; - private static readonly Action _viewFound; + private static readonly Action _viewResultExecuted; + private static readonly Action _viewFound; private static readonly Action, Exception> _viewNotFound; private static readonly Action _tempDataCookieNotFound; @@ -52,18 +54,23 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures.Internal _partialViewResultExecuting = LoggerMessage.Define( LogLevel.Information, 1, - "Executing PartialViewResult, running view at path {Path}."); + "Executing PartialViewResult, running view {PartialViewName}."); - _partialViewFound = LoggerMessage.Define( + _partialViewFound = LoggerMessage.Define( LogLevel.Debug, 2, - "The partial view '{PartialViewName}' was found."); + "The partial view path '{PartialViewFilePath}' was found in {ElapsedMilliseconds}ms."); _partialViewNotFound = LoggerMessage.Define>( LogLevel.Error, 3, "The partial view '{PartialViewName}' was not found. Searched locations: {SearchedViewLocations}"); + _partialViewResultExecuted = LoggerMessage.Define( + LogLevel.Information, + 4, + "Executed PartialViewResult - view {PartialViewName} executed in {ElapsedMilliseconds}ms."); + _antiforgeryTokenInvalid = LoggerMessage.Define( LogLevel.Information, 1, @@ -77,18 +84,23 @@ namespace Microsoft.AspNetCore.Mvc.ViewFeatures.Internal _viewResultExecuting = LoggerMessage.Define( LogLevel.Information, 1, - "Executing ViewResult, running view at path {Path}."); + "Executing ViewResult, running view {ViewName}."); - _viewFound = LoggerMessage.Define( + _viewFound = LoggerMessage.Define( LogLevel.Debug, 2, - "The view '{ViewName}' was found."); + "The view path '{ViewFilePath}' was found in {ElapsedMilliseconds}ms."); _viewNotFound = LoggerMessage.Define>( LogLevel.Error, 3, "The view '{ViewName}' was not found. Searched locations: {SearchedViewLocations}"); + _viewResultExecuted = LoggerMessage.Define( + LogLevel.Information, + 4, + "Executed ViewResult - view {ViewName} executed in {ElapsedMilliseconds}ms."); + _tempDataCookieNotFound = LoggerMessage.Define( 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) - { - var currentTimestamp = Stopwatch.GetTimestamp(); - var elapsed = new TimeSpan((long)(TimestampToTicks * (currentTimestamp - startTimestamp))); - - _viewComponentExecuted( - logger, - context.ViewComponentDescriptor.DisplayName, - elapsed.TotalMilliseconds, - Convert.ToString(result), - null); - } + _viewComponentExecuted( + logger, + context.ViewComponentDescriptor.DisplayName, + timespan.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, diff --git a/src/Microsoft.AspNetCore.Mvc.ViewFeatures/Microsoft.AspNetCore.Mvc.ViewFeatures.csproj b/src/Microsoft.AspNetCore.Mvc.ViewFeatures/Microsoft.AspNetCore.Mvc.ViewFeatures.csproj index 5f533aa3b1..27d839320d 100644 --- a/src/Microsoft.AspNetCore.Mvc.ViewFeatures/Microsoft.AspNetCore.Mvc.ViewFeatures.csproj +++ b/src/Microsoft.AspNetCore.Mvc.ViewFeatures/Microsoft.AspNetCore.Mvc.ViewFeatures.csproj @@ -28,6 +28,7 @@ Microsoft.AspNetCore.Mvc.ViewComponent + diff --git a/src/Microsoft.AspNetCore.Mvc.ViewFeatures/ViewComponents/DefaultViewComponentInvoker.cs b/src/Microsoft.AspNetCore.Mvc.ViewFeatures/ViewComponents/DefaultViewComponentInvoker.cs index 365f3fe908..d2a8614bda 100644 --- a/src/Microsoft.AspNetCore.Mvc.ViewFeatures/ViewComponents/DefaultViewComponentInvoker.cs +++ b/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); diff --git a/src/Microsoft.AspNetCore.Mvc.ViewFeatures/ViewFeatures/PartialViewResultExecutor.cs b/src/Microsoft.AspNetCore.Mvc.ViewFeatures/ViewFeatures/PartialViewResultExecutor.cs index f0c178eaf4..18ecbebe3d 100644 --- a/src/Microsoft.AspNetCore.Mvc.ViewFeatures/ViewFeatures/PartialViewResultExecutor.cs +++ b/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) diff --git a/src/Microsoft.AspNetCore.Mvc.ViewFeatures/ViewFeatures/ViewResultExecutor.cs b/src/Microsoft.AspNetCore.Mvc.ViewFeatures/ViewFeatures/ViewResultExecutor.cs index aa60b7f3d9..7d6b1ebc7c 100644 --- a/src/Microsoft.AspNetCore.Mvc.ViewFeatures/ViewFeatures/ViewResultExecutor.cs +++ b/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)