Reduce logging overhead in hosting #403

lodejard · 2015-10-13T21:13:52Z

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.

Tratcher · 2015-10-13T21:18:27Z

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

+
+            public HostingRequestScope(HttpContext httpContext)
+            {
+                this._httpContext = httpContext;


nit: remove this.

davidfowl · 2015-10-13T21:31:29Z

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

+        {
+            if (logger.IsEnabled(LogLevel.Information))
+            {
+                logger.Log(LogLevel.Information, 1, new HostingRequestStarting(httpContext), null, HostingRequestStarting.Callback);


null and 1 should use the optional args syntax.

davidfowl · 2015-10-14T08:05:59Z

This ci broke

lodejard · 2015-10-15T21:13:17Z

See also aspnet/Logging#261

benaadams · 2015-10-15T21:34:34Z

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

+        {
+            private readonly HttpContext _httpContext;
+
+            private FeatureReference<IHttpRequestIdentifierFeature> _requestIdentifierFeatureReference;


With aspnet/HttpAbstractions#440 merged, remove

Nice! Hmm... Why don't I see it yet? I'm using 1.0.0-rc1-15826... Must still be working its way through the system

Will merge back into other PR, and add comment changes - hopefully it will flow though soon :)

Not sure, updated #409 with all the changes but isn't picking up TraceIdentifier on HttpContextyet :(

Coherence hasn't passed, but you can reference https://www.myget.org/F/aspnetvolatiledev/api/v2 instead

Was test break, applied fix; build is now happy against aspnetvolatiledev for other PR

Is working now! 💃

benaadams · 2015-10-16T07:16:38Z

PR #409 is working now; which you'll need to merge as the HttpAbstraction changes look like they have flowed through; so currently this PR will break the CI. Added all my comment changes from this to it - as they were around the upcoming break.

benaadams · 2015-10-16T07:51:14Z

Sorry, was wrong, don't think this PR will break the CI as it stands (without the other changes)

davidfowl · 2015-10-16T08:59:51Z

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

+            }
+        }
+
+        private class HostingRequestScope : ILogValues


HostingLogScope. RequestScope sounds like DI

Okay, but the other two are still HostingRequestXxx

benaadams · 2015-10-17T09:55:52Z

Rebased #409 onto last commit and picked up remaining clean up and ci break

benaadams · 2015-10-18T03:40:24Z

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

+
+        private class HostingLogScope : ILogValues
+        {
+            private readonly HttpContext _httpContext;


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

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.

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.

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.

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.

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?

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

rynowak · 2015-10-22T23:10:18Z

@Tratcher updated

Tratcher · 2015-10-22T23:15:31Z

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

-                        throw;
+                        finally
+                        {
+                            logger.RequestFinished(httpContext);


It's still weird that this fires for unhandled exceptions and logs 200 OK.

How would you feel about just logging the elapsed time on failure then - no contenttype/status code. It really seems like the best we can do for now

Better, but you don't have the elapsed time here, do you? I would expect logger.RequestFailed(), with or without the exception.

An alternative is to hook the request completed event to have the correct status code and possibly more accurate overall time. That would need to be weighed against the overhead of the event hook per request - but it can be done only if that level is enabled - so it's no cost at all when no loggers aren't added.

rynowak · 2015-10-23T19:58:01Z

@Tratcher updated

benaadams · 2015-10-23T20:23:53Z

#409 changes:

~~Remove src/Microsoft.AspNet.Hosting/Internal/FastHttpRequestIdentifierFeature.cs~~
~~Remove function private string GetRequestIdentifier(HttpContext httpContext) from src/Microsoft.AspNet.Hosting/Internal/HostingEngine.cs~~
~~Remove call var requestIdentifier = GetRequestIdentifier(httpContext); from same file~~
~~Remove "allowUnsafe": true from src/Microsoft.AspNet.Hosting/project.json~~
~~Remove test/Microsoft.AspNet.Hosting.Tests/Internal/FastHttpRequestIdentifierFeatureTests.cs~~
~~Change function HostingEngine_CreatesDefaultRequestIdentifierFeature_IfNotPresent in test/Microsoft.AspNet.Hosting.Tests/HostingEngineTests.cs from~~

Assert.NotNull(httpContext);
Assert.IsType<FastHttpRequestIdentifierFeature>(httpContext.Features.Get<IHttpRequestIdentifierFeature>());

to

Assert.NotNull(httpContext);
Assert.IsType<HttpRequestIdentifierFeature>(httpContext.Features.Get<IHttpRequestIdentifierFeature>());
Assert.False(string.IsNullOrWhiteSpace(httpContext.TraceIdentifier));
Assert.Same(httpContext.TraceIdentifier, httpContext.Features.Get<IHttpRequestIdentifierFeature>().TraceIdentifier);

Tratcher · 2015-10-23T20:39:03Z

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

@@ -93,27 +93,40 @@ public virtual IApplication Start()
                {
                    var httpContext = contextFactory.CreateHttpContext(features);
                    httpContext.ApplicationServices = _applicationServices;
+
                    var requestIdentifier = GetRequestIdentifier(httpContext);


Remove this line.

Tratcher · 2015-10-23T21:08:50Z

* 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.

rynowak · 2015-10-23T21:11:24Z

Will wait until CI for hosting is green to push. Currently broken due to issues not related to this change.

rynowak · 2015-10-23T21:27:53Z

f37375f

dnfclas added the cla-already-signed label Oct 13, 2015

Tratcher reviewed Oct 13, 2015
View reviewed changes

lodejard force-pushed the lodejard/perf-logging branch from 2796353 to 7921894 Compare October 13, 2015 21:29

davidfowl reviewed Oct 13, 2015
View reviewed changes

This was referenced Oct 14, 2015

Minor perf and logging support changes aspnet/KestrelHttpServer#256

Closed

[Proposal] Lazy requestId and move TraceIdentifier to HttpAbstractions #394

Closed

benaadams reviewed Oct 15, 2015
View reviewed changes

benaadams mentioned this pull request Oct 15, 2015

Cleanup for HttpAbstractions changes #409

Closed

davidfowl reviewed Oct 16, 2015
View reviewed changes

lodejard added a commit that referenced this pull request Oct 16, 2015

PR #403 Feedback

d2feb06

benaadams reviewed Oct 18, 2015
View reviewed changes

rynowak mentioned this pull request Oct 22, 2015

Resolve logging when the request completes #443

Closed

rynowak force-pushed the lodejard/perf-logging branch from d2feb06 to 3845e33 Compare October 22, 2015 23:10

lodejard added a commit that referenced this pull request Oct 22, 2015

PR #403 Feedback

60aba73

Tratcher reviewed Oct 22, 2015
View reviewed changes

rynowak force-pushed the lodejard/perf-logging branch from 3845e33 to 561b10b Compare October 23, 2015 19:57

lodejard added a commit that referenced this pull request Oct 23, 2015

PR #403 Feedback

d0c5cbc

Tratcher reviewed Oct 23, 2015
View reviewed changes

Reduce logging overhead in hosting

8cdff72

* 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.

rynowak force-pushed the lodejard/perf-logging branch from 5085cce to 8cdff72 Compare October 23, 2015 21:10

rynowak closed this Oct 23, 2015

rynowak deleted the lodejard/perf-logging branch October 23, 2015 21:11

Reduce logging overhead in hosting #403

Reduce logging overhead in hosting #403

Uh oh!

Conversation

lodejard commented Oct 13, 2015

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

davidfowl commented Oct 14, 2015

Uh oh!

lodejard commented Oct 15, 2015

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

benaadams commented Oct 16, 2015

Uh oh!

benaadams commented Oct 16, 2015

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

benaadams commented Oct 17, 2015

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

rynowak commented Oct 22, 2015

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

rynowak commented Oct 23, 2015

Uh oh!

benaadams commented Oct 23, 2015

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Tratcher commented Oct 23, 2015

Uh oh!

rynowak commented Oct 23, 2015

Uh oh!

rynowak commented Oct 23, 2015

Uh oh!

Uh oh!