From e35d0bc43f8e02112f8eea416cbaafbdbcb93d3c Mon Sep 17 00:00:00 2001 From: Pranav K Date: Thu, 22 Feb 2018 12:57:19 -0800 Subject: [PATCH] Add more fine grained logging to RazorViewCompiler --- build/dependencies.props | 130 +++++++++--------- korebuild-lock.txt | 2 +- .../Internal/ChecksumValidator.cs | 10 +- .../Internal/MvcRazorLoggerExtensions.cs | 96 +++++++++++-- .../Internal/RazorViewCompiler.cs | 16 ++- 5 files changed, 173 insertions(+), 81 deletions(-) diff --git a/build/dependencies.props b/build/dependencies.props index 56b636e81e..a207a1bf7c 100644 --- a/build/dependencies.props +++ b/build/dependencies.props @@ -4,77 +4,77 @@ 0.10.11 - 2.1.0-preview2-15721 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 + 2.1.0-preview2-15723 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 5.2.4 2.6.1 2.6.1 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 2.1.0-preview2-25711-01 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 - 2.1.0-preview2-30187 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 + 2.1.0-preview2-30190 2.0.0 2.1.0-preview2-26130-04 - 2.1.0-preview2-30187 + 2.1.0-preview2-30190 15.6.0 4.7.49 1.0.1 diff --git a/korebuild-lock.txt b/korebuild-lock.txt index e6c7fddffa..b6a93c01ac 100644 --- a/korebuild-lock.txt +++ b/korebuild-lock.txt @@ -1,2 +1,2 @@ -version:2.1.0-preview2-15721 +version:2.1.0-preview2-15723 commithash:f9bb4be59e39938ec59a6975257e26099b0d03c1 diff --git a/src/Microsoft.AspNetCore.Mvc.Razor/Internal/ChecksumValidator.cs b/src/Microsoft.AspNetCore.Mvc.Razor/Internal/ChecksumValidator.cs index 4b8b2abdf8..fea6a7ba2d 100644 --- a/src/Microsoft.AspNetCore.Mvc.Razor/Internal/ChecksumValidator.cs +++ b/src/Microsoft.AspNetCore.Mvc.Razor/Internal/ChecksumValidator.cs @@ -27,11 +27,11 @@ namespace Microsoft.AspNetCore.Mvc.Razor.Internal // Validates that we can use an existing precompiled view by comparing checksums with files on // disk. - public static bool IsItemValid(RazorProjectFileSystem project, RazorCompiledItem item) + public static bool IsItemValid(RazorProjectFileSystem fileSystem, RazorCompiledItem item) { - if (project == null) + if (fileSystem == null) { - throw new ArgumentNullException(nameof(project)); + throw new ArgumentNullException(nameof(fileSystem)); } if (item == null) @@ -57,7 +57,7 @@ namespace Microsoft.AspNetCore.Mvc.Razor.Internal return true; } - var projectItem = project.GetItem(primaryChecksum.Identifier); + var projectItem = fileSystem.GetItem(primaryChecksum.Identifier); if (!projectItem.Exists) { // Main file doesn't exist - assume valid. @@ -81,7 +81,7 @@ namespace Microsoft.AspNetCore.Mvc.Razor.Internal continue; } - var importItem = project.GetItem(checksum.Identifier); + var importItem = fileSystem.GetItem(checksum.Identifier); if (!importItem.Exists) { // Import file doesn't exist - assume invalid. diff --git a/src/Microsoft.AspNetCore.Mvc.Razor/Internal/MvcRazorLoggerExtensions.cs b/src/Microsoft.AspNetCore.Mvc.Razor/Internal/MvcRazorLoggerExtensions.cs index 55597fcf78..21d7496abd 100644 --- a/src/Microsoft.AspNetCore.Mvc.Razor/Internal/MvcRazorLoggerExtensions.cs +++ b/src/Microsoft.AspNetCore.Mvc.Razor/Internal/MvcRazorLoggerExtensions.cs @@ -2,7 +2,9 @@ // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. using System; +using System.Collections.Generic; using System.Diagnostics; +using System.Linq; using Microsoft.Extensions.Logging; namespace Microsoft.AspNetCore.Mvc.Razor.Internal @@ -14,8 +16,15 @@ namespace Microsoft.AspNetCore.Mvc.Razor.Internal private static readonly Action _generatedCodeToAssemblyCompilationStart; private static readonly Action _generatedCodeToAssemblyCompilationEnd; - private static readonly Action _razorFileToCodeCompilationStart; - private static readonly Action _razorFileToCodeCompilationEnd; + private static readonly Action _viewCompilerStartCodeGeneration; + private static readonly Action _viewCompilerEndCodeGeneration; + private static readonly Action _viewCompilerLocatedCompiledView; + private static readonly Action _viewCompilerNoCompiledViewsFound; + private static readonly Action _viewCompilerLocatedCompiledViewForPath; + private static readonly Action _viewCompilerRecompilingCompiledView; + private static readonly Action _viewCompilerCouldNotFindFileToCompileForPath; + private static readonly Action _viewCompilerFoundFileToCompileForPath; + private static readonly Action _viewCompilerInvalidatingCompiledFile; private static readonly Action _viewLookupCacheMiss; private static readonly Action _viewLookupCacheHit; @@ -24,18 +33,59 @@ namespace Microsoft.AspNetCore.Mvc.Razor.Internal private static readonly Action _tagHelperComponentInitialized; private static readonly Action _tagHelperComponentProcessed; + static MvcRazorLoggerExtensions() { - _razorFileToCodeCompilationStart = LoggerMessage.Define( + _viewCompilerStartCodeGeneration = LoggerMessage.Define( LogLevel.Debug, 1, "Code generation for the Razor file at '{FilePath}' started."); - _razorFileToCodeCompilationEnd = LoggerMessage.Define( + _viewCompilerEndCodeGeneration = LoggerMessage.Define( LogLevel.Debug, 2, "Code generation for the Razor file at '{FilePath}' completed in {ElapsedMilliseconds}ms."); + _viewCompilerLocatedCompiledView = LoggerMessage.Define( + LogLevel.Debug, + 3, + "Initializing Razor view compiler with compiled view: '{ViewName}'."); + + _viewCompilerNoCompiledViewsFound = LoggerMessage.Define( + LogLevel.Debug, + 4, + "Initializing Razor view compiler with no compiled views."); + + _viewCompilerLocatedCompiledViewForPath = LoggerMessage.Define( + LogLevel.Trace, + 5, + "Located compiled view for view at path '{Path}'."); + + _viewCompilerLocatedCompiledViewForPath = LoggerMessage.Define( + LogLevel.Trace, + 5, + "Located compiled view for view at path '{Path}'."); + + _viewCompilerRecompilingCompiledView = LoggerMessage.Define( + LogLevel.Trace, + 6, + "Invalidating compiled view for view at path '{Path}'."); + + _viewCompilerCouldNotFindFileToCompileForPath = LoggerMessage.Define( + LogLevel.Trace, + 7, + "Could not find a file for view at path '{Path}'."); + + _viewCompilerFoundFileToCompileForPath = LoggerMessage.Define( + LogLevel.Trace, + 8, + "Found file at path '{Path}'."); + + _viewCompilerInvalidatingCompiledFile = LoggerMessage.Define( + LogLevel.Trace, + 9, + "Invalidating compiled view at path '{Path}' with a file since the checksum did not match."); + _viewLookupCacheMiss = LoggerMessage.Define( LogLevel.Debug, 1, @@ -72,22 +122,52 @@ namespace Microsoft.AspNetCore.Mvc.Razor.Internal "Tag helper component '{ComponentName}' processed."); } - public static void RazorFileToCodeCompilationStart(this ILogger logger, string filePath) + public static void ViewCompilerStartCodeGeneration(this ILogger logger, string filePath) { - _razorFileToCodeCompilationStart(logger, filePath, null); + _viewCompilerStartCodeGeneration(logger, filePath, null); } - public static void RazorFileToCodeCompilationEnd(this ILogger logger, string filePath, long startTimestamp) + public static void ViewCompilerEndCodeGeneration(this ILogger logger, string filePath, long startTimestamp) { // 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))); - _razorFileToCodeCompilationEnd(logger, filePath, elapsed.TotalMilliseconds, null); + _viewCompilerEndCodeGeneration(logger, filePath, elapsed.TotalMilliseconds, null); } } + public static void ViewCompilerLocatedCompiledView(this ILogger logger, string view) + { + _viewCompilerLocatedCompiledView(logger, view, null); + } + + public static void ViewCompilerNoCompiledViewsFound(this ILogger logger) + { + _viewCompilerNoCompiledViewsFound(logger, null); + } + + public static void ViewCompilerLocatedCompiledViewForPath(this ILogger logger, string path) + { + _viewCompilerLocatedCompiledViewForPath(logger, path, null); + } + + public static void ViewCompilerCouldNotFindFileAtPath(this ILogger logger, string path) + { + _viewCompilerCouldNotFindFileToCompileForPath(logger, path, null); + } + + public static void ViewCompilerFoundFileToCompile(this ILogger logger, string path) + { + _viewCompilerFoundFileToCompileForPath(logger, path, null); + } + + public static void ViewCompilerInvalidingCompiledFile(this ILogger logger, string path) + { + _viewCompilerInvalidatingCompiledFile(logger, path, null); + } + public static void ViewLookupCacheMiss(this ILogger logger, string viewName, string controllerName) { _viewLookupCacheMiss(logger, viewName, controllerName, null); diff --git a/src/Microsoft.AspNetCore.Mvc.Razor/Internal/RazorViewCompiler.cs b/src/Microsoft.AspNetCore.Mvc.Razor/Internal/RazorViewCompiler.cs index 857dd60ad1..00f99600a2 100644 --- a/src/Microsoft.AspNetCore.Mvc.Razor/Internal/RazorViewCompiler.cs +++ b/src/Microsoft.AspNetCore.Mvc.Razor/Internal/RazorViewCompiler.cs @@ -97,6 +97,8 @@ namespace Microsoft.AspNetCore.Mvc.Razor.Internal foreach (var precompiledView in precompiledViews) { + logger.ViewCompilerLocatedCompiledView(precompiledView.RelativePath); + if (_precompiledViews.TryGetValue(precompiledView.RelativePath, out var otherValue)) { var message = string.Join( @@ -109,6 +111,11 @@ namespace Microsoft.AspNetCore.Mvc.Razor.Internal _precompiledViews.Add(precompiledView.RelativePath, precompiledView); } + + if (_precompiledViews.Count == 0) + { + logger.ViewCompilerNoCompiledViewsFound(); + } } /// @@ -121,8 +128,7 @@ namespace Microsoft.AspNetCore.Mvc.Razor.Internal // Attempt to lookup the cache entry using the passed in path. This will succeed if the path is already // normalized and a cache entry exists. - Task cachedResult; - if (_cache.TryGetValue(relativePath, out cachedResult)) + if (_cache.TryGetValue(relativePath, out Task cachedResult)) { return cachedResult; } @@ -157,6 +163,7 @@ namespace Microsoft.AspNetCore.Mvc.Razor.Internal if (_precompiledViews.TryGetValue(normalizedPath, out var precompiledView)) { + _logger.ViewCompilerLocatedCompiledViewForPath(normalizedPath); item = CreatePrecompiledWorkItem(normalizedPath, precompiledView); } else @@ -204,6 +211,7 @@ namespace Microsoft.AspNetCore.Mvc.Razor.Internal return taskSource.Task; } + _logger.ViewCompilerInvalidingCompiledFile(item.NormalizedPath); try { var descriptor = CompileAndEmit(normalizedPath); @@ -284,6 +292,8 @@ namespace Microsoft.AspNetCore.Mvc.Razor.Internal var projectItem = _projectEngine.FileSystem.GetItem(normalizedPath); if (!projectItem.Exists) { + _logger.ViewCompilerCouldNotFindFileAtPath(normalizedPath); + // If the file doesn't exist, we can't do compilation right now - we still want to cache // the fact that we tried. This will allow us to retrigger compilation if the view file // is added. @@ -303,6 +313,8 @@ namespace Microsoft.AspNetCore.Mvc.Razor.Internal }; } + _logger.ViewCompilerFoundFileToCompile(normalizedPath); + // OK this means we can do compilation. For now let's just identify the other files we need to watch // so we can create the cache entry. Compilation will happen after we release the lock.