Skip to content
This repository was archived by the owner on Dec 19, 2018. It is now read-only.

Commit 2796353

Browse files
lodejardlodejard
committed
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.
1 parent 9a12085 commit 2796353

File tree

2 files changed

+149
-12
lines changed

2 files changed

+149
-12
lines changed

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

Lines changed: 14 additions & 12 deletions
Original file line numberDiff line numberDiff line change
@@ -96,32 +96,34 @@ public virtual IApplication Start()
9696
{
9797
var httpContext = contextFactory.CreateHttpContext(features);
9898
httpContext.ApplicationServices = _applicationServices;
99-
var requestIdentifier = GetRequestIdentifier(httpContext);
10099
contextAccessor.HttpContext = httpContext;
101100
#pragma warning disable 0618
102101
if (telemetrySource.IsEnabled("Microsoft.AspNet.Hosting.BeginRequest"))
103102
{
104103
telemetrySource.WriteTelemetry("Microsoft.AspNet.Hosting.BeginRequest", new { httpContext = httpContext });
105104
}
106105
#pragma warning restore 0618
107-
try
106+
using (logger.RequestScope(httpContext))
108107
{
109-
using (logger.IsEnabled(LogLevel.Critical)
110-
? logger.BeginScope("Request Id: {RequestId}", requestIdentifier)
111-
: null)
108+
try
112109
{
110+
logger.RequestStarting(httpContext);
113111
await application(httpContext);
114112
}
115-
}
116-
catch (Exception ex)
117-
{
113+
catch (Exception ex)
114+
{
118115
#pragma warning disable 0618
119-
if (telemetrySource.IsEnabled("Microsoft.AspNet.Hosting.UnhandledException"))
116+
if (telemetrySource.IsEnabled("Microsoft.AspNet.Hosting.UnhandledException"))
117+
{
118+
telemetrySource.WriteTelemetry("Microsoft.AspNet.Hosting.UnhandledException", new { httpContext = httpContext, exception = ex });
119+
}
120+
#pragma warning restore 0618
121+
throw;
122+
}
123+
finally
120124
{
121-
telemetrySource.WriteTelemetry("Microsoft.AspNet.Hosting.UnhandledException", new { httpContext = httpContext, exception = ex });
125+
logger.RequestFinished(httpContext);
122126
}
123-
#pragma warning restore 0618
124-
throw;
125127
}
126128
#pragma warning disable 0618
127129
if (telemetrySource.IsEnabled("Microsoft.AspNet.Hosting.EndRequest"))

‎src/Microsoft.AspNet.Hosting/Internal/HostingLoggerExtensions.cs‎

Lines changed: 135 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,135 @@
1+
// Copyright (c) .NET Foundation. All rights reserved.
2+
// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information.
3+
4+
using System;
5+
using System.Collections.Generic;
6+
using System.Threading;
7+
using Microsoft.AspNet.Http;
8+
using Microsoft.AspNet.Http.Features;
9+
using Microsoft.Extensions.Logging;
10+
11+
namespace Microsoft.AspNet.Hosting.Internal
12+
{
13+
internal static class HostingLoggerExtensions
14+
{
15+
public static IDisposable RequestScope(this ILogger logger, HttpContext httpContext)
16+
{
17+
return logger.BeginScopeImpl(new HostingRequestScope(httpContext));
18+
}
19+
20+
public static void RequestStarting(this ILogger logger, HttpContext httpContext)
21+
{
22+
if (logger.IsEnabled(LogLevel.Information))
23+
{
24+
logger.Log(LogLevel.Information, 1, new HostingRequestStarting(httpContext), null, HostingRequestStarting.Callback);
25+
}
26+
}
27+
28+
public static void RequestFinished(this ILogger logger, HttpContext httpContext)
29+
{
30+
if (logger.IsEnabled(LogLevel.Information))
31+
{
32+
logger.Log(LogLevel.Information, 2, new HostingRequestFinished(httpContext), null, HostingRequestFinished.Callback);
33+
}
34+
}
35+
36+
private class HostingRequestScope : ILogValues
37+
{
38+
private readonly HttpContext _httpContext;
39+
40+
private FeatureReference<IHttpRequestIdentifierFeature> _requestIdentifierFeatureReference;
41+
private IEnumerable<KeyValuePair<string, object>> _cachedGetValues;
42+
private string _cachedToString;
43+
44+
public HostingRequestScope(HttpContext httpContext)
45+
{
46+
this._httpContext = httpContext;
47+
}
48+
49+
public IHttpRequestIdentifierFeature RequestIdFeature =>
50+
_requestIdentifierFeatureReference.Fetch(_httpContext.Features) ??
51+
_requestIdentifierFeatureReference.Update(_httpContext.Features, new FastHttpRequestIdentifierFeature());
52+
53+
public override string ToString() => _cachedToString ?? Interlocked.CompareExchange(
54+
ref _cachedToString,
55+
$"RequestId:{RequestIdFeature.TraceIdentifier} RequestPath:{_httpContext.Request.Path}",
56+
null);
57+
58+
public IEnumerable<KeyValuePair<string, object>> GetValues() => _cachedGetValues ?? Interlocked.CompareExchange(
59+
ref _cachedGetValues,
60+
new[]
61+
{
62+
new KeyValuePair<string, object>("RequestId", RequestIdFeature.TraceIdentifier),
63+
new KeyValuePair<string, object>("RequestPath", _httpContext.Request.Path.ToString()),
64+
},
65+
null);
66+
}
67+
68+
private class HostingRequestStarting : ILogValues
69+
{
70+
internal static readonly Func<object, Exception, string> Callback = (state, exception) => ((HostingRequestStarting)state).ToString();
71+
72+
private readonly HttpContext _httpContext;
73+
private IEnumerable<KeyValuePair<string, object>> _cachedGetValues;
74+
private string _cachedToString;
75+
76+
public HostingRequestStarting(HttpContext httpContext)
77+
{
78+
_httpContext = httpContext;
79+
}
80+
81+
public override string ToString() => _cachedToString ?? Interlocked.CompareExchange(
82+
ref _cachedToString,
83+
$"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}",
84+
null);
85+
86+
public IEnumerable<KeyValuePair<string, object>> GetValues() => _cachedGetValues ?? Interlocked.CompareExchange(
87+
ref _cachedGetValues,
88+
new[]
89+
{
90+
new KeyValuePair<string, object>("EventName", "RequestStarting"),
91+
new KeyValuePair<string, object>("Protocol", _httpContext.Request.Protocol),
92+
new KeyValuePair<string, object>("Method", _httpContext.Request.Method),
93+
new KeyValuePair<string, object>("ContentType", _httpContext.Request.ContentType),
94+
new KeyValuePair<string, object>("ContentLength", _httpContext.Request.ContentLength),
95+
new KeyValuePair<string, object>("Scheme", _httpContext.Request.Scheme.ToString()),
96+
new KeyValuePair<string, object>("Host", _httpContext.Request.Host.ToString()),
97+
new KeyValuePair<string, object>("PathBase", _httpContext.Request.PathBase.ToString()),
98+
new KeyValuePair<string, object>("Path", _httpContext.Request.Path.ToString()),
99+
new KeyValuePair<string, object>("QueryString", _httpContext.Request.QueryString.ToString()),
100+
},
101+
null);
102+
}
103+
104+
private class HostingRequestFinished
105+
{
106+
internal static readonly Func<object, Exception, string> Callback = (state, exception) => ((HostingRequestFinished)state).ToString();
107+
108+
private readonly HttpContext _httpContext;
109+
private IEnumerable<KeyValuePair<string, object>> _cachedGetValues;
110+
private string _cachedToString;
111+
112+
public HostingRequestFinished(HttpContext httpContext)
113+
{
114+
_httpContext = httpContext;
115+
}
116+
117+
public override string ToString() => _cachedToString ?? Interlocked.CompareExchange(
118+
ref _cachedToString,
119+
$"Request finished {_httpContext.Response.StatusCode} {_httpContext.Response.ContentType} {_httpContext.Response.Body.Length}",
120+
null);
121+
122+
public IEnumerable<KeyValuePair<string, object>> GetValues() => _cachedGetValues ?? Interlocked.CompareExchange(
123+
ref _cachedGetValues,
124+
new[]
125+
{
126+
new KeyValuePair<string, object>("EventName", "RequestFinished"),
127+
new KeyValuePair<string, object>("StatusCode", _httpContext.Response.StatusCode),
128+
new KeyValuePair<string, object>("ContentType", _httpContext.Response.ContentType),
129+
new KeyValuePair<string, object>("BodyLength", _httpContext.Response.Body.Length),
130+
},
131+
null);
132+
}
133+
}
134+
}
135+

0 commit comments

Comments
 (0)