Disabled logging fast-path (#937)

src/Microsoft.AspNetCore.Hosting/Internal/HostingApplication.cs

@@ -3,6 +3,7 @@
 
 using System;
 using System.Diagnostics;
+using System.Runtime.CompilerServices;
 using System.Threading.Tasks;
 using Microsoft.AspNetCore.Hosting.Server;
 using Microsoft.AspNetCore.Http;
@@ -13,6 +14,12 @@ namespace Microsoft.AspNetCore.Hosting.Internal
 {
     public class HostingApplication : IHttpApplication<HostingApplication.Context>
     {
+        private const string DiagnosticsBeginRequestKey = "Microsoft.AspNetCore.Hosting.BeginRequest";
+        private const string DiagnosticsEndRequestKey = "Microsoft.AspNetCore.Hosting.EndRequest";
+        private const string DiagnosticsUnhandledExceptionKey = "Microsoft.AspNetCore.Hosting.UnhandledException";
+
+        private static readonly double TimestampToTicks = TimeSpan.TicksPerSecond / (double)Stopwatch.Frequency;
+
         private readonly RequestDelegate _application;
         private readonly ILogger _logger;
         private readonly DiagnosticSource _diagnosticSource;
@@ -30,25 +37,41 @@ namespace Microsoft.AspNetCore.Hosting.Internal
             _httpContextFactory = httpContextFactory;
         }
 
+        // Set up the request
         public Context CreateContext(IFeatureCollection contextFeatures)
         {
             var httpContext = _httpContextFactory.Create(contextFeatures);
-            var diagnoticsEnabled = _diagnosticSource.IsEnabled("Microsoft.AspNetCore.Hosting.BeginRequest");
-            var startTimestamp = (diagnoticsEnabled || _logger.IsEnabled(LogLevel.Information)) ? Stopwatch.GetTimestamp() : 0;
 
+            // These enabled checks are virtual dispatch and used twice and so cache to locals
+            var diagnoticsEnabled = _diagnosticSource.IsEnabled(DiagnosticsBeginRequestKey);
+            var loggingEnabled = _logger.IsEnabled(LogLevel.Information);
+
+            if (HostingEventSource.Log.IsEnabled())
+            {
+                // To keep the hot path short we defer logging in this function to non-inlines
+                RecordRequestStartEventLog(httpContext);
+            }
+
+            // Only make call GetTimestamp if its value will be used, i.e. of the listenters is enabled
+            var startTimestamp = (diagnoticsEnabled || loggingEnabled) ? Stopwatch.GetTimestamp() : 0;
+
+            // Scope may be relevant for a different level of logging, so we always create it
+            // see: https://github.com/aspnet/Hosting/pull/944
             var scope = _logger.RequestScope(httpContext);
-            _logger.RequestStarting(httpContext);
+
+            if (loggingEnabled)
+            {
+                // Non-inline
+                LogRequestStarting(httpContext);
+            }
+
             if (diagnoticsEnabled)
             {
-                _diagnosticSource.Write("Microsoft.AspNetCore.Hosting.BeginRequest", new { httpContext = httpContext, timestamp = startTimestamp });
+                // Non-inline
-            }
+                RecordBeginRequestDiagnostics(httpContext, startTimestamp);
-
-            var hostingLog = HostingEventSource.Log;
-            if (hostingLog.IsEnabled())
-            {
-                hostingLog.RequestStart(httpContext.Request.Method, httpContext.Request.Path);
             }
 
+            // Create and return the request Context
             return new Context
             {
                 HttpContext = httpContext,
@@ -57,53 +80,147 @@ namespace Microsoft.AspNetCore.Hosting.Internal
             };
         }
 
+        // Execute the request
+        public Task ProcessRequestAsync(Context context)
+        {
+            return _application(context.HttpContext);
+        }
+
+        // Clean up the request
         public void DisposeContext(Context context, Exception exception)
         {
+            // Local cache items resolved multiple items, in order of use so they are primed in cpu pipeline when used
+            var hostingEventLog = HostingEventSource.Log;
+            var startTimestamp = context.StartTimestamp;
             var httpContext = context.HttpContext;
-            var hostingLog = HostingEventSource.Log;
+            var eventLogEnabled = hostingEventLog.IsEnabled();
+
+            // If startTimestamp is 0, don't call GetTimestamp, likely don't need the value
+            var currentTimestamp = (startTimestamp != 0) ? Stopwatch.GetTimestamp() : 0;
+
+            // To keep the hot path short we defer logging to non-inlines
             if (exception == null)
             {
-                var diagnoticsEnabled = _diagnosticSource.IsEnabled("Microsoft.AspNetCore.Hosting.EndRequest");
+                // No exception was thrown, request was sucessful
-                var currentTimestamp = (diagnoticsEnabled || context.StartTimestamp != 0) ? Stopwatch.GetTimestamp() : 0;
+                if (_diagnosticSource.IsEnabled(DiagnosticsEndRequestKey))
-
-                _logger.RequestFinished(httpContext, context.StartTimestamp, currentTimestamp);
-
-                if (diagnoticsEnabled)
                 {
-                    _diagnosticSource.Write("Microsoft.AspNetCore.Hosting.EndRequest", new { httpContext = httpContext, timestamp = currentTimestamp });
+                    // Diagnostics is enabled for EndRequest, but it may not be for BeginRequest
+                    // so call GetTimestamp if currentTimestamp is zero (from above)
+                    RecordEndRequestDiagnostics(
+                        httpContext, 
+                        (currentTimestamp != 0) ? currentTimestamp : Stopwatch.GetTimestamp());
                 }
             }
             else
             {
-                var diagnoticsEnabled = _diagnosticSource.IsEnabled("Microsoft.AspNetCore.Hosting.UnhandledException");
+                // Exception was thrown from request
-                var currentTimestamp = (diagnoticsEnabled || context.StartTimestamp != 0) ? Stopwatch.GetTimestamp() : 0;
+                if (_diagnosticSource.IsEnabled(DiagnosticsUnhandledExceptionKey))
-
-                _logger.RequestFinished(httpContext, context.StartTimestamp, currentTimestamp);
-
-                if (diagnoticsEnabled)
                 {
-                    _diagnosticSource.Write("Microsoft.AspNetCore.Hosting.UnhandledException", new { httpContext = httpContext, timestamp = currentTimestamp, exception = exception });
+                    // Diagnostics is enabled for UnhandledException, but it may not be for BeginRequest 
+                    // so call GetTimestamp if currentTimestamp is zero (from above)
+                    RecordUnhandledExceptionDiagnostics(
+                        httpContext, 
+                        (currentTimestamp != 0) ? currentTimestamp : Stopwatch.GetTimestamp(), 
+                        exception);
                 }
 
-                if (hostingLog.IsEnabled())
+                if (eventLogEnabled)
                 {
-                    hostingLog.UnhandledException();
+                    // Non-inline
+                    hostingEventLog.UnhandledException();
                 }
             }
 
-            if (hostingLog.IsEnabled())
+            // If startTimestamp was 0, then Information logging wasn't enabled at for this request (and calcuated time will be wildly wrong)
+            // Is used as proxy to reduce calls to virtual: _logger.IsEnabled(LogLevel.Information)
+            if (startTimestamp != 0)
             {
-                hostingLog.RequestStop();
+                // Non-inline
+                LogRequestFinished(httpContext, startTimestamp, currentTimestamp);
             }
 
+            // Logging Scope and context are finshed with
             context.Scope?.Dispose();
-
             _httpContextFactory.Dispose(httpContext);
+
+            if (eventLogEnabled)
+            {
+                // Non-inline
+                hostingEventLog.RequestStop();
+            }
         }
 
-        public Task ProcessRequestAsync(Context context)
+        [MethodImpl(MethodImplOptions.NoInlining)]
+        private void LogRequestStarting(HttpContext httpContext)
         {
-            return _application(context.HttpContext);
+            // IsEnabled is checked in the caller, so if we are here just log
+            _logger.Log(
+                logLevel: LogLevel.Information,
+                eventId: LoggerEventIds.RequestStarting,
+                state: new HostingRequestStartingLog(httpContext),
+                exception: null,
+                formatter: HostingRequestStartingLog.Callback);
+        }
+
+        [MethodImpl(MethodImplOptions.NoInlining)]
+        private void LogRequestFinished(HttpContext httpContext, long startTimestamp, long currentTimestamp)
+        {
+            // IsEnabled isn't checked in the caller, startTimestamp > 0 is used as a fast proxy check
+            // but that may be because diagnostics are enabled, which also uses startTimestamp, so check here
+            if (_logger.IsEnabled(LogLevel.Information))
+            {
+                var elapsed = new TimeSpan((long)(TimestampToTicks * (currentTimestamp - startTimestamp)));
+
+                _logger.Log(
+                    logLevel: LogLevel.Information,
+                    eventId: LoggerEventIds.RequestFinished,
+                    state: new HostingRequestFinishedLog(httpContext, elapsed),
+                    exception: null,
+                    formatter: HostingRequestFinishedLog.Callback);
+            }
+        }
+
+        [MethodImpl(MethodImplOptions.NoInlining)]
+        private void RecordBeginRequestDiagnostics(HttpContext httpContext, long startTimestamp)
+        {
+            _diagnosticSource.Write(
+                DiagnosticsBeginRequestKey,
+                new
+                {
+                    httpContext = httpContext,
+                    timestamp = startTimestamp
+                });
+        }
+
+        [MethodImpl(MethodImplOptions.NoInlining)]
+        private void RecordEndRequestDiagnostics(HttpContext httpContext, long currentTimestamp)
+        {
+            _diagnosticSource.Write(
+                DiagnosticsEndRequestKey,
+                new
+                {
+                    httpContext = httpContext,
+                    timestamp = currentTimestamp
+                });
+        }
+
+        [MethodImpl(MethodImplOptions.NoInlining)]
+        private void RecordUnhandledExceptionDiagnostics(HttpContext httpContext, long currentTimestamp, Exception exception)
+        {
+            _diagnosticSource.Write(
+                DiagnosticsUnhandledExceptionKey,
+                new
+                {
+                    httpContext = httpContext,
+                    timestamp = currentTimestamp,
+                    exception = exception
+                });
+        }
+
+        [MethodImpl(MethodImplOptions.NoInlining)]
+        private static void RecordRequestStartEventLog(HttpContext httpContext)
+        {
+            HostingEventSource.Log.RequestStart(httpContext.Request.Method, httpContext.Request.Path);
         }
 
         public struct Context

src/Microsoft.AspNetCore.Hosting/Internal/HostingEventSource.cs

@@ -2,7 +2,7 @@
 // Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
 
 using System.Diagnostics.Tracing;
-using Microsoft.AspNetCore.Http;
+using System.Runtime.CompilerServices;
 
 namespace Microsoft.AspNetCore.Hosting.Internal
 {
@@ -38,12 +38,14 @@ namespace Microsoft.AspNetCore.Hosting.Internal
             WriteEvent(3, method, path);
         }
 
+        [MethodImpl(MethodImplOptions.NoInlining)]
         [Event(4, Level = EventLevel.Informational)]
         public void RequestStop()
         {
             WriteEvent(4);
         }
 
+        [MethodImpl(MethodImplOptions.NoInlining)]
         [Event(5, Level = EventLevel.Error)]
         public void UnhandledException()
         {

src/Microsoft.AspNetCore.Hosting/Internal/HostingLoggerExtensions.cs

@@ -4,7 +4,6 @@
 using System;
 using System.Collections;
 using System.Collections.Generic;
-using System.Diagnostics;
 using System.Globalization;
 using System.Reflection;
 using Microsoft.AspNetCore.Http;
@@ -14,42 +13,11 @@ namespace Microsoft.AspNetCore.Hosting.Internal
 {
     internal static class HostingLoggerExtensions
     {
-        private static readonly double TimestampToTicks = TimeSpan.TicksPerSecond / (double)Stopwatch.Frequency;
-
         public static IDisposable RequestScope(this ILogger logger, HttpContext httpContext)
         {
             return logger.BeginScope(new HostingLogScope(httpContext));
         }
 
-        public static void RequestStarting(this ILogger logger, HttpContext httpContext)
-        {
-            if (logger.IsEnabled(LogLevel.Information))
-            {
-                logger.Log(
-                    logLevel: LogLevel.Information,
-                    eventId: LoggerEventIds.RequestStarting,
-                    state: new HostingRequestStarting(httpContext),
-                    exception: null,
-                    formatter: HostingRequestStarting.Callback);
-            }
-        }
-
-        public static void RequestFinished(this ILogger logger, HttpContext httpContext, long startTimestamp, long currentTimestamp)
-        {
-            // Don't log if Information logging wasn't enabled at start or end of request as time will be wildly wrong.
-            if (startTimestamp != 0)
-            {
-                var elapsed = new TimeSpan((long)(TimestampToTicks * (currentTimestamp - startTimestamp)));
-
-                logger.Log(
-                    logLevel: LogLevel.Information,
-                    eventId: LoggerEventIds.RequestFinished,
-                    state: new HostingRequestFinished(httpContext, elapsed),
-                    exception: null,
-                    formatter: HostingRequestFinished.Callback);
-            }
-        }
-
         public static void ApplicationError(this ILogger logger, Exception exception)
         {
             logger.ApplicationError(
@@ -168,162 +136,6 @@ namespace Microsoft.AspNetCore.Hosting.Internal
                 return GetEnumerator();
             }
         }
-
-        private class HostingRequestStarting : IReadOnlyList<KeyValuePair<string, object>>
-        {
-            internal static readonly Func<object, Exception, string> Callback = (state, exception) => ((HostingRequestStarting)state).ToString();
-
-            private readonly HttpRequest _request;
-
-            private string _cachedToString;
-
-            public int Count
-            {
-                get
-                {
-                    return 9;
-                }
-            }
-
-            public KeyValuePair<string, object> this[int index]
-            {
-                get
-                {
-                    switch (index)
-                    {
-                        case 0:
-                            return new KeyValuePair<string, object>("Protocol", _request.Protocol);
-                        case 1:
-                            return new KeyValuePair<string, object>("Method", _request.Method);
-                        case 2:
-                            return new KeyValuePair<string, object>("ContentType", _request.ContentType);
-                        case 3:
-                            return new KeyValuePair<string, object>("ContentLength", _request.ContentLength);
-                        case 4:
-                            return new KeyValuePair<string, object>("Scheme", _request.Scheme.ToString());
-                        case 5:
-                            return new KeyValuePair<string, object>("Host", _request.Host.ToString());
-                        case 6:
-                            return new KeyValuePair<string, object>("PathBase", _request.PathBase.ToString());
-                        case 7:
-                            return new KeyValuePair<string, object>("Path", _request.Path.ToString());
-                        case 8:
-                            return new KeyValuePair<string, object>("QueryString", _request.QueryString.ToString());
-                        default:
-                            throw new IndexOutOfRangeException(nameof(index));
-                    }
-                }
-            }
-
-            public HostingRequestStarting(HttpContext httpContext)
-            {
-                _request = httpContext.Request;
-            }
-
-            public override string ToString()
-            {
-                if (_cachedToString == null)
-                {
-                    _cachedToString = string.Format(
-                        CultureInfo.InvariantCulture,
-                        "Request starting {0} {1} {2}://{3}{4}{5}{6} {7} {8}",
-                        _request.Protocol,
-                        _request.Method,
-                        _request.Scheme,
-                        _request.Host,
-                        _request.PathBase,
-                        _request.Path,
-                        _request.QueryString,
-                        _request.ContentType,
-                        _request.ContentLength);
-                }
-
-                return _cachedToString;
-            }
-
-            public IEnumerator<KeyValuePair<string, object>> GetEnumerator()
-            {
-                for (int i = 0; i < Count; ++i)
-                {
-                    yield return this[i];
-                }
-            }
-
-            IEnumerator IEnumerable.GetEnumerator()
-            {
-                return GetEnumerator();
-            }
-        }
-
-        private class HostingRequestFinished : IReadOnlyList<KeyValuePair<string, object>>
-        {
-            internal static readonly Func<object, Exception, string> Callback = (state, exception) => ((HostingRequestFinished)state).ToString();
-
-            private readonly HttpContext _httpContext;
-            private readonly TimeSpan _elapsed;
-
-            private string _cachedToString;
-
-            public int Count
-            {
-                get
-                {
-                    return 3;
-                }
-            }
-
-            public KeyValuePair<string, object> this[int index]
-            {
-                get
-                {
-                    switch (index)
-                    {
-                        case 0:
-                            return new KeyValuePair<string, object>("ElapsedMilliseconds", _elapsed.TotalMilliseconds);
-                        case 1:
-                            return new KeyValuePair<string, object>("StatusCode", _httpContext.Response.StatusCode);
-                        case 2:
-                            return new KeyValuePair<string, object>("ContentType", _httpContext.Response.ContentType);
-                        default:
-                            throw new IndexOutOfRangeException(nameof(index));
-                    }
-                }
-            }
-
-            public HostingRequestFinished(HttpContext httpContext, TimeSpan elapsed)
-            {
-                _httpContext = httpContext;
-                _elapsed = elapsed;
-            }
-
-            public override string ToString()
-            {
-                if (_cachedToString == null)
-                {
-                    _cachedToString = string.Format(
-                        CultureInfo.InvariantCulture,
-                        "Request finished in {0}ms {1} {2}",
-                        _elapsed.TotalMilliseconds,
-                        _httpContext.Response.StatusCode,
-                        _httpContext.Response.ContentType);
-                }
-
-                return _cachedToString;
-            }
-
-            public IEnumerator<KeyValuePair<string, object>> GetEnumerator()
-            {
-                for (int i = 0; i < Count; ++i)
-                {
-                    yield return this[i];
-                }
-            }
-
-            IEnumerator IEnumerable.GetEnumerator()
-            {
-                return GetEnumerator();
-            }
-        }
     }
 }
 

src/Microsoft.AspNetCore.Hosting/Internal/HostingRequestFinishedLog.cs

@@ -0,0 +1,75 @@
+// 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.Collections;
+using System.Collections.Generic;
+using System.Globalization;
+using Microsoft.AspNetCore.Http;
+
+namespace Microsoft.AspNetCore.Hosting.Internal
+{
+    internal class HostingRequestFinishedLog : IReadOnlyList<KeyValuePair<string, object>>
+    {
+        internal static readonly Func<object, Exception, string> Callback = (state, exception) => ((HostingRequestFinishedLog)state).ToString();
+
+        private readonly HttpContext _httpContext;
+        private readonly TimeSpan _elapsed;
+
+        private string _cachedToString;
+
+        public int Count => 3;
+
+        public KeyValuePair<string, object> this[int index]
+        {
+            get
+            {
+                switch (index)
+                {
+                    case 0:
+                        return new KeyValuePair<string, object>("ElapsedMilliseconds", _elapsed.TotalMilliseconds);
+                    case 1:
+                        return new KeyValuePair<string, object>("StatusCode", _httpContext.Response.StatusCode);
+                    case 2:
+                        return new KeyValuePair<string, object>("ContentType", _httpContext.Response.ContentType);
+                    default:
+                        throw new IndexOutOfRangeException(nameof(index));
+                }
+            }
+        }
+
+        public HostingRequestFinishedLog(HttpContext httpContext, TimeSpan elapsed)
+        {
+            _httpContext = httpContext;
+            _elapsed = elapsed;
+        }
+
+        public override string ToString()
+        {
+            if (_cachedToString == null)
+            {
+                _cachedToString = string.Format(
+                    CultureInfo.InvariantCulture,
+                    "Request finished in {0}ms {1} {2}",
+                    _elapsed.TotalMilliseconds,
+                    _httpContext.Response.StatusCode,
+                    _httpContext.Response.ContentType);
+            }
+
+            return _cachedToString;
+        }
+
+        public IEnumerator<KeyValuePair<string, object>> GetEnumerator()
+        {
+            for (var i = 0; i < Count; i++)
+            {
+                yield return this[i];
+            }
+        }
+
+        IEnumerator IEnumerable.GetEnumerator()
+        {
+            return GetEnumerator();
+        }
+    }
+}

src/Microsoft.AspNetCore.Hosting/Internal/HostingRequestStartingLog.cs

@@ -0,0 +1,91 @@
+// 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.Collections;
+using System.Collections.Generic;
+using System.Globalization;
+using Microsoft.AspNetCore.Http;
+
+namespace Microsoft.AspNetCore.Hosting.Internal
+{
+    internal class HostingRequestStartingLog : IReadOnlyList<KeyValuePair<string, object>>
+    {
+        internal static readonly Func<object, Exception, string> Callback = (state, exception) => ((HostingRequestStartingLog)state).ToString();
+
+        private readonly HttpRequest _request;
+
+        private string _cachedToString;
+
+        public int Count => 9;
+
+        public KeyValuePair<string, object> this[int index]
+        {
+            get
+            {
+                switch (index)
+                {
+                    case 0:
+                        return new KeyValuePair<string, object>("Protocol", _request.Protocol);
+                    case 1:
+                        return new KeyValuePair<string, object>("Method", _request.Method);
+                    case 2:
+                        return new KeyValuePair<string, object>("ContentType", _request.ContentType);
+                    case 3:
+                        return new KeyValuePair<string, object>("ContentLength", _request.ContentLength);
+                    case 4:
+                        return new KeyValuePair<string, object>("Scheme", _request.Scheme.ToString());
+                    case 5:
+                        return new KeyValuePair<string, object>("Host", _request.Host.ToString());
+                    case 6:
+                        return new KeyValuePair<string, object>("PathBase", _request.PathBase.ToString());
+                    case 7:
+                        return new KeyValuePair<string, object>("Path", _request.Path.ToString());
+                    case 8:
+                        return new KeyValuePair<string, object>("QueryString", _request.QueryString.ToString());
+                    default:
+                        throw new IndexOutOfRangeException(nameof(index));
+                }
+            }
+        }
+
+        public HostingRequestStartingLog(HttpContext httpContext)
+        {
+            _request = httpContext.Request;
+        }
+
+        public override string ToString()
+        {
+            if (_cachedToString == null)
+            {
+                _cachedToString = string.Format(
+                    CultureInfo.InvariantCulture,
+                    "Request starting {0} {1} {2}://{3}{4}{5}{6} {7} {8}",
+                    _request.Protocol,
+                    _request.Method,
+                    _request.Scheme,
+                    _request.Host,
+                    _request.PathBase,
+                    _request.Path,
+                    _request.QueryString,
+                    _request.ContentType,
+                    _request.ContentLength);
+            }
+
+            return _cachedToString;
+        }
+
+        public IEnumerator<KeyValuePair<string, object>> GetEnumerator()
+        {
+            for (var i = 0; i < Count; i++)
+            {
+                yield return this[i];
+            }
+        }
+
+        IEnumerator IEnumerable.GetEnumerator()
+        {
+            return GetEnumerator();
+        }
+    }
+}