From f37375f43cd9e49ebcd61b62130d3455c8d41944 Mon Sep 17 00:00:00 2001 From: Louis DeJardin Date: Tue, 13 Oct 2015 14:10:26 -0700 Subject: [PATCH] Reduce logging overhead in hosting * TraceIdentifier is done at the last moment, or not at all * Request starting and finished messages are added * This pair provide many of the top-level values that you would have found in server log files. --- .../FastHttpRequestIdentifierFeature.cs | 65 ------ .../Internal/HostingEngine.cs | 41 ++-- .../Internal/HostingLoggerExtensions.cs | 189 ++++++++++++++++++ src/Microsoft.AspNet.Hosting/project.json | 3 +- .../HostingEngineTests.cs | 121 ++++++++++- .../FastHttpRequestIdentifierFeatureTests.cs | 44 ---- 6 files changed, 324 insertions(+), 139 deletions(-) delete mode 100644 src/Microsoft.AspNet.Hosting/Internal/FastHttpRequestIdentifierFeature.cs create mode 100644 src/Microsoft.AspNet.Hosting/Internal/HostingLoggerExtensions.cs delete mode 100644 test/Microsoft.AspNet.Hosting.Tests/Internal/FastHttpRequestIdentifierFeatureTests.cs diff --git a/src/Microsoft.AspNet.Hosting/Internal/FastHttpRequestIdentifierFeature.cs b/src/Microsoft.AspNet.Hosting/Internal/FastHttpRequestIdentifierFeature.cs deleted file mode 100644 index 95e78065..00000000 --- a/src/Microsoft.AspNet.Hosting/Internal/FastHttpRequestIdentifierFeature.cs +++ /dev/null @@ -1,65 +0,0 @@ -// 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.Threading; -using Microsoft.AspNet.Http.Features; - -namespace Microsoft.AspNet.Hosting.Internal -{ - public class FastHttpRequestIdentifierFeature : IHttpRequestIdentifierFeature - { - // Base64 encoding - but in ascii sort order for easy text based sorting - private static readonly string _encode32Chars = "0123456789ABCDEFGHIJKLMNOPQRSTUV"; - // Seed the _requestId for this application instance with - // the number of 100-nanosecond intervals that have elapsed since 12:00:00 midnight, January 1, 0001 - // for a roughly increasing _requestId over restarts - private static long _requestId = DateTime.UtcNow.Ticks; - - private string _id = null; - - public string TraceIdentifier - { - get - { - // Don't incur the cost of generating the request ID until it's asked for - if (_id == null) - { - _id = GenerateRequestId(Interlocked.Increment(ref _requestId)); - } - return _id; - } - set - { - _id = value; - } - } - - private static unsafe string GenerateRequestId(long id) - { - // The following routine is ~310% faster than calling long.ToString() on x64 - // and ~600% faster than calling long.ToString() on x86 in tight loops of 1 million+ iterations - // See: https://github.com/aspnet/Hosting/pull/385 - - // stackalloc to allocate array on stack rather than heap - char* charBuffer = stackalloc char[13]; - - charBuffer[0] = _encode32Chars[(int)(id >> 60) & 31]; - charBuffer[1] = _encode32Chars[(int)(id >> 55) & 31]; - charBuffer[2] = _encode32Chars[(int)(id >> 50) & 31]; - charBuffer[3] = _encode32Chars[(int)(id >> 45) & 31]; - charBuffer[4] = _encode32Chars[(int)(id >> 40) & 31]; - charBuffer[5] = _encode32Chars[(int)(id >> 35) & 31]; - charBuffer[6] = _encode32Chars[(int)(id >> 30) & 31]; - charBuffer[7] = _encode32Chars[(int)(id >> 25) & 31]; - charBuffer[8] = _encode32Chars[(int)(id >> 20) & 31]; - charBuffer[9] = _encode32Chars[(int)(id >> 15) & 31]; - charBuffer[10] = _encode32Chars[(int)(id >> 10) & 31]; - charBuffer[11] = _encode32Chars[(int)(id >> 5) & 31]; - charBuffer[12] = _encode32Chars[(int)id & 31]; - - // string ctor overload that takes char* - return new string(charBuffer, 0, 13); - } - } -} diff --git a/src/Microsoft.AspNet.Hosting/Internal/HostingEngine.cs b/src/Microsoft.AspNet.Hosting/Internal/HostingEngine.cs index 7bcad032..b68e2f7c 100644 --- a/src/Microsoft.AspNet.Hosting/Internal/HostingEngine.cs +++ b/src/Microsoft.AspNet.Hosting/Internal/HostingEngine.cs @@ -93,27 +93,34 @@ public virtual IApplication Start() { var httpContext = contextFactory.CreateHttpContext(features); httpContext.ApplicationServices = _applicationServices; - var requestIdentifier = GetRequestIdentifier(httpContext); + if (diagnosticSource.IsEnabled("Microsoft.AspNet.Hosting.BeginRequest")) { diagnosticSource.Write("Microsoft.AspNet.Hosting.BeginRequest", new { httpContext = httpContext }); } - try + + using (logger.RequestScope(httpContext)) { - using (logger.IsEnabled(LogLevel.Critical) - ? logger.BeginScope("Request Id: {RequestId}", requestIdentifier) - : null) + int startTime = 0; + try { + logger.RequestStarting(httpContext); + + startTime = Environment.TickCount; await application(httpContext); + + logger.RequestFinished(httpContext, startTime); } - } - catch (Exception ex) - { - if (diagnosticSource.IsEnabled("Microsoft.AspNet.Hosting.UnhandledException")) + catch (Exception ex) { - diagnosticSource.Write("Microsoft.AspNet.Hosting.UnhandledException", new { httpContext = httpContext, exception = ex }); + logger.RequestFailed(httpContext, startTime); + + if (diagnosticSource.IsEnabled("Microsoft.AspNet.Hosting.UnhandledException")) + { + diagnosticSource.Write("Microsoft.AspNet.Hosting.UnhandledException", new { httpContext = httpContext, exception = ex }); + } + throw; } - throw; } if (diagnosticSource.IsEnabled("Microsoft.AspNet.Hosting.EndRequest")) { @@ -266,18 +273,6 @@ private void EnsureServer() } } - private string GetRequestIdentifier(HttpContext httpContext) - { - var requestIdentifierFeature = httpContext.Features.Get(); - if (requestIdentifierFeature == null) - { - requestIdentifierFeature = new FastHttpRequestIdentifierFeature(); - httpContext.Features.Set(requestIdentifierFeature); - } - - return requestIdentifierFeature.TraceIdentifier; - } - private class Disposable : IDisposable { private Action _dispose; diff --git a/src/Microsoft.AspNet.Hosting/Internal/HostingLoggerExtensions.cs b/src/Microsoft.AspNet.Hosting/Internal/HostingLoggerExtensions.cs new file mode 100644 index 00000000..3f6b109c --- /dev/null +++ b/src/Microsoft.AspNet.Hosting/Internal/HostingLoggerExtensions.cs @@ -0,0 +1,189 @@ +// 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.Generic; +using System.Threading; +using Microsoft.AspNet.Http; +using Microsoft.Extensions.Logging; + +namespace Microsoft.AspNet.Hosting.Internal +{ + internal static class HostingLoggerExtensions + { + public static IDisposable RequestScope(this ILogger logger, HttpContext httpContext) + { + return logger.BeginScopeImpl(new HostingLogScope(httpContext)); + } + + public static void RequestStarting(this ILogger logger, HttpContext httpContext) + { + if (logger.IsEnabled(LogLevel.Information)) + { + logger.Log( + logLevel: LogLevel.Information, + eventId: 1, + state: new HostingRequestStarting(httpContext), + exception: null, + formatter: HostingRequestStarting.Callback); + } + } + + public static void RequestFinished(this ILogger logger, HttpContext httpContext, int startTimeInTicks) + { + if (logger.IsEnabled(LogLevel.Information)) + { + var elapsed = new TimeSpan(Environment.TickCount - startTimeInTicks); + logger.Log( + logLevel: LogLevel.Information, + eventId: 2, + state: new HostingRequestFinished(httpContext, elapsed), + exception: null, + formatter: HostingRequestFinished.Callback); + } + } + + public static void RequestFailed(this ILogger logger, HttpContext httpContext, int startTimeInTicks) + { + if (logger.IsEnabled(LogLevel.Information)) + { + var elapsed = new TimeSpan(Environment.TickCount - startTimeInTicks); + logger.Log( + logLevel: LogLevel.Information, + eventId: 2, + state: new HostingRequestFailed(httpContext, elapsed), + exception: null, + formatter: HostingRequestFailed.Callback); + } + } + + + private class HostingLogScope : ILogValues + { + private readonly HttpContext _httpContext; + + private string _cachedToString; + private IEnumerable> _cachedGetValues; + + public HostingLogScope(HttpContext httpContext) + { + _httpContext = httpContext; + } + + public override string ToString() => _cachedToString ?? Interlocked.CompareExchange( + ref _cachedToString, + $"RequestId:{_httpContext.TraceIdentifier} RequestPath:{_httpContext.Request.Path}", + null); + + public IEnumerable> GetValues() => _cachedGetValues ?? Interlocked.CompareExchange( + ref _cachedGetValues, + new[] + { + new KeyValuePair("RequestId", _httpContext.TraceIdentifier), + new KeyValuePair("RequestPath", _httpContext.Request.Path.ToString()), + }, + null); + } + + private class HostingRequestStarting : ILogValues + { + internal static readonly Func Callback = (state, exception) => ((HostingRequestStarting)state).ToString(); + + private readonly HttpContext _httpContext; + + private string _cachedToString; + private IEnumerable> _cachedGetValues; + + public HostingRequestStarting(HttpContext httpContext) + { + _httpContext = httpContext; + } + + public override string ToString() => _cachedToString ?? Interlocked.CompareExchange( + ref _cachedToString, + $"Request starting {_httpContext.Request.Protocol} {_httpContext.Request.Method} {_httpContext.Request.Scheme}://{_httpContext.Request.Host}{_httpContext.Request.PathBase}{_httpContext.Request.Path}{_httpContext.Request.QueryString} {_httpContext.Request.ContentType} {_httpContext.Request.ContentLength}", + null); + + public IEnumerable> GetValues() => _cachedGetValues ?? Interlocked.CompareExchange( + ref _cachedGetValues, + new[] + { + new KeyValuePair("Protocol", _httpContext.Request.Protocol), + new KeyValuePair("Method", _httpContext.Request.Method), + new KeyValuePair("ContentType", _httpContext.Request.ContentType), + new KeyValuePair("ContentLength", _httpContext.Request.ContentLength), + new KeyValuePair("Scheme", _httpContext.Request.Scheme.ToString()), + new KeyValuePair("Host", _httpContext.Request.Host.ToString()), + new KeyValuePair("PathBase", _httpContext.Request.PathBase.ToString()), + new KeyValuePair("Path", _httpContext.Request.Path.ToString()), + new KeyValuePair("QueryString", _httpContext.Request.QueryString.ToString()), + }, + null); + } + + private class HostingRequestFinished + { + internal static readonly Func Callback = (state, exception) => ((HostingRequestFinished)state).ToString(); + + private readonly HttpContext _httpContext; + private readonly TimeSpan _elapsed; + + private IEnumerable> _cachedGetValues; + private string _cachedToString; + + public HostingRequestFinished(HttpContext httpContext, TimeSpan elapsed) + { + _httpContext = httpContext; + _elapsed = elapsed; + } + + public override string ToString() => _cachedToString ?? Interlocked.CompareExchange( + ref _cachedToString, + $"Request finished in {_elapsed.TotalMilliseconds}ms {_httpContext.Response.StatusCode} {_httpContext.Response.ContentType}", + null); + + public IEnumerable> GetValues() => _cachedGetValues ?? Interlocked.CompareExchange( + ref _cachedGetValues, + new[] + { + new KeyValuePair("ElapsedMilliseconds", _elapsed.TotalMilliseconds), + new KeyValuePair("StatusCode", _httpContext.Response.StatusCode), + new KeyValuePair("ContentType", _httpContext.Response.ContentType), + }, + null); + } + + private class HostingRequestFailed + { + internal static readonly Func Callback = (state, exception) => ((HostingRequestFailed)state).ToString(); + + private readonly HttpContext _httpContext; + private readonly TimeSpan _elapsed; + + private IEnumerable> _cachedGetValues; + private string _cachedToString; + + public HostingRequestFailed(HttpContext httpContext, TimeSpan elapsed) + { + _httpContext = httpContext; + _elapsed = elapsed; + } + + public override string ToString() => _cachedToString ?? Interlocked.CompareExchange( + ref _cachedToString, + $"Request finished in {_elapsed.TotalMilliseconds}ms 500", + null); + + public IEnumerable> GetValues() => _cachedGetValues ?? Interlocked.CompareExchange( + ref _cachedGetValues, + new[] + { + new KeyValuePair("ElapsedMilliseconds", _elapsed.TotalMilliseconds), + new KeyValuePair("StatusCode", 500), + new KeyValuePair("ContentType", null), + }, + null); + } + } +} + diff --git a/src/Microsoft.AspNet.Hosting/project.json b/src/Microsoft.AspNet.Hosting/project.json index c5801b91..edd34b54 100644 --- a/src/Microsoft.AspNet.Hosting/project.json +++ b/src/Microsoft.AspNet.Hosting/project.json @@ -6,8 +6,7 @@ "url": "git://github.com/aspnet/hosting" }, "compilationOptions": { - "warningsAsErrors": true, - "allowUnsafe": true + "warningsAsErrors": true }, "dependencies": { "Microsoft.AspNet.FileProviders.Physical": "1.0.0-*", diff --git a/test/Microsoft.AspNet.Hosting.Tests/HostingEngineTests.cs b/test/Microsoft.AspNet.Hosting.Tests/HostingEngineTests.cs index 9467dba2..1d9ababa 100644 --- a/test/Microsoft.AspNet.Hosting.Tests/HostingEngineTests.cs +++ b/test/Microsoft.AspNet.Hosting.Tests/HostingEngineTests.cs @@ -14,13 +14,13 @@ using Microsoft.AspNet.Hosting.Startup; using Microsoft.AspNet.Http; using Microsoft.AspNet.Http.Features; -using Microsoft.AspNet.Http.Features.Internal; using Microsoft.AspNet.Server.Features; using Microsoft.AspNet.Testing.xunit; using Microsoft.Extensions.Configuration; using Microsoft.Extensions.DependencyInjection; -using Microsoft.Extensions.Internal; +using Microsoft.Extensions.Logging; using Microsoft.Extensions.OptionsModel; +using Microsoft.Extensions.Primitives; using Moq; using Xunit; @@ -29,7 +29,16 @@ namespace Microsoft.AspNet.Hosting public class HostingEngineTests : IServerFactory { private readonly IList _startInstances = new List(); - private IFeatureCollection _featuresSupportedByThisHost = new FeatureCollection(); + private IFeatureCollection _featuresSupportedByThisHost = NewFeatureCollection(); + + static IFeatureCollection NewFeatureCollection() + { + var stub = new StubFeatures(); + var features = new FeatureCollection(); + features[typeof(IHttpRequestFeature)] = stub; + features[typeof(IHttpResponseFeature)] = stub; + return features; + } [Fact] public void HostingEngineThrowsWithNoServer() @@ -314,7 +323,9 @@ public void HostingEngine_CreatesDefaultRequestIdentifierFeature_IfNotPresent() // Assert Assert.NotNull(httpContext); - Assert.IsType(httpContext.Features.Get()); + var featuresTraceIdentifier = httpContext.Features.Get().TraceIdentifier; + Assert.False(string.IsNullOrWhiteSpace(httpContext.TraceIdentifier)); + Assert.Same(httpContext.TraceIdentifier, featuresTraceIdentifier); } [Fact] @@ -393,7 +404,11 @@ private IHostingEngine CreateHostingEngine(RequestDelegate requestDelegate) var host = CreateBuilder() .UseServer(this) .UseStartup( - appBuilder => { appBuilder.Run(requestDelegate); }, + appBuilder => + { + appBuilder.ApplicationServices.GetRequiredService().AddProvider(new AllMessagesAreNeeded()); + appBuilder.Run(requestDelegate); + }, configureServices => configureServices.BuildServiceProvider()); return host.Build(); } @@ -498,5 +513,101 @@ private class ServerAddressesFeature : IServerAddressesFeature { public ICollection Addresses { get; } = new List(); } + + private class AllMessagesAreNeeded : ILoggerProvider, ILogger + { + public bool IsEnabled(LogLevel logLevel) => true; + + public ILogger CreateLogger(string name) => this; + + public IDisposable BeginScopeImpl(object state) + { + var stringified = state.ToString(); + return this; + } + public void Log(LogLevel logLevel, int eventId, object state, Exception exception, Func formatter) + { + var stringified = formatter(state, exception); + } + + public void Dispose() + { + } + } + + private class StubFeatures : IHttpRequestFeature, IHttpResponseFeature, IHeaderDictionary + { + public StubFeatures() + { + Headers = this; + Body = new MemoryStream(); + } + + public StringValues this[string key] + { + get { return StringValues.Empty; } + set { } + } + + public Stream Body { get; set; } + + public int Count => 0; + + public bool HasStarted { get; set; } + + public IHeaderDictionary Headers { get; set; } + + public bool IsReadOnly => false; + + public ICollection Keys => null; + + public string Method { get; set; } + + public string Path { get; set; } + + public string PathBase { get; set; } + + public string Protocol { get; set; } + + public string QueryString { get; set; } + + public string ReasonPhrase { get; set; } + + public string Scheme { get; set; } + + public int StatusCode { get; set; } + + public ICollection Values => null; + + public void Add(KeyValuePair item) { } + + public void Add(string key, StringValues value) { } + + public void Clear() { } + + public bool Contains(KeyValuePair item) => false; + + public bool ContainsKey(string key) => false; + + public void CopyTo(KeyValuePair[] array, int arrayIndex) { } + + public IEnumerator> GetEnumerator() => null; + + public void OnCompleted(Func callback, object state) { } + + public void OnStarting(Func callback, object state) { } + + public bool Remove(KeyValuePair item) => false; + + public bool Remove(string key) => false; + + public bool TryGetValue(string key, out StringValues value) + { + value = StringValues.Empty; + return false; + } + + IEnumerator IEnumerable.GetEnumerator() => null; + } } } diff --git a/test/Microsoft.AspNet.Hosting.Tests/Internal/FastHttpRequestIdentifierFeatureTests.cs b/test/Microsoft.AspNet.Hosting.Tests/Internal/FastHttpRequestIdentifierFeatureTests.cs deleted file mode 100644 index fff0fb60..00000000 --- a/test/Microsoft.AspNet.Hosting.Tests/Internal/FastHttpRequestIdentifierFeatureTests.cs +++ /dev/null @@ -1,44 +0,0 @@ -// 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 Microsoft.AspNet.Hosting.Internal; -using Xunit; - -namespace Microsoft.AspNet.Hosting.Tests.Internal -{ - public class FastHttpRequestIdentifierFeatureTests - { - [Fact] - public void TraceIdentifier_ReturnsId() - { - var feature = new FastHttpRequestIdentifierFeature(); - - var id = feature.TraceIdentifier; - - Assert.NotNull(id); - } - - [Fact] - public void TraceIdentifier_ReturnsStableId() - { - var feature = new FastHttpRequestIdentifierFeature(); - - var id1 = feature.TraceIdentifier; - var id2 = feature.TraceIdentifier; - - Assert.Equal(id1, id2); - } - - [Fact] - public void TraceIdentifier_ReturnsUniqueIdForDifferentInstances() - { - var feature1 = new FastHttpRequestIdentifierFeature(); - var feature2 = new FastHttpRequestIdentifierFeature(); - - var id1 = feature1.TraceIdentifier; - var id2 = feature2.TraceIdentifier; - - Assert.NotEqual(id1, id2); - } - } -}