DiagnosticSource Tracing

[alistairjevans]

With the new pipelines architecture coming in v6.0, the ability to trace Autofac operations has been significantly improved.

At the moment, there is an interface IResolvePipelineTracer, that can be implemented to watch the various stages of the Resolve Pipeline.

There is also a default Diagnostic tracer, DefaultDiagnosticTracer, which I put in as a debugging tool more than anything else really, which dumps out detailed trace data for each resolve operation, for example:

Resolve Operation Starting
{
  Resolve Request Starting
  {
    Service: Autofac.Specification.Test.Features.DecoratorTests+IDecoratedService
    Component: Autofac.Specification.Test.Features.DecoratorTests+ImplementorA

    Pipeline:
    -> CircularDependencyDetectorMiddleware
      -> ScopeSelectionMiddleware
        -> DecoratorMiddleware
          -> SharingMiddleware
            -> ActivatorErrorHandlingMiddleware
              -> DisposalTrackingMiddleware
                -> ImplementorA (ReflectionActivator)
                <- ImplementorA (ReflectionActivator)
              <- DisposalTrackingMiddleware
            <- ActivatorErrorHandlingMiddleware
          <- SharingMiddleware
          Resolve Operation Starting
          {
            Resolve Request Starting
            {
              Service: Decorator (Autofac.Specification.Test.Features.DecoratorTests+IDecoratedService)
              Component: Autofac.Specification.Test.Features.DecoratorTests+DecoratorA
              Target: Autofac.Specification.Test.Features.DecoratorTests+ImplementorA

              Pipeline:
              -> CircularDependencyDetectorMiddleware
                -> ScopeSelectionMiddleware
                  -> DecoratorMiddleware
                    -> SharingMiddleware
                      -> ActivatorErrorHandlingMiddleware
                        -> DisposalTrackingMiddleware
                          -> DecoratorA (ReflectionActivator)
                          <- DecoratorA (ReflectionActivator)
                        <- DisposalTrackingMiddleware
                      <- ActivatorErrorHandlingMiddleware
                    <- SharingMiddleware
                  <- DecoratorMiddleware
                <- ScopeSelectionMiddleware
              <- CircularDependencyDetectorMiddleware
            }
            Resolve Request Succeeded; result instance was Autofac.Specification.Test.Features.DecoratorTests+DecoratorA
          }
          Operation Succeeded; result instance was Autofac.Specification.Test.Features.DecoratorTests+DecoratorA
        <- DecoratorMiddleware
      <- ScopeSelectionMiddleware
    <- CircularDependencyDetectorMiddleware
  }
  Resolve Request Succeeded; result instance was Autofac.Specification.Test.Features.DecoratorTests+DecoratorA
}
Operation Succeeded; result instance was Autofac.Specification.Test.Features.DecoratorTests+DecoratorA

In addition to this diagnostic tooling, it may also be good to add support for the .NET Diagnostic Source, as a production-time tracing feature.

I think it's important to distinguish between investigative tracing, and production tracing.

https://github.com/dotnet/runtime/blob/master/src/libraries/System.Diagnostics.DiagnosticSource/src/DiagnosticSourceUsersGuide.md

There are probably the following things to consider:

• Does the DiagnosticSource tracing just become another implementation of IResolvePipelineTracer, which feeds data to a DiagnosticSource? Should it instead just be baked into Autofac generally?

My instinct is that if people aren't using the DiagnosticSource, they may not want the performance cost of us writing to it (or trying to write to it). It could either be a custom tracer they explicitly attach, or a global ContainerBuilder option that lets you enable DiagnosticSource tracing separately from regular tracing.

• What data we capture? We should probably capture less than the detailed tracer, but capturing ResolveRequests and any errors would probably be useful.

• How do we mitigate any run-time performance concerns?

Anything else?

[tillig]

I'm curious as well if we could/should invert the tracing - instead of having our own tracer interface or AttachTracer mechanism, would it be possible to simply expose the trace events using DiagnosticSource and get the same result as our tracing mechanism? ASP.NET Core, for example, uses this as a mechanism for tracing events and it doesn't appear to sacrifice too much speed. However, it'd be good to know the differences and be sure.

[alistairjevans]

One problem; no support prior to .NET Core (as far as I can tell). So we would need to drop netfx support entirely post-6. Not sure how keen we are on that.

Perhaps we could put a DiagnosticSource tracer directly into the Autofac.Extensions.DependencyInjection library, which is where a lot of people would be using it anyway?

Also, one of my (somewhat minor) concerns with that approach is that it puts more onus on the consumer to understand how to consume DiagnosticSource; it's not super complicated, but it might require an additional package (Microsoft.Extensions.DiagnosticAdapter?), and it's another thing we'd have to explain, as opposed to a 'here's a one line callback that outputs your tracing'.

That said, I guess we could provide something like the default tracer we already put in, and just provide a utility consumer of our diagnostic data.

[tillig]

Oh, crap, yeah, I see that now. I didn't realize it wasn't even .NET standard, it's totally just .NET Core. Strike that, then. I'm a lot less keen on it now. I was hoping this would be a standard way we could offer trace events and take advantage of the same benefits ASP.NET Core was using. We could always have shipped a default tracer that uses it (as an example) and a one-liner registration to hook it up (also as an example) to make it easy for folks to understand. But...

Yeah, maybe this isn't as interesting as I thought. Damn.

[alistairjevans]

I think adding it as a built-in feature of the Autofac.Extensions.DependencyInjection library still has legs though.

But that suggests we have 'built-in' tracing, plus possible custom ones, which means we might have to support multiple tracers.

[tillig]

I think supporting multiple tracers is an interesting idea. Sort of like how events can have more than one handler. I could see, like, one tracer that does diagnostic level output, one tracer that puts out Prometheus stats so you can track resolve operations per minute (or something like that)... different tracers for different functions.

[alistairjevans]

If we have multiple tracers, I'd be tempted to restrict them to a property of the entire container, rather than per-scope, so we don't have to manage tracer list copies/changes between scopes.

[alistairjevans]

Perhaps set them up in ContainerBuilder?

[tillig]

Yeah, I'd be OK with a builder-level setup for registering tracers. I can't think of a use case where you'd need to modify later where you couldn't do it from the tracer code (e.g., "if this scope has a tag" or something like that).

[tillig]

Dammit, I once again fell into the trap of thinking DiagnosticSource could really help unify the notion of hooking up tracing for us until I scrolled through and remembered the .NET desktop framework limitation.

I hate to even suggest it, but... what if tracing was only available for .NET Standard targets? That is, if you're on .NET desktop, you just... don't get tracing. It'd make it so there isn't any breaking change later when we want to go DiagnosticSource - we won't have to try to sunset our own custom thing and roll in a new one, it'll just be there.

This is coming up in context of setting up the DOT language tracer and figuring out how to get traces out of the system. There's an event that has to be on every tracer to handle writing out trace; there's an interface for every event (which means we can't add new/interesting events without breaking the interface)... It seems like we could provide a single diagnostic source that raises events (if you enable it) and have multiple listeners if you want, and all that would be maintained.

At the cost of not having tracing in .NET desktop.

(I mean, on a personal note, having to build this thing in a VM on Mac because of the .NET desktop targeting is already pretty sub-par, so I may be biased.)

[alistairjevans]

Radical thought, but what if we dropped support for .NET 4.* entirely, perhaps also lining up the v6 release with the .NET 5 release date? Might be a bit overeager, but...just picture it...

Otherwise, you could conditionally include files for certain targets; leave the core tracing support in there, but don't compile in the tracer that does diagnostic source stuff.

Littering #ifdef throughout may not be ideal however.

[tillig]

This... doesn't hurt my feelings. It would mean we dead-end the integrations that aren't .NET standard, like

• WCF
• MVC (classic)
• web forms
• WebAPI
• OWIN

And that... also doesn't hurt my feelings. We don't get changes in those anymore and it would reduce our maintenance overhead to mark them as "complete" or "maintenance mode."

Let me take this to the contributors discussion group to see what the group thinks.

[tillig]

Wait! Looking at NuGet, System.Diagnostics.DiagnosticSource has support all the way back to .NET 4.5. I think we'll be OK!

[tillig]

I mean, I still wouldn't mind if we dropped .NET desktop support, but we might not have to for this. Let me see if I can refactor it as part of my DOT graph generator thingy.

[alistairjevans]

Huh; weird. The docs seem pretty clear on the matter.

[tillig]

That's why I'm confused, too. Let me try it out and see what's what. Probably not today; but it should be easy enough to add a reference, instantiate one of these things, and see if the build breaks.

[alistairjevans]

Can I suggest/request that whatever mechanism we end up using under the hood, we provide some sort of shortcut via extension method or provider that gives users a way to generate a text-based dump without having to understand System.Diagnostics, in the way it works right now?

It would be good to add a requirement to the issue templates with a short instruction on how to dump a trace, set a low bar for giving us helpful info without us having to handhold anyone.

[tillig]

Oh, absolutely. A simple mechanism to enable diagnostics is going to be key. I, myself, can never remember how to get DiagnosticSource all wired up properly, so having some convenient and clear way to just "make it happen" will be important.

[alistairjevans]

Fixed in #1169