[Fixes #3755] Added logging for view compilation

src/Microsoft.AspNet.Mvc.Razor/Compilation/RazorCompilationService.cs

@@ -3,12 +3,15 @@
 
 using System;
 using System.Collections.Generic;
+using System.Diagnostics;
 using System.IO;
 using System.Linq;
 using Microsoft.AspNet.Diagnostics;
 using Microsoft.AspNet.FileProviders;
+using Microsoft.AspNet.Mvc.Logging;
 using Microsoft.AspNet.Razor;
 using Microsoft.AspNet.Razor.CodeGenerators;
+using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
 
 namespace Microsoft.AspNet.Mvc.Razor.Compilation
@@ -21,6 +24,7 @@ namespace Microsoft.AspNet.Mvc.Razor.Compilation
         private readonly ICompilationService _compilationService;
         private readonly IMvcRazorHost _razorHost;
         private readonly IFileProvider _fileProvider;
+        private readonly ILogger _logger;
 
         /// <summary>
         /// Instantiates a new instance of the <see cref="RazorCompilationService"/> class.
@@ -31,11 +35,13 @@ namespace Microsoft.AspNet.Mvc.Razor.Compilation
         public RazorCompilationService(
             ICompilationService compilationService,
             IMvcRazorHost razorHost,
-            IRazorViewEngineFileProviderAccessor fileProviderAccessor)
+            IRazorViewEngineFileProviderAccessor fileProviderAccessor,
+            ILoggerFactory loggerFactory)
         {
             _compilationService = compilationService;
             _razorHost = razorHost;
             _fileProvider = fileProviderAccessor.FileProvider;
+            _logger = loggerFactory.CreateLogger<RazorCompilationService>();
         }
 
         /// <inheritdoc />
@@ -49,7 +55,13 @@ namespace Microsoft.AspNet.Mvc.Razor.Compilation
             GeneratorResults results;
             using (var inputStream = file.FileInfo.CreateReadStream())
             {
+                _logger.RazorFileToCodeCompilationStart(file.RelativePath);
+
+                var startTimestamp = _logger.IsEnabled(LogLevel.Debug) ? Stopwatch.GetTimestamp() : 0;
+
                 results = GenerateCode(file.RelativePath, inputStream);
+
+                _logger.RazorFileToCodeCompilationEnd(file.RelativePath, startTimestamp);
             }
 
             if (!results.Success)

src/Microsoft.AspNet.Mvc.Razor/Compilation/RoslynCompilationService.cs

@@ -14,6 +14,7 @@ using System.Runtime.Loader;
 #endif
 using System.Runtime.Versioning;
 using Microsoft.AspNet.FileProviders;
+using Microsoft.AspNet.Mvc.Logging;
 using Microsoft.AspNet.Mvc.Razor.Internal;
 using Microsoft.CodeAnalysis;
 using Microsoft.CodeAnalysis.CSharp;
@@ -22,6 +23,7 @@ using Microsoft.Dnx.Compilation.CSharp;
 using Microsoft.Extensions.PlatformAbstractions;
 using Microsoft.Extensions.Options;
 using Microsoft.AspNet.Diagnostics;
+using Microsoft.Extensions.Logging;
 
 namespace Microsoft.AspNet.Mvc.Razor.Compilation
 {
@@ -42,6 +44,7 @@ namespace Microsoft.AspNet.Mvc.Razor.Compilation
         private readonly Action<RoslynCompilationContext> _compilationCallback;
         private readonly CSharpParseOptions _parseOptions;
         private readonly CSharpCompilationOptions _compilationOptions;
+        private readonly ILogger _logger;
 
 #if DOTNET5_5
         private readonly RazorLoadContext _razorLoadContext;
@@ -60,7 +63,8 @@ namespace Microsoft.AspNet.Mvc.Razor.Compilation
             Extensions.CompilationAbstractions.ILibraryExporter libraryExporter,
             IMvcRazorHost host,
             IOptions<RazorViewEngineOptions> optionsAccessor,
-            IRazorViewEngineFileProviderAccessor fileProviderAccessor)
+            IRazorViewEngineFileProviderAccessor fileProviderAccessor,
+            ILoggerFactory loggerFactory)
         {
             _environment = environment;
             _libraryExporter = libraryExporter;
@@ -70,6 +74,7 @@ namespace Microsoft.AspNet.Mvc.Razor.Compilation
             _compilationCallback = optionsAccessor.Value.CompilationCallback;
             _parseOptions = optionsAccessor.Value.ParseOptions;
             _compilationOptions = optionsAccessor.Value.CompilationOptions;
+            _logger = loggerFactory.CreateLogger<RoslynCompilationService>();
 
 #if DOTNET5_5
             _razorLoadContext = new RazorLoadContext();
@@ -89,6 +94,10 @@ namespace Microsoft.AspNet.Mvc.Razor.Compilation
                 throw new ArgumentNullException(nameof(compilationContent));
             }
 
+            _logger.GeneratedCodeToAssemblyCompilationStart(fileInfo.RelativePath);
+
+            var startTimestamp = _logger.IsEnabled(LogLevel.Debug) ? Stopwatch.GetTimestamp() : 0;
+
             var assemblyName = Path.GetRandomFileName();
 
             var syntaxTree = SyntaxTreeGenerator.Generate(
@@ -150,6 +159,8 @@ namespace Microsoft.AspNet.Mvc.Razor.Compilation
                     var type = assembly.GetExportedTypes()
                                        .First(t => t.Name.StartsWith(_classPrefix, StringComparison.Ordinal));
 
+                    _logger.GeneratedCodeToAssemblyCompilationEnd(fileInfo.RelativePath, startTimestamp);
+
                     return new CompilationResult(type);
                 }
             }

src/Microsoft.AspNet.Mvc.Razor/Logging/RazorCompilationServiceLoggerExtensions.cs

@@ -0,0 +1,45 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
+
+using System;
+using System.Diagnostics;
+using Microsoft.Extensions.Logging;
+
+namespace Microsoft.AspNet.Mvc.Logging
+{
+    public static class RazorCompilationServiceLoggerExtensions
+    {
+        private static readonly double TimestampToTicks = Stopwatch.Frequency / 10000000.0;
+        private static readonly Action<ILogger, string, Exception> _razorFileToCodeCompilationStart;
+        private static readonly Action<ILogger, string, double, Exception> _razorFileToCodeCompilationEnd;
+
+        static RazorCompilationServiceLoggerExtensions()
+        {
+            _razorFileToCodeCompilationStart = LoggerMessage.Define<string>(
+                LogLevel.Debug,
+                1,
+                "Code generation for the Razor file at '{FilePath}' started.");
+
+            _razorFileToCodeCompilationEnd = LoggerMessage.Define<string, double>(
+                LogLevel.Debug,
+                2,
+                "Code generation for the Razor file at '{FilePath}' completed in {ElapsedMilliseconds}ms.");
+        }
+
+        public static void RazorFileToCodeCompilationStart(this ILogger logger, string filePath)
+        {
+            _razorFileToCodeCompilationStart(logger, filePath, null);
+        }
+
+        public static void RazorFileToCodeCompilationEnd(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);
+            }
+        }
+    }
+}

src/Microsoft.AspNet.Mvc.Razor/Logging/RazorViewEngineLoggerExtensions.cs

@@ -0,0 +1,37 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
+
+using System;
+using Microsoft.Extensions.Logging;
+
+namespace Microsoft.AspNet.Mvc.Logging
+{
+    public static class RazorViewEngineLoggerExtensions
+    {
+        private static readonly Action<ILogger, string, string, Exception> _viewLookupCacheMiss;
+        private static readonly Action<ILogger, string, string, Exception> _viewLookupCacheHit;
+
+        static RazorViewEngineLoggerExtensions()
+        {
+            _viewLookupCacheMiss = LoggerMessage.Define<string, string>(
+                LogLevel.Debug,
+                1,
+                "View lookup cache miss for view '{ViewName}' in controller '{ControllerName}'.");
+
+            _viewLookupCacheHit = LoggerMessage.Define<string, string>(
+                LogLevel.Debug,
+                2,
+                "View lookup cache hit for view '{ViewName}' in controller '{ControllerName}'.");
+        }
+
+        public static void ViewLookupCacheMiss(this ILogger logger, string viewName, string controllerName)
+        {
+            _viewLookupCacheMiss(logger, viewName, controllerName, null);
+        }
+
+        public static void ViewLookupCacheHit(this ILogger logger, string viewName, string controllerName)
+        {
+            _viewLookupCacheHit(logger, viewName, controllerName, null);
+        }
+    }
+}

src/Microsoft.AspNet.Mvc.Razor/Logging/RoslynCompilationServiceLoggerExtensions.cs

@@ -0,0 +1,45 @@
+// Copyright (c) .NET Foundation. All rights reserved.
+// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
+
+using System;
+using System.Diagnostics;
+using Microsoft.Extensions.Logging;
+
+namespace Microsoft.AspNet.Mvc.Logging
+{
+    public static class RoslynCompilationServiceLoggerExtensions
+    {
+        private static readonly double TimestampToTicks = Stopwatch.Frequency / 10000000.0;
+        private static readonly Action<ILogger, string, Exception> _generatedCodeToAssemblyCompilationStart;
+        private static readonly Action<ILogger, string, double, Exception> _generatedCodeToAssemblyCompilationEnd;
+
+        static RoslynCompilationServiceLoggerExtensions()
+        {
+            _generatedCodeToAssemblyCompilationStart = LoggerMessage.Define<string>(
+                LogLevel.Debug,
+                1,
+                "Compilation of the generated code for the Razor file at '{FilePath}' started.");
+
+            _generatedCodeToAssemblyCompilationEnd = LoggerMessage.Define<string, double>(
+                LogLevel.Debug,
+                2,
+                "Compilation of the generated code for the Razor file at '{FilePath}' completed in {ElapsedMilliseconds}ms.");
+        }
+
+        public static void GeneratedCodeToAssemblyCompilationStart(this ILogger logger, string filePath)
+        {
+            _generatedCodeToAssemblyCompilationStart(logger, filePath, null);
+        }
+
+        public static void GeneratedCodeToAssemblyCompilationEnd(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)));
+                _generatedCodeToAssemblyCompilationEnd(logger, filePath, elapsed.TotalMilliseconds, null);
+            }
+        }
+    }
+}

src/Microsoft.AspNet.Mvc.Razor/RazorViewEngine.cs

@@ -7,9 +7,11 @@ using System.Diagnostics;
 using System.Globalization;
 using System.Linq;
 using System.Text.Encodings.Web;
+using Microsoft.AspNet.Mvc.Logging;
 using Microsoft.AspNet.Mvc.Routing;
 using Microsoft.AspNet.Mvc.ViewEngines;
 using Microsoft.Extensions.Caching.Memory;
+using Microsoft.Extensions.Logging;
 using Microsoft.Extensions.Options;
 using Microsoft.Extensions.Primitives;
 
@@ -35,6 +37,7 @@ namespace Microsoft.AspNet.Mvc.Razor
         private readonly IList<IViewLocationExpander> _viewLocationExpanders;
         private readonly IRazorPageActivator _pageActivator;
         private readonly HtmlEncoder _htmlEncoder;
+        private readonly ILogger _logger;
 
         /// <summary>
         /// Initializes a new instance of the <see cref="RazorViewEngine" />.
@@ -43,12 +46,14 @@ namespace Microsoft.AspNet.Mvc.Razor
             IRazorPageFactoryProvider pageFactory,
             IRazorPageActivator pageActivator,
             HtmlEncoder htmlEncoder,
-            IOptions<RazorViewEngineOptions> optionsAccessor)
+            IOptions<RazorViewEngineOptions> optionsAccessor,
+            ILoggerFactory loggerFactory)
         {
             _pageFactory = pageFactory;
             _pageActivator = pageActivator;
             _viewLocationExpanders = optionsAccessor.Value.ViewLocationExpanders;
             _htmlEncoder = htmlEncoder;
+            _logger = loggerFactory.CreateLogger<RazorViewEngine>();
             ViewLookupCache = new MemoryCache(new MemoryCacheOptions
             {
                 CompactOnMemoryPressure = false
@@ -341,8 +346,13 @@ namespace Microsoft.AspNet.Mvc.Razor
             ViewLocationCacheResult cacheResult;
             if (!ViewLookupCache.TryGetValue(cacheKey, out cacheResult))
             {
+                _logger.ViewLookupCacheMiss(cacheKey.ViewName, cacheKey.ControllerName);
                 cacheResult = OnCacheMiss(expanderContext, cacheKey);
             }
+            else
+            {
+                _logger.ViewLookupCacheHit(cacheKey.ViewName, cacheKey.ControllerName);
+            }
 
             return cacheResult;
         }

test/Microsoft.AspNet.Mvc.Razor.Test/Compilation/RazorCompilationServiceTest.cs

@@ -9,6 +9,7 @@ using Microsoft.AspNet.Razor.Chunks;
 using Microsoft.AspNet.Razor.CodeGenerators;
 using Microsoft.AspNet.Razor.Compilation.TagHelpers;
 using Microsoft.AspNet.Razor.Parser.SyntaxTree;
+using Microsoft.Extensions.Logging.Testing;
 using Microsoft.Extensions.Options;
 using Moq;
 using Xunit;
@@ -38,7 +39,7 @@ namespace Microsoft.AspNet.Mvc.Razor.Compilation
             compiler.Setup(c => c.Compile(relativeFileInfo, It.IsAny<string>()))
                     .Returns(new CompilationResult(typeof(RazorCompilationServiceTest)));
 
-            var razorService = new RazorCompilationService(compiler.Object, host.Object, GetFileProviderAccessor());
+            var razorService = new RazorCompilationService(compiler.Object, host.Object, GetFileProviderAccessor(), NullLoggerFactory.Instance);
 
             // Act
             razorService.Compile(relativeFileInfo);
@@ -70,7 +71,7 @@ namespace Microsoft.AspNet.Mvc.Razor.Compilation
 
             var compiler = new Mock<ICompilationService>(MockBehavior.Strict);
             var relativeFileInfo = new RelativeFileInfo(fileInfo.Object, @"Views\index\home.cshtml");
-            var razorService = new RazorCompilationService(compiler.Object, host.Object, GetFileProviderAccessor());
+            var razorService = new RazorCompilationService(compiler.Object, host.Object, GetFileProviderAccessor(), NullLoggerFactory.Instance);
 
             // Act
             var result = razorService.Compile(relativeFileInfo);
@@ -111,7 +112,7 @@ namespace Microsoft.AspNet.Mvc.Razor.Compilation
             compiler.Setup(c => c.Compile(relativeFileInfo, code))
                     .Returns(compilationResult)
                     .Verifiable();
-            var razorService = new RazorCompilationService(compiler.Object, host.Object, GetFileProviderAccessor());
+            var razorService = new RazorCompilationService(compiler.Object, host.Object, GetFileProviderAccessor(), NullLoggerFactory.Instance);
 
             // Act
             var result = razorService.Compile(relativeFileInfo);
@@ -136,7 +137,8 @@ namespace Microsoft.AspNet.Mvc.Razor.Compilation
             var razorService = new RazorCompilationService(
                 Mock.Of<ICompilationService>(),
                 Mock.Of<IMvcRazorHost>(),
-                GetFileProviderAccessor(fileProvider));
+                GetFileProviderAccessor(fileProvider),
+                NullLoggerFactory.Instance);
             var errors = new[]
             {
                 new RazorError("message-1", new SourceLocation(1, 2, 17), length: 1),

test/Microsoft.AspNet.Mvc.Razor.Test/Compilation/RoslynCompilationServiceTest.cs

@@ -6,6 +6,7 @@ using Microsoft.AspNet.FileProviders;
 using Microsoft.CodeAnalysis;
 using Microsoft.CodeAnalysis.Text;
 using Microsoft.Extensions.CompilationAbstractions;
+using Microsoft.Extensions.Logging.Testing;
 using Microsoft.Extensions.Options;
 using Microsoft.Extensions.PlatformAbstractions;
 using Moq;
@@ -34,7 +35,8 @@ public class MyTestType  {}";
                 libraryExporter,
                 mvcRazorHost.Object,
                 GetOptions(),
-                GetFileProviderAccessor());
+                GetFileProviderAccessor(),
+                NullLoggerFactory.Instance);
             var relativeFileInfo = new RelativeFileInfo(
                 new TestFileInfo { PhysicalPath = "SomePath" },
                 "some-relative-path");
@@ -66,7 +68,8 @@ this should fail";
                 libraryExporter,
                 mvcRazorHost,
                 GetOptions(),
-                GetFileProviderAccessor(fileProvider));
+                GetFileProviderAccessor(fileProvider),
+                NullLoggerFactory.Instance);
             var relativeFileInfo = new RelativeFileInfo(fileInfo, "some-relative-path");
 
             // Act
@@ -95,7 +98,8 @@ this should fail";
                 libraryExporter,
                 mvcRazorHost,
                 GetOptions(),
-                GetFileProviderAccessor());
+                GetFileProviderAccessor(),
+                NullLoggerFactory.Instance);
             var relativeFileInfo = new RelativeFileInfo(
                 new TestFileInfo { Content = fileContent },
                 "some-relative-path");
@@ -135,7 +139,8 @@ this should fail";
                 libraryExporter,
                 mvcRazorHost,
                 GetOptions(),
-                GetFileProviderAccessor(fileProvider));
+                GetFileProviderAccessor(fileProvider),
+                NullLoggerFactory.Instance);
 
             var relativeFileInfo = new RelativeFileInfo(mockFileInfo.Object, path);
 
@@ -175,7 +180,8 @@ public class MyNonCustomDefinedClass {}
                 libraryExporter,
                 mvcRazorHost.Object,
                 options,
-                GetFileProviderAccessor());
+                GetFileProviderAccessor(),
+                NullLoggerFactory.Instance);
             var relativeFileInfo = new RelativeFileInfo(
                 new TestFileInfo { PhysicalPath = "SomePath" },
                 "some-relative-path");
@@ -206,7 +212,8 @@ public class NotRazorPrefixType {}";
                 libraryExporter,
                 mvcRazorHost.Object,
                 GetOptions(),
-                GetFileProviderAccessor());
+                GetFileProviderAccessor(),
+                NullLoggerFactory.Instance);
 
             var relativeFileInfo = new RelativeFileInfo(
                 new TestFileInfo { PhysicalPath = "SomePath" },
@@ -238,7 +245,8 @@ public class NotRazorPrefixType {}";
                 CompilationServices.Default.LibraryExporter,
                 Mock.Of<IMvcRazorHost>(),
                 optionsAccessor.Object,
-                GetFileProviderAccessor(fileProvider));
+                GetFileProviderAccessor(fileProvider),
+                NullLoggerFactory.Instance);
 
             var assemblyName = "random-assembly-name";
 
@@ -330,7 +338,8 @@ public class NotRazorPrefixType {}";
                 libraryExporter,
                 mvcRazorHost.Object,
                 GetOptions(callback: c => usedCompilation = c),
-                GetFileProviderAccessor());
+                GetFileProviderAccessor(),
+                NullLoggerFactory.Instance);
 
             var relativeFileInfo = new RelativeFileInfo(
                 new TestFileInfo { PhysicalPath = "SomePath" },

test/Microsoft.AspNet.Mvc.Razor.Test/RazorViewEngineTest.cs

@@ -11,6 +11,7 @@ using Microsoft.AspNet.Mvc.ViewEngines;
 using Microsoft.AspNet.Routing;
 using Microsoft.AspNet.Testing;
 using Microsoft.Extensions.Caching.Memory;
+using Microsoft.Extensions.Logging.Testing;
 using Microsoft.Extensions.Options;
 using Microsoft.Extensions.Primitives;
 using Microsoft.Extensions.WebEncoders.Testing;
@@ -1806,7 +1807,7 @@ namespace Microsoft.AspNet.Mvc.Razor.Test
             public TestableRazorViewEngine(
                 IRazorPageFactoryProvider pageFactory,
                 IOptions<RazorViewEngineOptions> optionsAccessor)
-                : base(pageFactory, Mock.Of<IRazorPageActivator>(), new HtmlTestEncoder(), optionsAccessor)
+                : base(pageFactory, Mock.Of<IRazorPageActivator>(), new HtmlTestEncoder(), optionsAccessor, NullLoggerFactory.Instance)
             {
             }
 

test/Microsoft.AspNet.Mvc.Razor.Test/project.json

@@ -26,6 +26,7 @@
     "Microsoft.Dnx.Runtime": "1.0.0-*",
     "Microsoft.Extensions.DependencyInjection": "1.0.0-*",
     "Microsoft.Extensions.DiagnosticAdapter": "1.0.0-*",
+    "Microsoft.Extensions.Logging.Testing": "1.0.0-*",
     "xunit.runner.aspnet": "2.0.0-aspnet-*"
   },
   "commands": {

test/WebSites/RazorPageExecutionInstrumentationWebSite/TestRazorCompilationService.cs

@@ -6,6 +6,7 @@ using System.Text;
 using Microsoft.AspNet.Mvc.Razor;
 using Microsoft.AspNet.Mvc.Razor.Compilation;
 using Microsoft.AspNet.Razor.CodeGenerators;
+using Microsoft.Extensions.Logging;
 
 namespace RazorPageExecutionInstrumentationWebSite
 {
@@ -14,8 +15,9 @@ namespace RazorPageExecutionInstrumentationWebSite
         public TestRazorCompilationService(
             ICompilationService compilationService,
             IMvcRazorHost razorHost,
-            IRazorViewEngineFileProviderAccessor fileProviderAccessor)
+            IRazorViewEngineFileProviderAccessor fileProviderAccessor,
-            : base(compilationService, razorHost, fileProviderAccessor)
+            ILoggerFactory loggerFactory)
+            : base(compilationService, razorHost, fileProviderAccessor, loggerFactory)
         {
         }