Betterize Hosting Log #10102

benaadams · 2019-05-09T05:17:13Z

Output something more useful for HostingRequestFinishedLog (which can get intermixed when multiple parallel requests); so it becomes the more interesting event given context; since its kinda junky currently unless you are also outputting full scopes (even then you need to do matching).

Before

info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 GET http://ben-laptop/
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 31.180400000000002ms 404
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 GET http://ben-laptop/index.html
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 1.6021ms 200 text/html
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 GET http://ben-laptop/js/aoa.avatar.js
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 2.6724ms 200 application/octet-stream
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 GET http://ben-laptop:26347/textures/spacedrop2048_right1.dds
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 GET http://ben-laptop:26347/textures/spacedrop2048_left2.dds
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 GET http://ben-laptop:26347/textures/spacedrop2048_top3.dds
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 GET http://ben-laptop:26347/textures/spacedrop2048_bottom4.dds
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 GET http://ben-laptop:26347/textures/spacedrop2048_back6.dds
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 GET http://ben-laptop:26347/textures/spacedrop2048_front5.dds
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 46.6755ms 200 application/octet-stream
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 2.5938000000000003ms 200 application/octet-stream
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 2.7852ms 200 application/octet-stream
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 246.4214ms 200 application/octet-stream
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 280.962ms 200 application/octet-stream
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished in 2.2681ms 200 application/octet-stream

After

info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 GET http://ben-laptop/index.html - -
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/1.1 GET http://ben-laptop/index.html - - - 200 2348 text/html 76.8050ms
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 GET http://ben-laptop/js/aoa.avatar.js - -
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/1.1 GET http://ben-laptop/js/aoa.avatar.js - - - 200 39852 application/octet-stream 8.6488ms
info: Microsoft.AspNetCore.Hosting.Diagnostics[1]
      Request starting HTTP/1.1 POST http://ben-laptop/form application/x-www-form-urlencoded 19
info: Microsoft.AspNetCore.Hosting.Diagnostics[2]
      Request finished HTTP/1.1 POST http://ben-laptop/form application/x-www-form-urlencoded 19 - 404 0 - 8.1129ms

Also improve the more detailed semantic logged output

Before

After

Resolves #10097
Resolves #10556
Resolves #10557

/cc @davidfowl

benaadams · 2019-05-09T12:37:34Z

Also improve the more detailed semantic logged output

Before

After

Tratcher · 2019-05-09T16:20:12Z

@aspnet-hello triage https://dev.azure.com/dnceng/public/_build/results?buildId=184378

aspnet-hello · 2019-05-09T16:22:18Z

This comment was made automatically. If there is a problem contact aspnetcore-build@microsoft.com.

I've triaged the above build. I've created/commented on the following issue(s)
https://github.com/aspnet/AspNetCore-Internal/issues/2451

src/Hosting/Hosting/src/Internal/HostingRequestFinishedLog.cs

src/Hosting/Hosting/src/Internal/HostingRequestStartingLog.cs

halter73 · 2019-05-10T22:14:17Z

src/Hosting/Hosting/src/Internal/HostingApplication.cs

+            }
+
+            // Get or create the _loggingContext
+            private LogContext LoggingContext => _loggingContext ??= new LogContext();


??= @pranavkm How many points for that?

My remaining question is how often a Context is constructed without setting any of these properties to a non-default value.

This does seem like a ton of work to turn six properties into one lazy-allocated field with six properties.

Also, does this need to be thread safe? I hope not because new LogContext() could run multiple times if LoggingContext is accessed and initialized twice in a parallel.

My remaining question is how often a Context is constructed without setting any of these properties to a non-default value.

If you don't want an Activity (152 bytes), 4 ExecutionContexts (160 bytes), 2 strings (76+66 bytes), 4 AsyncLocalMaps (160 bytes) and 3 Logging scope objects (144 bytes); => 758 bytes per request; when you aren't outputting any of it because you aren't at Information level; you might set "Microsoft.AspNetCore.Hosting.Diagnostics": "None" which will do it.

e.g.

"Logging": { "LogLevel": { "Default": "Information", "Microsoft": "Warning", "Microsoft.AspNetCore.Hosting.Diagnostics": "None" }, "EventLog": { "LogLevel": { "Microsoft.AspNetCore.Hosting.Diagnostics": "None" } } },

And if you are picking up that extra 758 bytes per request, what's an extra object ;)

Also if you have no logging as per the TE benchmarks; which also benefits from the struct being 64 bytes rather than 82 bytes when passed.

Also, does this need to be thread safe?

No, its contained to before and after the request in hosting and not exposed to the user code in the application

e.g.

DateTimeFormat (string, byte[], HeaderValues) and ConcurrentDictionary (enumerator) are both heartbeat rather than request allocations so should be subtracted.

I completely forgot that the Context itself was a struct. Too bad it's public. It would have been sooo much easier to turn the Context into a class, but that's breaking.

And if Logging is off for Hosting then the Activity and the LogContext will never be allocated as they are guarded by the Log Enabled check

https://github.com/aspnet/AspNetCore/blob/b744814f06aa145c77db1db496a356d8f9808a4e/src/Hosting/Hosting/src/Internal/HostingApplicationDiagnostics.cs#L47-L53

I completely forgot that the Context itself was a struct. Too bad it's public. It would have been sooo much easier to turn the Context into a class, but that's breaking.

Well LogContext is now a class if you can work out where to hang it rather than allocating it per request? (when logging or diagnostics is enabled)

And if Logging is off for Hosting then the Activity and the LogContext will never be allocated as they are guarded by the Log Enabled check

I figured, but that's unrelated to the LogContext.

Well LogContext is now a class if you can work out where to hang it rather than allocating it per request? (when logging or diagnostics is enabled)

Pooling is an interesting idea. If Context itself was a class, could we pool that instead?

The HttpContext is "pooled" via IHttpContextFactory (lives on connection); but the HostingApplication.Context is side-car'd over it and avoids allocation by living in the stack and being passed around by value.

halter73 · 2019-05-10T22:18:20Z

src/Hosting/Hosting/src/Internal/HostingRequestFinishedLog.cs


 namespace Microsoft.AspNetCore.Hosting.Internal
 {
+    using static HostingRequestStartingLog;


More @pranavkm points 😄 I see this was introduced "way back" in C# 6, but I haven't seen this used much.

benaadams · 2019-05-10T22:26:54Z

src/Hosting/Hosting/src/Internal/HostingApplication.cs

+            public IDisposable Scope
+            {
+                // Get set value or return null
+                get => _loggingContext?.Scope;


I was going to make this readonly get but the version of C# AspNetCore uses is too old.

I think updating it will make Code Check unhappy as every auto-property getter gets the [Readonly] attribute

halter73 · 2019-05-11T00:59:56Z

Actually, would it really be too breaking to make HostingApplication.Context a class? Context seems to have turned into an overly-long, overly-complicated class anyway with almost everything being stored via LogContext reference. This PR changes the struct layout anyway which is why the reference assembly needed updating.

@davidfowl

benaadams · 2019-05-11T01:37:52Z

Actually, would it really be too breaking to make HostingApplication.Context a class?

Would need to introduce a service that the server implemented to not allocated it per request (as per HttpContext); so would be a lot more motion? And since it also contains the HttpContext would you want to bypass its pooling (rather than pooling both)?

Could go with a double interface; if server implements HostContext pooling use that, otherwise use only HttpContext pooling and allocate the HostContext?

benaadams · 2019-05-11T01:40:20Z

This PR changes the struct layout anyway which is why the reference assembly needed updating.

Only removes the attributes [System.Runtime.CompilerServices.CompilerGeneratedAttribute] which I'm not sure why Code Check cares about; and the dummy int field to indicate it also has non-objects for the C# compiler.

benaadams · 2019-05-11T01:51:44Z

Could go with a double interface; if server implements HostContext pooling use that, otherwise use only HttpContext pooling and allocate the HostContext?

Something like:

public interface IHostingContextContainer
{
    HostingContext HostingContext { get; }
}

benaadams · 2019-05-11T01:56:30Z

Though... that might be part of a bigger issue. Like are some routing structures connection orientated rather than request; can scopes be reset and reused etc..?

benaadams · 2019-05-11T17:50:32Z

With pooling the HostContext #10180

analogrelay · 2019-05-24T18:38:38Z

@halter73 @Tratcher Good to merge? Everything seems nice and green :)

davidfowl · 2019-05-26T15:40:38Z

I'd like to review this before merging. I haven't kept up to date with the changes.

benaadams · 2019-05-27T15:18:06Z

Added WIP as it adds a cost; so should be rebased on (merged after) #10319 which removes that cost.

Also raised the issues #10556 and #10557 for the race conditions and incorrect reporting it addresses.

analogrelay · 2019-08-13T19:58:43Z

@davidfowl @halter73 what's the situation here? Are we ready to merge? Unfortunately it'll probably need another rebase :(.

halter73 · 2019-08-13T20:37:22Z

I'm fine with merging this. We'll want to keep a close eye on the benchmarks.

analogrelay · 2019-08-13T20:56:12Z

With master targeting 5.0 now, I'm totally fine with that. I'll re-kick the build to force it to run against the latest master. If that works, I'm OK with merging without a rebase (since we'll rebase as it's merged).

analogrelay · 2019-08-13T20:56:25Z

/azp run

azure-pipelines · 2019-08-13T20:56:39Z

Azure Pipelines successfully started running 2 pipeline(s).

davidfowl · 2019-08-13T23:19:06Z

Imagine if we could run benchmarks before committing 😬

analogrelay · 2019-08-13T23:54:38Z

Someday... someday our dreams will come true :).

@halter73 the rebuild looks to be fine, merge when you're ready.

src/Hosting/Hosting/src/Internal/HostingRequestStartingLog.cs

benaadams · 2019-08-15T09:43:18Z

Rebased

halter73 · 2019-08-15T21:55:09Z

/azp run AspNetCore-ci

azure-pipelines · 2019-08-15T21:55:18Z

Azure Pipelines successfully started running 1 pipeline(s).

benaadams · 2019-08-15T22:41:03Z

Didn't seem to restart the AspNetCore-helix-test (Tests: Helix x64) test which failed in
Microsoft.AspNetCore.SignalR.StackExchangeRedis.Tests
So I'd assume unrelated?

halter73 · 2019-08-15T23:00:34Z

Command '/usr/bin/docker logs redisTestContainer' failed with exit code '-1'

Doesn't look to be related to this change. The failure isn't related to the contents of the logs, but the docker logs command exiting with a non-zero code.

benaadams · 2019-08-18T21:54:05Z

/azp run

azure-pipelines · 2019-08-18T21:54:09Z

Commenter does not have sufficient privileges for PR 10102 in repo aspnet/AspNetCore

benaadams requested review from analogrelay and Tratcher as code owners May 9, 2019 05:17

benaadams mentioned this pull request May 9, 2019

Can the HostingRequestFinishedLog.ToString include the request url too? #10097

Closed

analogrelay added the area-hosting label May 9, 2019

analogrelay added this to the 3.0.0-preview6 milestone May 9, 2019

halter73 self-requested a review May 9, 2019 08:42

benaadams requested a review from jkotalik as a code owner May 9, 2019 12:57

benaadams force-pushed the Hosting-Log branch from 5b5fbdf to 3c7fe6b Compare May 9, 2019 14:32

halter73 reviewed May 10, 2019

View reviewed changes

src/Hosting/Hosting/src/Internal/HostingRequestFinishedLog.cs Outdated Show resolved Hide resolved

halter73 reviewed May 10, 2019

View reviewed changes

src/Hosting/Hosting/src/Internal/HostingRequestStartingLog.cs Outdated Show resolved Hide resolved

halter73 reviewed May 10, 2019

View reviewed changes

halter73 approved these changes May 10, 2019

View reviewed changes

benaadams commented May 10, 2019

View reviewed changes

benaadams mentioned this pull request May 11, 2019

Hosting & other Servers improvements #10180

Closed

This was referenced May 16, 2019

Reduce HttpSysServer Allocations #10283

Closed

Improved Context pooling #10319

Closed

benaadams changed the title ~~Betterize Hosting Log~~ [WIP] Betterize Hosting Log May 27, 2019

analogrelay modified the milestones: 3.0.0-preview8, 5.0.0-alpha1 Aug 13, 2019

analogrelay assigned halter73 Aug 13, 2019

halter73 reviewed Aug 15, 2019

View reviewed changes

src/Hosting/Hosting/src/Internal/HostingRequestStartingLog.cs Show resolved Hide resolved

benaadams commented Aug 15, 2019

View reviewed changes

src/Hosting/Hosting/src/Internal/HostingRequestStartingLog.cs Outdated Show resolved Hide resolved

benaadams force-pushed the Hosting-Log branch from 680ac79 to 6ce3c81 Compare August 15, 2019 09:43

benaadams added 4 commits August 18, 2019 22:55

Betterize Hosting Log

811d53b

Handle encoding

3eddc18

Feedback

26032c1

Encode space only as +

d5fa619

benaadams force-pushed the Hosting-Log branch from 6ce3c81 to d5fa619 Compare August 18, 2019 21:55

halter73 merged commit 5b2f3fb into dotnet:master Aug 20, 2019

benaadams deleted the Hosting-Log branch August 20, 2019 02:35

khellang mentioned this pull request Oct 9, 2019

Add Uri to 'Request finished' log entry #13330

Closed

benaadams mentioned this pull request Oct 3, 2020

Consider using a format string for TimeSpan.TotalMilliseconds in log messages #14854

Closed

amcasey added the area-hosting Includes Hosting label Jun 1, 2023

Betterize Hosting Log #10102

Betterize Hosting Log #10102

Conversation

benaadams commented May 9, 2019 • edited Loading

benaadams commented May 9, 2019 • edited Loading

Tratcher commented May 9, 2019

aspnet-hello commented May 9, 2019

halter73 May 10, 2019

Choose a reason for hiding this comment

pranavkm May 10, 2019

Choose a reason for hiding this comment

halter73 May 10, 2019

Choose a reason for hiding this comment

benaadams May 10, 2019 • edited Loading

Choose a reason for hiding this comment

benaadams May 10, 2019 • edited Loading

Choose a reason for hiding this comment

halter73 May 11, 2019

Choose a reason for hiding this comment

benaadams May 11, 2019 • edited Loading

Choose a reason for hiding this comment

benaadams May 11, 2019 • edited Loading

Choose a reason for hiding this comment

halter73 May 11, 2019

Choose a reason for hiding this comment

benaadams May 11, 2019

Choose a reason for hiding this comment

halter73 May 10, 2019

Choose a reason for hiding this comment

benaadams May 10, 2019 • edited Loading

Choose a reason for hiding this comment

halter73 commented May 11, 2019 • edited Loading

benaadams commented May 11, 2019

benaadams commented May 11, 2019

benaadams commented May 11, 2019

benaadams commented May 11, 2019

benaadams commented May 11, 2019

analogrelay commented May 24, 2019

davidfowl commented May 26, 2019

benaadams commented May 27, 2019

analogrelay commented Aug 13, 2019

halter73 commented Aug 13, 2019

analogrelay commented Aug 13, 2019

analogrelay commented Aug 13, 2019

azure-pipelines bot commented Aug 13, 2019

davidfowl commented Aug 13, 2019

analogrelay commented Aug 13, 2019

benaadams commented Aug 15, 2019

halter73 commented Aug 15, 2019

azure-pipelines bot commented Aug 15, 2019

benaadams commented Aug 15, 2019

halter73 commented Aug 15, 2019

benaadams commented Aug 18, 2019

azure-pipelines bot commented Aug 18, 2019

benaadams commented May 9, 2019 •

edited

Loading

benaadams commented May 9, 2019 •

edited

Loading

benaadams May 10, 2019 •

edited

Loading

benaadams May 10, 2019 •

edited

Loading

benaadams May 11, 2019 •

edited

Loading

benaadams May 11, 2019 •

edited

Loading

benaadams May 10, 2019 •

edited

Loading

halter73 commented May 11, 2019 •

edited

Loading