From d5ec0859e5496f83ca32bf8bfb68ce3c3efe832f Mon Sep 17 00:00:00 2001 From: Ben Adams Date: Fri, 17 Feb 2017 16:43:25 +0000 Subject: [PATCH] Disabled logging fast-path (#937) --- .../Internal/HostingApplication.cs | 181 ++++++++++++++--- .../Internal/HostingEventSource.cs | 4 +- .../Internal/HostingLoggerExtensions.cs | 188 ------------------ .../Internal/HostingRequestFinishedLog.cs | 75 +++++++ .../Internal/HostingRequestStartingLog.cs | 91 +++++++++ 5 files changed, 318 insertions(+), 221 deletions(-) create mode 100644 src/Microsoft.AspNetCore.Hosting/Internal/HostingRequestFinishedLog.cs create mode 100644 src/Microsoft.AspNetCore.Hosting/Internal/HostingRequestStartingLog.cs diff --git a/src/Microsoft.AspNetCore.Hosting/Internal/HostingApplication.cs b/src/Microsoft.AspNetCore.Hosting/Internal/HostingApplication.cs index 5f95916e89..c44d58d5e6 100644 --- a/src/Microsoft.AspNetCore.Hosting/Internal/HostingApplication.cs +++ b/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 { + 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 }); - } - - var hostingLog = HostingEventSource.Log; - if (hostingLog.IsEnabled()) - { - hostingLog.RequestStart(httpContext.Request.Method, httpContext.Request.Path); + // Non-inline + RecordBeginRequestDiagnostics(httpContext, startTimestamp); } + // 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"); - var currentTimestamp = (diagnoticsEnabled || context.StartTimestamp != 0) ? Stopwatch.GetTimestamp() : 0; - - _logger.RequestFinished(httpContext, context.StartTimestamp, currentTimestamp); - - if (diagnoticsEnabled) + // No exception was thrown, request was sucessful + if (_diagnosticSource.IsEnabled(DiagnosticsEndRequestKey)) { - _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"); - var currentTimestamp = (diagnoticsEnabled || context.StartTimestamp != 0) ? Stopwatch.GetTimestamp() : 0; - - _logger.RequestFinished(httpContext, context.StartTimestamp, currentTimestamp); - - if (diagnoticsEnabled) + // Exception was thrown from request + if (_diagnosticSource.IsEnabled(DiagnosticsUnhandledExceptionKey)) { - _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 diff --git a/src/Microsoft.AspNetCore.Hosting/Internal/HostingEventSource.cs b/src/Microsoft.AspNetCore.Hosting/Internal/HostingEventSource.cs index 82ec37c2c9..199f8aae85 100644 --- a/src/Microsoft.AspNetCore.Hosting/Internal/HostingEventSource.cs +++ b/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() { diff --git a/src/Microsoft.AspNetCore.Hosting/Internal/HostingLoggerExtensions.cs b/src/Microsoft.AspNetCore.Hosting/Internal/HostingLoggerExtensions.cs index 35072a3972..37912b3f47 100644 --- a/src/Microsoft.AspNetCore.Hosting/Internal/HostingLoggerExtensions.cs +++ b/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> - { - internal static readonly Func Callback = (state, exception) => ((HostingRequestStarting)state).ToString(); - - private readonly HttpRequest _request; - - private string _cachedToString; - - public int Count - { - get - { - return 9; - } - } - - public KeyValuePair this[int index] - { - get - { - switch (index) - { - case 0: - return new KeyValuePair("Protocol", _request.Protocol); - case 1: - return new KeyValuePair("Method", _request.Method); - case 2: - return new KeyValuePair("ContentType", _request.ContentType); - case 3: - return new KeyValuePair("ContentLength", _request.ContentLength); - case 4: - return new KeyValuePair("Scheme", _request.Scheme.ToString()); - case 5: - return new KeyValuePair("Host", _request.Host.ToString()); - case 6: - return new KeyValuePair("PathBase", _request.PathBase.ToString()); - case 7: - return new KeyValuePair("Path", _request.Path.ToString()); - case 8: - return new KeyValuePair("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> GetEnumerator() - { - for (int i = 0; i < Count; ++i) - { - yield return this[i]; - } - } - - IEnumerator IEnumerable.GetEnumerator() - { - return GetEnumerator(); - } - } - - private class HostingRequestFinished : IReadOnlyList> - { - internal static readonly Func 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 this[int index] - { - get - { - switch (index) - { - case 0: - return new KeyValuePair("ElapsedMilliseconds", _elapsed.TotalMilliseconds); - case 1: - return new KeyValuePair("StatusCode", _httpContext.Response.StatusCode); - case 2: - return new KeyValuePair("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> GetEnumerator() - { - for (int i = 0; i < Count; ++i) - { - yield return this[i]; - } - } - - IEnumerator IEnumerable.GetEnumerator() - { - return GetEnumerator(); - } - } } } diff --git a/src/Microsoft.AspNetCore.Hosting/Internal/HostingRequestFinishedLog.cs b/src/Microsoft.AspNetCore.Hosting/Internal/HostingRequestFinishedLog.cs new file mode 100644 index 0000000000..ab440481ba --- /dev/null +++ b/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> + { + internal static readonly Func Callback = (state, exception) => ((HostingRequestFinishedLog)state).ToString(); + + private readonly HttpContext _httpContext; + private readonly TimeSpan _elapsed; + + private string _cachedToString; + + public int Count => 3; + + public KeyValuePair this[int index] + { + get + { + switch (index) + { + case 0: + return new KeyValuePair("ElapsedMilliseconds", _elapsed.TotalMilliseconds); + case 1: + return new KeyValuePair("StatusCode", _httpContext.Response.StatusCode); + case 2: + return new KeyValuePair("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> GetEnumerator() + { + for (var i = 0; i < Count; i++) + { + yield return this[i]; + } + } + + IEnumerator IEnumerable.GetEnumerator() + { + return GetEnumerator(); + } + } +} diff --git a/src/Microsoft.AspNetCore.Hosting/Internal/HostingRequestStartingLog.cs b/src/Microsoft.AspNetCore.Hosting/Internal/HostingRequestStartingLog.cs new file mode 100644 index 0000000000..e0162cacdd --- /dev/null +++ b/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> + { + internal static readonly Func Callback = (state, exception) => ((HostingRequestStartingLog)state).ToString(); + + private readonly HttpRequest _request; + + private string _cachedToString; + + public int Count => 9; + + public KeyValuePair this[int index] + { + get + { + switch (index) + { + case 0: + return new KeyValuePair("Protocol", _request.Protocol); + case 1: + return new KeyValuePair("Method", _request.Method); + case 2: + return new KeyValuePair("ContentType", _request.ContentType); + case 3: + return new KeyValuePair("ContentLength", _request.ContentLength); + case 4: + return new KeyValuePair("Scheme", _request.Scheme.ToString()); + case 5: + return new KeyValuePair("Host", _request.Host.ToString()); + case 6: + return new KeyValuePair("PathBase", _request.PathBase.ToString()); + case 7: + return new KeyValuePair("Path", _request.Path.ToString()); + case 8: + return new KeyValuePair("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> GetEnumerator() + { + for (var i = 0; i < Count; i++) + { + yield return this[i]; + } + } + + IEnumerator IEnumerable.GetEnumerator() + { + return GetEnumerator(); + } + } +}