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.

src/Microsoft.AspNet.Hosting/Internal/FastHttpRequestIdentifierFeature.cs

@@ -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);
-        }
-    }
-}

src/Microsoft.AspNet.Hosting/Internal/HostingEngine.cs

@@ -93,27 +93,34 @@ namespace Microsoft.AspNet.Hosting.Internal
                 {
                     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)
+                        int startTime = 0;
-                            ? logger.BeginScope("Request Id: {RequestId}", requestIdentifier) 
+                        try
-                            : null)
                         {
+                            logger.RequestStarting(httpContext);
+
+                            startTime = Environment.TickCount;
                             await application(httpContext);
+
+                            logger.RequestFinished(httpContext, startTime);
                         }
-                    }
+                        catch (Exception ex)
-                    catch (Exception ex)
-                    {
-                        if (diagnosticSource.IsEnabled("Microsoft.AspNet.Hosting.UnhandledException"))
                         {
-                            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 @@ namespace Microsoft.AspNet.Hosting.Internal
             }
         }
 
-        private string GetRequestIdentifier(HttpContext httpContext)
-        {
-            var requestIdentifierFeature = httpContext.Features.Get<IHttpRequestIdentifierFeature>();
-            if (requestIdentifierFeature == null)
-            {
-                requestIdentifierFeature = new FastHttpRequestIdentifierFeature();
-                httpContext.Features.Set(requestIdentifierFeature);
-            }
-
-            return requestIdentifierFeature.TraceIdentifier;
-        }
-
         private class Disposable : IDisposable
         {
             private Action _dispose;

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<KeyValuePair<string, object>> _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<KeyValuePair<string, object>> GetValues() => _cachedGetValues ?? Interlocked.CompareExchange(
+                ref _cachedGetValues,
+                new[]
+                {
+                    new KeyValuePair<string, object>("RequestId", _httpContext.TraceIdentifier),
+                    new KeyValuePair<string, object>("RequestPath", _httpContext.Request.Path.ToString()),
+                },
+                null);
+        }
+
+        private class HostingRequestStarting : ILogValues
+        {
+            internal static readonly Func<object, Exception, string> Callback = (state, exception) => ((HostingRequestStarting)state).ToString();
+
+            private readonly HttpContext _httpContext;
+
+            private string _cachedToString;
+            private IEnumerable<KeyValuePair<string, object>> _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<KeyValuePair<string, object>> GetValues() => _cachedGetValues ?? Interlocked.CompareExchange(
+                ref _cachedGetValues,
+                new[]
+                {
+                    new KeyValuePair<string, object>("Protocol", _httpContext.Request.Protocol),
+                    new KeyValuePair<string, object>("Method", _httpContext.Request.Method),
+                    new KeyValuePair<string, object>("ContentType", _httpContext.Request.ContentType),
+                    new KeyValuePair<string, object>("ContentLength", _httpContext.Request.ContentLength),
+                    new KeyValuePair<string, object>("Scheme", _httpContext.Request.Scheme.ToString()),
+                    new KeyValuePair<string, object>("Host", _httpContext.Request.Host.ToString()),
+                    new KeyValuePair<string, object>("PathBase", _httpContext.Request.PathBase.ToString()),
+                    new KeyValuePair<string, object>("Path", _httpContext.Request.Path.ToString()),
+                    new KeyValuePair<string, object>("QueryString", _httpContext.Request.QueryString.ToString()),
+                },
+                null);
+        }
+
+        private class HostingRequestFinished
+        {
+            internal static readonly Func<object, Exception, string> Callback = (state, exception) => ((HostingRequestFinished)state).ToString();
+
+            private readonly HttpContext _httpContext;
+            private readonly TimeSpan _elapsed;
+
+            private IEnumerable<KeyValuePair<string, object>> _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<KeyValuePair<string, object>> GetValues() => _cachedGetValues ?? Interlocked.CompareExchange(
+                ref _cachedGetValues,
+                new[]
+                {
+                    new KeyValuePair<string, object>("ElapsedMilliseconds", _elapsed.TotalMilliseconds),
+                    new KeyValuePair<string, object>("StatusCode", _httpContext.Response.StatusCode),
+                    new KeyValuePair<string, object>("ContentType", _httpContext.Response.ContentType),
+                },
+                null);
+        }
+
+        private class HostingRequestFailed
+        {
+            internal static readonly Func<object, Exception, string> Callback = (state, exception) => ((HostingRequestFailed)state).ToString();
+
+            private readonly HttpContext _httpContext;
+            private readonly TimeSpan _elapsed;
+
+            private IEnumerable<KeyValuePair<string, object>> _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<KeyValuePair<string, object>> GetValues() => _cachedGetValues ?? Interlocked.CompareExchange(
+                ref _cachedGetValues,
+                new[]
+                {
+                    new KeyValuePair<string, object>("ElapsedMilliseconds", _elapsed.TotalMilliseconds),
+                    new KeyValuePair<string, object>("StatusCode", 500),
+                    new KeyValuePair<string, object>("ContentType", null),
+                },
+                null);
+        }
+    }
+}
+

src/Microsoft.AspNet.Hosting/project.json

@@ -6,8 +6,7 @@
     "url": "git://github.com/aspnet/hosting"
   },
   "compilationOptions": {
-    "warningsAsErrors": true,
+    "warningsAsErrors": true
-    "allowUnsafe": true
   },
   "dependencies": {
     "Microsoft.AspNet.FileProviders.Physical": "1.0.0-*",

test/Microsoft.AspNet.Hosting.Tests/HostingEngineTests.cs

@@ -14,13 +14,13 @@ using Microsoft.AspNet.Hosting.Server;
 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<StartInstance> _startInstances = new List<StartInstance>();
-        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 @@ namespace Microsoft.AspNet.Hosting
 
             // Assert
             Assert.NotNull(httpContext);
-            Assert.IsType<FastHttpRequestIdentifierFeature>(httpContext.Features.Get<IHttpRequestIdentifierFeature>());
+            var featuresTraceIdentifier = httpContext.Features.Get<IHttpRequestIdentifierFeature>().TraceIdentifier;
+            Assert.False(string.IsNullOrWhiteSpace(httpContext.TraceIdentifier));
+            Assert.Same(httpContext.TraceIdentifier, featuresTraceIdentifier);
         }
 
         [Fact]
@@ -393,7 +404,11 @@ namespace Microsoft.AspNet.Hosting
             var host = CreateBuilder()
                 .UseServer(this)
                 .UseStartup(
-                    appBuilder => { appBuilder.Run(requestDelegate); },
+                    appBuilder =>
+                    {
+                        appBuilder.ApplicationServices.GetRequiredService<ILoggerFactory>().AddProvider(new AllMessagesAreNeeded());
+                        appBuilder.Run(requestDelegate);
+                    },
                     configureServices => configureServices.BuildServiceProvider());
             return host.Build();
         }
@@ -498,5 +513,101 @@ namespace Microsoft.AspNet.Hosting
         {
             public ICollection<string> Addresses { get; } = new List<string>();
         }
+
+        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<object, Exception, string> 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<string> 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<StringValues> Values => null;
+
+            public void Add(KeyValuePair<string, StringValues> item) { }
+
+            public void Add(string key, StringValues value) { }
+
+            public void Clear() { }
+
+            public bool Contains(KeyValuePair<string, StringValues> item) => false;
+
+            public bool ContainsKey(string key) => false;
+
+            public void CopyTo(KeyValuePair<string, StringValues>[] array, int arrayIndex) { }
+
+            public IEnumerator<KeyValuePair<string, StringValues>> GetEnumerator() => null;
+
+            public void OnCompleted(Func<object, Task> callback, object state) { }
+
+            public void OnStarting(Func<object, Task> callback, object state) { }
+
+            public bool Remove(KeyValuePair<string, StringValues> 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;
+        }
     }
 }

test/Microsoft.AspNet.Hosting.Tests/Internal/FastHttpRequestIdentifierFeatureTests.cs

@@ -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);
-        }
-    }
-}