External scope storrage prototype by pakrym · Pull Request #723 · aspnet/Logging

pakrym · 2017-10-25T21:55:21Z

Goal: every logger should have scope support but it should be done in efficient way

Solution: provide opt in mechanism for logger providers to indicate that they can consume external scope and allow ILoggerFactory keep an single storage for all loggers.

When logger provider implements ISupportsExternalScope LoggerFactory would provider it's implementation of IExternalScopeProvider to it and never call StartScope in the future. In case implementation of ILoggerFactory does not support IExternalScopeProvider logger provider is able to instantiate and use LoggerExternalScopeProvider on it's own.

CollectScope<T>(Action<object, T> callback, T state) is implemented as a callback instead of returning IEnumerable to provider allocation free way of consuming scope values without exposing internal implementation details.

Current IExternalScopeProvider implementation is subject to change too.

@nblumhardt

analogrelay · 2017-10-25T22:03:07Z

src/Microsoft.Extensions.Logging.Console/ConsoleLogScope.cs


 namespace Microsoft.Extensions.Logging.Console
 {
+    [Obsolete("Use " + nameof(LoggerExternalScopeProvider) + "instead" )]


Why was this ever public?

analogrelay · 2017-10-25T22:09:59Z

src/Microsoft.Extensions.Logging.Console/ConsoleLogger.cs


+        public IExternalScopeProvider ScopeProvider { get; set; }
+
+        [Obsolete("Changing this property would have no effect, please use " + nameof(ConsoleLoggerOptions) + "." + nameof(ConsoleLoggerOptions.IncludeScopes))]


"Changing this property has no effect. Use " + ... + " instead"

NinoFloris · 2017-10-25T22:29:34Z

What about the returned IDisposable instance for each new scope? What's the perf impact of that?

pakrym · 2017-10-25T22:32:33Z

@NinoFloris this PR would alow to reduce overall count of IDisposables because we woldn't get one per provider per scope.

Future optimization is possible if all configured logger providers support external scope we can return IDisposable from IExternalScopeProvider without wrapping it in Logger.Scope

analogrelay

Some minor things in my first look (I know this is just a prototype, but prototypes become real code pretty quickly ;P). I like the pattern generally, but need to take a deeper look at it

analogrelay · 2017-10-25T22:41:02Z

src/Microsoft.Extensions.Logging.Console/ConsoleLogger.cs

-                else
+                var length = builder.Length;
+
+                ScopeProvider?.CollectScope((scope, stringBuilder) => stringBuilder.Append("=> ").Append(scope), builder);


You capture scopeProvider above, then use ScopeProvider here. Mistake?

analogrelay · 2017-10-25T22:43:37Z

src/Microsoft.Extensions.Logging/Logger.cs

+                scope.SetDisposable(0, _loggerFactory.ScopeProvider.Push(state));
+            }
+
+


nit: blank line

analogrelay · 2017-10-25T22:45:36Z

src/Microsoft.Extensions.Logging/LoggerExternalScopeProvider.cs

+
+        public void CollectScope<T>(Action<object, T> callback, T state)
+        {
+            var curent = _currentScope.Value;


nit: current (two rs)

analogrelay · 2017-10-25T22:49:33Z

src/Microsoft.Extensions.Logging/LoggerExternalScopeProvider.cs

+    {
+        private readonly AsyncLocal<Scope> _currentScope = new AsyncLocal<Scope>();
+
+        public void CollectScope<T>(Action<object, T> callback, T state)


Put a doc comment on here describing how the walk is done (from leaf nodes up to the root). Doesn't have to be amazing prose, but something that makes the behavior relatively clear for us to wordsmith later (and to help provider authors)

nblumhardt · 2017-10-25T23:16:07Z

@pakrym thanks for the heads-up!

I think Serilog is unaffected because, by integrating at the ILoggerFactory level, we're working at a layer above this infrastructure. (Please correct me if I'm wrong.)

Integrating this into the Seq provider seems straightforward - it's using a cut-down copy of Serilog's infrastructure, so effectively we'd call CollectScope() within an ILogEventEnricher and apply the logic that's in https://github.com/datalust/seq-extensions-logging/blob/dev/src/Seq.Extensions.Logging/Serilog/Extensions/Logging/SerilogLoggerScope.cs#L48.

One thing that doesn't quite sit right with me about the way MEL is evolving is the disconnect between scopes, events, and filters in the pipeline. In Serilog, properties from the scope go onto the event; later, filters can determine whether an event is included based on its properties, and we can even do tricky things like enrich or route events selectively based on their properties.

Events being a collection of properties is such a fundamental structured logging concept that it's strange to flesh out the implementation side of MEL without acknowledging it in the design.

I suspect that the ultimate reason for avoiding an "event" type was to eliminate mandatory allocations, and keeping it out of the MEL interface/abstraction was a great move, but with each tactical feature addition like this one, allocations appear in real-world use of the pipeline anyway. (There's a likely per-event allocation for the first delegate argument to CollectScope(), for example.)

In the long run, would struct LogEvent and some kind of low-footprint Properties collection on it, unify the implementation-side of MEL and help connect all of these features logically?

nblumhardt · 2017-10-26T00:09:33Z

(In case the relevance of the LogEvent topic is unclear - the alternative to the design explored in the PR is to have the scope set properties on a LogEvent for consumption by the providers, instead of having providers pull information from the scope directly.)

pakrym · 2017-10-26T00:14:13Z

@nblumhardt unfortunately we are not able to make large design changes at this point so what we left with is trying to improve current situation with targeted fixes.

There's a likely per-event allocation for the first delegate argument to CollectScope(), for example.
My hope was that having T state would alow to prevent allocation.

nblumhardt · 2017-10-26T00:43:20Z

@pakrym under those constraints it's fine - I am only thinking of how each API added tactically will make larger-scale changes trickier in the future (always that catch-22).

The Action is the object that will be allocated - at least in the case of the console provider, the closure will end up on the heap. No big deal.

The T state argument makes sense 👍. Naming did trip me up at first - scanning the code I read it as TState state. It's consistent with other callbacks like ParameterizedThreadStart though.

analogrelay · 2017-10-26T21:14:09Z

The Action is the object that will be allocated - at least in the case of the console provider, the closure will end up on the heap. No big deal.

Even less deal if the Action only depends on the state parameter, which means there'd only be one per process (hence why that pattern appears everywhere :))

instead of having providers pull information from the scope directly

This PR is kinda trying to move us towards that model in a compatible way. I completely agree that the model for this should really just be that scope properties are aggregated with the log event properties and logger providers never really need to see scopes. This model allows us to start migrating providers to a model where they don't do scope management at all.

halter73 · 2017-10-26T22:52:52Z

src/Microsoft.Extensions.Logging.Abstractions/ISupportsExternalScope.cs

+    /// <summary>
+    /// An interface for configuring logging providers.
+    /// </summary>
+    public interface ISupportsExternalScope


Nit: ISupportExternalScope

I was going to write a response about the I not being part of the name and we should keep the s, but then I found this: https://source.dot.net/#System.ComponentModel.Primitives/System/ComponentModel/ISupportInitialize.cs,f5af3a8671036626 ;P

So, yeah, carry on then.

halter73 · 2017-10-26T23:02:41Z

src/Microsoft.Extensions.Logging.Abstractions/ISupportsExternalScope.cs

+
+    public interface IExternalScopeProvider
+    {
+        void CollectScope<T>(Action<object, T> callback, T state);


Nit: I prefer AggregateScopes or ReduceScopes.

Maybe TAccumulate AggregateScopes<TAccumulate>(Function<TAccumulate, object, TAccumulate>. It should be easy to convert any Action<object, T> callback into this by just returning the T/TAccumlate.

I actually don't care to much if the method is void or not, but putting Aggregate or Reduce in the name makes it more clear that the callback is called potentially multiple times inline.

AggregateScopes is fine with me if it lets you flow an accumulator, to match Enumerable.Aggregate. I'm not a fan of ReduceScopes because Reduce isn't a term we generally use in our APIs (even if I do like it :)).

I agree Collect isn't a great word since it implies collecting into a single unit (kinda like Aggregate). Perhaps just ForEachScope (precedent with List<T>.ForEach) or EnumerateScopes (other BCL examples of this return IEnumerable but I think we wouldn't want to do that here, however it would be pretty clear what the callback is doing when you see the void return).

I like ForEach more, don't think Aggregate pattern would be useful in this case: TAccumulate would often be collection or collection like object and passed in by reference.

halter73 · 2017-10-26T23:05:12Z

src/Microsoft.Extensions.Logging.Abstractions/ISupportsExternalScope.cs

+    public interface IExternalScopeProvider
+    {
+        void CollectScope<T>(Action<object, T> callback, T state);
+        IDisposable Push(object state);


Since BeginScope takes TState state, shouldn't this too?

Push<TState>(TState state)?

This is one place where the external scope provider isn't able to have the advantages that each provider has. We preserve generics all the way through in order to allow structs to remain unboxed, but the external provider will be forced to box them in order to store them for later.

halter73 · 2017-10-26T23:07:54Z

src/Microsoft.Extensions.Logging/Logger.cs

+            var scopeProvider = _loggerFactory.ScopeProvider;
+            var scopeCount = scopeProvider != null ? 1 : 0;
+
+            // TODO: do not do this every time


Are you going to cache the result for this?

davidfowl · 2017-10-27T16:33:06Z

src/Microsoft.Extensions.Logging.Abstractions/IExternalScopeProvider.cs

+        /// <param name="callback">The callback to be executed for every scope object</param>
+        /// <param name="state">The state object to be passed into the callback</param>
+        /// <typeparam name="T"></typeparam>
+        void CollectScope<T>(Action<object, T> callback, T state);


nit: T -> TState

davidfowl · 2017-10-27T16:39:20Z

src/Microsoft.Extensions.Logging/LoggerFactory.cs

-            _providerRegistrations = providers.Select(provider => new ProviderRegistration { Provider = provider }).ToList();
+            foreach (var provider in providers)
+            {
+                AddProviderRegistration(provider, false);


nit: use a named parameter for the false argument.

davidfowl · 2017-10-27T16:50:24Z

src/Microsoft.Extensions.Logging.Abstractions/LoggerExternalScopeProvider.cs

+            return newScope;
+        }
+
+        private class Scope: IDisposable


nit: spacing

pakrym · 2017-10-30T16:42:12Z

🆙📅

analogrelay

Small suggestion to change ForEachScope.

analogrelay · 2017-10-30T16:49:41Z

src/Microsoft.Extensions.Logging.Abstractions/LoggerExternalScopeProvider.cs

+                {
+                    return;
+                }
+                Report(current.Parent);


Recursion :(. This could be done iteratively, no? It would probably be better to avoid stack diving (even though we're generally going to have a smallish number of scopes)

Not without additional data structure, I'm using recursion to reverse order of items in collection

Ah, I see. Didn't notice the position of the recursion was above the consumption. Ok then.

analogrelay · 2017-10-30T16:59:33Z

src/Microsoft.Extensions.Logging.Console/ConsoleLogger.cs

+                    var (builder, length) = state;
+                    var first = length == builder.Length;
+                    builder.Append(first ? "=> " : " => ").Append(scope);
+                }, (stringBuilder, initialLength));


Clever. Almost makes me want this as a compiler-assisted pattern (capture clauses, a la C++?)

halter73 · 2017-10-30T19:08:00Z

src/Microsoft.Extensions.Logging.Abstractions/LoggerExternalScopeProvider.cs

+
+            public override string ToString()
+            {
+                return State?.ToString();


Nit: Can State really be null? If so, is it OK to return null from ToString()?

Copied from

Logging/src/Microsoft.Extensions.Logging.Console/ConsoleLogScope.cs

Line 47 in e568501

return _state?.ToString();

but not sure how valid it is.

kierenj · 2018-02-27T12:51:40Z

very cool, am (re-)implementing scope at the moment for a logger and of course this would be a plus. is there any kind of timeline for this appearing in a particular version? (am sneaking the 2.1.0-preview1-final version at the moment)

snakefoot · 2018-10-06T22:05:51Z

@pakrym Any reason why you removed this optimization:

if (loggers.Length == 1)
    return loggers[0].Logger.BeginScope(state);

It will hurt NLog and Log4net that doesn't replace the LoggerFactory like Serilog does.

Please re-introduce the optimization ASAP.

snakefoot · 2018-10-06T22:23:28Z

@pakrym Because you have removed this optimization and because the internal combined Scope-class fails to override ToString() then it is actually a breaking change as this now fails:

using (var scopeState = _logger.BeginScope("{World} People", "Earth"))
{
    _logger.LogInformation(scopeState.ToString());  // No longer prints Earth People
}

davidfowl · 2018-10-06T22:30:26Z

@snakefoot I'm more worried about breaking changes then the "optimization". Can you file a new bug describing the problem NLog is having with a repro project? That'll help us quickly identify the issue.

snakefoot · 2018-10-06T22:32:56Z

@pakrym It would be nice if LoggerProviders could still be notified on BeginScope / DisposeScope. In case they had extra state to maintain without having to enter allocation frenzy.

davidfowl · 2018-10-06T22:34:58Z

@pakrym It would be nice if LoggerProviders could still be notified on BeginScope / DisposeScope. In case they had extra state to maintain without having to enter allocation frenzy.

Can you please file an issue for each of the problems you're having (with evidence)...

snakefoot · 2018-10-06T22:37:42Z

@davidfowl Created #893

snakefoot · 2018-10-06T23:17:29Z

@davidfowl Created #894

pakrym requested review from analogrelay and davidfowl October 25, 2017 21:55

dnfclas added the cla-already-signed label Oct 25, 2017

analogrelay reviewed Oct 25, 2017

View reviewed changes

pakrym changed the title ~~[WIP] External scope storrage prototype~~ External scope storrage prototype Oct 26, 2017

halter73 suggested changes Oct 26, 2017

View reviewed changes

davidfowl reviewed Oct 27, 2017

View reviewed changes

pakrym added 10 commits October 27, 2017 13:47

Add support for external scope storrage

3b83e7c

Obsolete more

93411b8

obsolete beter

9c322d5

obsolete beter

0012196

PR comments

3bed4b8

Space

b3c466f

COmments and style

8bfdad7

PR comments

16b0a84

Rename interface

aab55ea

More tests

2758848

pakrym force-pushed the pakrym/externalscope branch from 1ed010d to 2758848 Compare October 27, 2017 20:48

Fix tests

a6a43a4

More fixes

e568501

analogrelay reviewed Oct 30, 2017

View reviewed changes

halter73 approved these changes Oct 30, 2017

View reviewed changes

pakrym merged commit 000418a into dev Oct 31, 2017

This was referenced Jan 25, 2018

Don't set AsyncLocal for scope if not included #714

Closed

Don't set AsyncLocal for scope if not included #715

Closed

davidfowl mentioned this pull request Feb 8, 2018

Add Logger base class with scope logic #682

Closed

snakefoot mentioned this pull request Oct 6, 2018

Configure NLogProviderOptions from appsettings.json NLog/NLog.Extensions.Logging#248

Merged

snakefoot mentioned this pull request Oct 6, 2018

Logger.BeginScope ToString fails when LoggerProvider without ISupportExternalScope #893

Closed

snakefoot mentioned this pull request Oct 6, 2018

Logger.BeginScope with IncludeScopes = false gets performance hit #894

Closed

clement911 mentioned this pull request Oct 16, 2018

HttpContext.Request.Method is empty dotnet/aspnetcore#3627

Closed

natemcmaster deleted the pakrym/externalscope branch November 6, 2018 22:41


		public IExternalScopeProvider ScopeProvider { get; set; }

		[Obsolete("Changing this property would have no effect, please use " + nameof(ConsoleLoggerOptions) + "." + nameof(ConsoleLoggerOptions.IncludeScopes))]

		scope.SetDisposable(0, _loggerFactory.ScopeProvider.Push(state));
		}

Conversation

pakrym commented Oct 25, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

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!

NinoFloris commented Oct 25, 2017

Uh oh!

pakrym commented Oct 25, 2017

Uh oh!

analogrelay left a comment

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!

nblumhardt commented Oct 25, 2017

Uh oh!

nblumhardt commented Oct 26, 2017

Uh oh!

pakrym commented Oct 26, 2017

Uh oh!

nblumhardt commented Oct 26, 2017

Uh oh!

analogrelay commented Oct 26, 2017

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!

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!

pakrym commented Oct 30, 2017

Uh oh!

analogrelay left a comment

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!

pakrym Oct 30, 2017 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

kierenj commented Feb 27, 2018 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

pakrym commented Oct 25, 2017 •

edited

Loading

pakrym Oct 30, 2017 •

edited

Loading

kierenj commented Feb 27, 2018 •

edited

Loading

snakefoot commented Oct 6, 2018 •

edited

Loading