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

Reduce logging overhead in hosting #403

Closed
wants to merge 1 commit into from
Closed

Reduce logging overhead in hosting #403

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
65 changes: 0 additions & 65 deletions src/Microsoft.AspNet.Hosting/Internal/FastHttpRequestIdentifierFeature.cs
View file
Open in desktop

This file was deleted.

41 changes: 18 additions & 23 deletions src/Microsoft.AspNet.Hosting/Internal/HostingEngine.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -93,27 +93,34 @@ public virtual IApplication Start()
{
var httpContext = contextFactory.CreateHttpContext(features);
httpContext.ApplicationServices = _applicationServices;
var requestIdentifier = GetRequestIdentifier(httpContext);

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

nit: empty line

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"))
{
Expand Down Expand Up @@ -266,18 +273,6 @@ private void EnsureServer()
}
}

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;
Expand Down
189 changes: 189 additions & 0 deletions src/Microsoft.AspNet.Hosting/Internal/HostingLoggerExtensions.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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))
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is going to be very noisy. Is there a downside to making this Verbose?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

These two messages part of the "ideal ten-ish" messages @DamianEdwards and friends called out as visible from a default web application configuration

{
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;
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Could move this up to HttpAbstractions implement in safe general way (but not alloc free), and thus drop the HostingLogScope class create in RequestScope(...)

public abstract class HttpContext : ILogValues
{
    ...

    public override string ToString() => $"RequestId:{TraceIdentifier} RequestPath:{Request.Path}";

    IEnumerable<KeyValuePair<string, object>> ILogValues.GetValues()
    {
        yield return new KeyValuePair<string, object>("RequestId", TraceIdentifier);
        yield return new KeyValuePair<string, object>("RequestPath", Request.Path.ToString());
    }
}

Specific derived classes could then override with caching as per HostingLogScope

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I wouldn't recommend it. Hosting has an opinion on what is appropriate to log at this moment in the request's execution. That opinion is not valid or useful elsewhere in the app.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Hmm, then switch

public static IDisposable RequestScope(this ILogger logger, HttpContext httpContext)
{
    return logger.BeginScopeImpl(new HostingLogScope(httpContext));
}

for

public static IDisposable RequestScope(this ILogger logger, HttpContext httpContext)
{
    return logger.IsEnabled(LogLevel.Critical) 
                ? logger.BeginScopeImpl(new HostingLogScope(httpContext)) 
                : null;
}

Would that work? Else might regress on perf.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Per discussion with lou, that's not really correct. Scopes are relevant to all loggers, not just to the current one. We'd need a sort of global 'all loggers disabled' check.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Doesn't it go via Microsoft.Extensions.Logging.Logger which enumerates all loggers in the IsEnabled method bailing on first true?

Also have fast path PR for no loggers for the check: https://github.com/aspnet/Logging/pull/254/files

An IsEnabled with no params would be prettier, but would change the interface.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah, you mean because its an extension method so can be used in multiple places rather than just on the top level logger?

Or adding a logger at a particular point in the pipeline, to only log specific bits?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It turns out it was a bug to check the IsEnabled to short-circuit the scope. Even if messages in the logger's category are entirely disabled, there can be other messages in the application that will be logged and will need the logger scope available... We might be able to optimize the BeginScopeImpl a little bit more and get the per-request overhead down to a single object with one field, then measure it from there to see how much impact that is having


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

3 changes: 1 addition & 2 deletions src/Microsoft.AspNet.Hosting/project.json
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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-*",
Expand Down
Loading