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

Commit 8cdff72

Browse files
lodejardrynowak
lodejard
authored and
rynowak
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 56256a0 commit 8cdff72

File tree

6 files changed

+324
-139
lines changed

6 files changed

+324
-139
lines changed

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

Lines changed: 0 additions & 65 deletions
This file was deleted.

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

Lines changed: 18 additions & 23 deletions
Original file line numberDiff line numberDiff line change
@@ -93,27 +93,34 @@ public virtual IApplication Start()
9393
{
9494
var httpContext = contextFactory.CreateHttpContext(features);
9595
httpContext.ApplicationServices = _applicationServices;
96-
var requestIdentifier = GetRequestIdentifier(httpContext);
96+
9797
if (diagnosticSource.IsEnabled("Microsoft.AspNet.Hosting.BeginRequest"))
9898
{
9999
diagnosticSource.Write("Microsoft.AspNet.Hosting.BeginRequest", new { httpContext = httpContext });
100100
}
101-
try
101+
102+
using (logger.RequestScope(httpContext))
102103
{
103-
using (logger.IsEnabled(LogLevel.Critical)
104-
? logger.BeginScope("Request Id: {RequestId}", requestIdentifier)
105-
: null)
104+
int startTime = 0;
105+
try
106106
{
107+
logger.RequestStarting(httpContext);
108+
109+
startTime = Environment.TickCount;
107110
await application(httpContext);
111+
112+
logger.RequestFinished(httpContext, startTime);
108113
}
109-
}
110-
catch (Exception ex)
111-
{
112-
if (diagnosticSource.IsEnabled("Microsoft.AspNet.Hosting.UnhandledException"))
114+
catch (Exception ex)
113115
{
114-
diagnosticSource.Write("Microsoft.AspNet.Hosting.UnhandledException", new { httpContext = httpContext, exception = ex });
116+
logger.RequestFailed(httpContext, startTime);
117+
118+
if (diagnosticSource.IsEnabled("Microsoft.AspNet.Hosting.UnhandledException"))
119+
{
120+
diagnosticSource.Write("Microsoft.AspNet.Hosting.UnhandledException", new { httpContext = httpContext, exception = ex });
121+
}
122+
throw;
115123
}
116-
throw;
117124
}
118125
if (diagnosticSource.IsEnabled("Microsoft.AspNet.Hosting.EndRequest"))
119126
{
@@ -266,18 +273,6 @@ private void EnsureServer()
266273
}
267274
}
268275

269-
private string GetRequestIdentifier(HttpContext httpContext)
270-
{
271-
var requestIdentifierFeature = httpContext.Features.Get<IHttpRequestIdentifierFeature>();
272-
if (requestIdentifierFeature == null)
273-
{
274-
requestIdentifierFeature = new FastHttpRequestIdentifierFeature();
275-
httpContext.Features.Set(requestIdentifierFeature);
276-
}
277-
278-
return requestIdentifierFeature.TraceIdentifier;
279-
}
280-
281276
private class Disposable : IDisposable
282277
{
283278
private Action _dispose;

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

Lines changed: 189 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,189 @@
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.Extensions.Logging;
9+
10+
namespace Microsoft.AspNet.Hosting.Internal
11+
{
12+
internal static class HostingLoggerExtensions
13+
{
14+
public static IDisposable RequestScope(this ILogger logger, HttpContext httpContext)
15+
{
16+
return logger.BeginScopeImpl(new HostingLogScope(httpContext));
17+
}
18+
19+
public static void RequestStarting(this ILogger logger, HttpContext httpContext)
20+
{
21+
if (logger.IsEnabled(LogLevel.Information))
22+
{
23+
logger.Log(
24+
logLevel: LogLevel.Information,
25+
eventId: 1,
26+
state: new HostingRequestStarting(httpContext),
27+
exception: null,
28+
formatter: HostingRequestStarting.Callback);
29+
}
30+
}
31+
32+
public static void RequestFinished(this ILogger logger, HttpContext httpContext, int startTimeInTicks)
33+
{
34+
if (logger.IsEnabled(LogLevel.Information))
35+
{
36+
var elapsed = new TimeSpan(Environment.TickCount - startTimeInTicks);
37+
logger.Log(
38+
logLevel: LogLevel.Information,
39+
eventId: 2,
40+
state: new HostingRequestFinished(httpContext, elapsed),
41+
exception: null,
42+
formatter: HostingRequestFinished.Callback);
43+
}
44+
}
45+
46+
public static void RequestFailed(this ILogger logger, HttpContext httpContext, int startTimeInTicks)
47+
{
48+
if (logger.IsEnabled(LogLevel.Information))
49+
{
50+
var elapsed = new TimeSpan(Environment.TickCount - startTimeInTicks);
51+
logger.Log(
52+
logLevel: LogLevel.Information,
53+
eventId: 2,
54+
state: new HostingRequestFailed(httpContext, elapsed),
55+
exception: null,
56+
formatter: HostingRequestFailed.Callback);
57+
}
58+
}
59+
60+
61+
private class HostingLogScope : ILogValues
62+
{
63+
private readonly HttpContext _httpContext;
64+
65+
private string _cachedToString;
66+
private IEnumerable<KeyValuePair<string, object>> _cachedGetValues;
67+
68+
public HostingLogScope(HttpContext httpContext)
69+
{
70+
_httpContext = httpContext;
71+
}
72+
73+
public override string ToString() => _cachedToString ?? Interlocked.CompareExchange(
74+
ref _cachedToString,
75+
$"RequestId:{_httpContext.TraceIdentifier} RequestPath:{_httpContext.Request.Path}",
76+
null);
77+
78+
public IEnumerable<KeyValuePair<string, object>> GetValues() => _cachedGetValues ?? Interlocked.CompareExchange(
79+
ref _cachedGetValues,
80+
new[]
81+
{
82+
new KeyValuePair<string, object>("RequestId", _httpContext.TraceIdentifier),
83+
new KeyValuePair<string, object>("RequestPath", _httpContext.Request.Path.ToString()),
84+
},
85+
null);
86+
}
87+
88+
private class HostingRequestStarting : ILogValues
89+
{
90+
internal static readonly Func<object, Exception, string> Callback = (state, exception) => ((HostingRequestStarting)state).ToString();
91+
92+
private readonly HttpContext _httpContext;
93+
94+
private string _cachedToString;
95+
private IEnumerable<KeyValuePair<string, object>> _cachedGetValues;
96+
97+
public HostingRequestStarting(HttpContext httpContext)
98+
{
99+
_httpContext = httpContext;
100+
}
101+
102+
public override string ToString() => _cachedToString ?? Interlocked.CompareExchange(
103+
ref _cachedToString,
104+
$"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}",
105+
null);
106+
107+
public IEnumerable<KeyValuePair<string, object>> GetValues() => _cachedGetValues ?? Interlocked.CompareExchange(
108+
ref _cachedGetValues,
109+
new[]
110+
{
111+
new KeyValuePair<string, object>("Protocol", _httpContext.Request.Protocol),
112+
new KeyValuePair<string, object>("Method", _httpContext.Request.Method),
113+
new KeyValuePair<string, object>("ContentType", _httpContext.Request.ContentType),
114+
new KeyValuePair<string, object>("ContentLength", _httpContext.Request.ContentLength),
115+
new KeyValuePair<string, object>("Scheme", _httpContext.Request.Scheme.ToString()),
116+
new KeyValuePair<string, object>("Host", _httpContext.Request.Host.ToString()),
117+
new KeyValuePair<string, object>("PathBase", _httpContext.Request.PathBase.ToString()),
118+
new KeyValuePair<string, object>("Path", _httpContext.Request.Path.ToString()),
119+
new KeyValuePair<string, object>("QueryString", _httpContext.Request.QueryString.ToString()),
120+
},
121+
null);
122+
}
123+
124+
private class HostingRequestFinished
125+
{
126+
internal static readonly Func<object, Exception, string> Callback = (state, exception) => ((HostingRequestFinished)state).ToString();
127+
128+
private readonly HttpContext _httpContext;
129+
private readonly TimeSpan _elapsed;
130+
131+
private IEnumerable<KeyValuePair<string, object>> _cachedGetValues;
132+
private string _cachedToString;
133+
134+
public HostingRequestFinished(HttpContext httpContext, TimeSpan elapsed)
135+
{
136+
_httpContext = httpContext;
137+
_elapsed = elapsed;
138+
}
139+
140+
public override string ToString() => _cachedToString ?? Interlocked.CompareExchange(
141+
ref _cachedToString,
142+
$"Request finished in {_elapsed.TotalMilliseconds}ms {_httpContext.Response.StatusCode} {_httpContext.Response.ContentType}",
143+
null);
144+
145+
public IEnumerable<KeyValuePair<string, object>> GetValues() => _cachedGetValues ?? Interlocked.CompareExchange(
146+
ref _cachedGetValues,
147+
new[]
148+
{
149+
new KeyValuePair<string, object>("ElapsedMilliseconds", _elapsed.TotalMilliseconds),
150+
new KeyValuePair<string, object>("StatusCode", _httpContext.Response.StatusCode),
151+
new KeyValuePair<string, object>("ContentType", _httpContext.Response.ContentType),
152+
},
153+
null);
154+
}
155+
156+
private class HostingRequestFailed
157+
{
158+
internal static readonly Func<object, Exception, string> Callback = (state, exception) => ((HostingRequestFailed)state).ToString();
159+
160+
private readonly HttpContext _httpContext;
161+
private readonly TimeSpan _elapsed;
162+
163+
private IEnumerable<KeyValuePair<string, object>> _cachedGetValues;
164+
private string _cachedToString;
165+
166+
public HostingRequestFailed(HttpContext httpContext, TimeSpan elapsed)
167+
{
168+
_httpContext = httpContext;
169+
_elapsed = elapsed;
170+
}
171+
172+
public override string ToString() => _cachedToString ?? Interlocked.CompareExchange(
173+
ref _cachedToString,
174+
$"Request finished in {_elapsed.TotalMilliseconds}ms 500",
175+
null);
176+
177+
public IEnumerable<KeyValuePair<string, object>> GetValues() => _cachedGetValues ?? Interlocked.CompareExchange(
178+
ref _cachedGetValues,
179+
new[]
180+
{
181+
new KeyValuePair<string, object>("ElapsedMilliseconds", _elapsed.TotalMilliseconds),
182+
new KeyValuePair<string, object>("StatusCode", 500),
183+
new KeyValuePair<string, object>("ContentType", null),
184+
},
185+
null);
186+
}
187+
}
188+
}
189+

‎src/Microsoft.AspNet.Hosting/project.json‎

Lines changed: 1 addition & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -6,8 +6,7 @@
66
"url": "git://github.com/aspnet/hosting"
77
},
88
"compilationOptions": {
9-
"warningsAsErrors": true,
10-
"allowUnsafe": true
9+
"warningsAsErrors": true
1110
},
1211
"dependencies": {
1312
"Microsoft.AspNet.FileProviders.Physical": "1.0.0-*",

0 commit comments

Comments
 (0)