Performance overhead for components not consuming ILogger

[srogovtsev]

Recently we've encountered a performance issue in a project using AutofacSerilogIntegration. The performance profiling was indicating a lot of time spent in registration.Preparing handler attached by ContextualLoggingModule; the strange thing, though, was that none of the components in the dependency tree were actually using an ILogger. So I did a little digging and found out that if you register a delegate factory, the integration is always enabled for it (because, of course, there's no way of knowing if it requires ILogger or not).

Enter the benchmark (Autofac 5.1.2, AutofacSerilogIntegration 3.0.0). Here are there most relevant parts of the registration:

containerBuilder.RegisterInstance(new InstanceDependency());
containerBuilder.Register(_ => new DelegateDependency());
containerBuilder.Register(_ => new DelegateDependency2());
containerBuilder.RegisterType<ReflectionDependency>();
containerBuilder.RegisterType<ReflectionDependencyWithLogger>();

Only ReflectionDependencyWithLogger has ILogger as a dependency. And the consumers are very simple:

public class Service<T>
{
  private readonly T _dependency;
  public Service(T dependency) => _dependency = dependency;
}

public class Service2
{
  private readonly DelegateDependency _dependency;
  private readonly DelegateDependency2 _dependency2;

  public Service2(DelegateDependency dependency, DelegateDependency2 dependency2)
  {
    _dependency = dependency;
    _dependency2 = dependency2;
  }
}

Let's start with pure Autofac, no logger registration

Method	Mean	Error	StdDev	Ratio	RatioSD
ReflectionNoLogger	1.452 μs	0.0220 μs	0.0349 μs	1.00	0.00
InstanceNoLogger	1.174 μs	0.0106 μs	0.0094 μs	0.80	0.02
DelegateNoLogger	1.285 μs	0.0124 μs	0.0103 μs	0.88	0.02
TwoDelegatesNoLogger	1.733 μs	0.0159 μs	0.0149 μs	1.19	0.04

No wonders here, provided instance is the fastest, delegate is faster than reflection, when we have two delegates it becomes slower. Everything is as expected. Now we add the logger:

Method	Mean	Error	StdDev	Ratio	RatioSD
Reflection	1.511 μs	0.0264 μs	0.0234 μs	1.00	0.00
ReflectionWithLogger	3.382 μs	0.0674 μs	0.0526 μs	2.24	0.05
Instance	1.202 μs	0.0237 μs	0.0421 μs	0.82	0.03
Delegate	2.807 μs	0.0253 μs	0.0197 μs	1.86	0.03
TwoDelegates	4.960 μs	0.0822 μs	0.0729 μs	3.28	0.08

When we use the logger (ReflectionWithLogger), it is understandably slower. Provided instance is again the fastest. But what happened with the delegates (which, I remind you, don't use ILogger)? They are almost as slow as if we were using the logger, and it grows with the number of consumed delegates.

Here's the culprit:

var ra = registration.Activator as ReflectionActivator;
if (ra != null)
{
  //...some checks...

  // Ignore components known to be without logger dependencies
  if (!usesLogger)
    return;
}

So, for every non-ReflectionActivator component we'll have the Preparing handler attached and firing and the logger being created even if it's not consumed. Which, in our case, was responsible for roughly 3x slowdown (almost the same as in the benchmarks above - we were consuming two delegate dependencies).

As far as I know, Autofac provides 3 activators out-of-the-box: Reflection, ProvidedInstance and Delegate. Reflection is the one the integration properly handles. For the ProvidedInstance the handlers are redundant (nothing will consume the created Parameter), but because it's called only once in the lifecycle, the impact is negligible.

The Delegates, though, are an issue. I'd argue that the handlers are redundant as well, because even while it is possible to consume the Parameter in the factory (using the Register<T>(Func<IComponentContext, IEnumerable<Parameter>, T>) overload) one would have to rely on the private implementation details in the Preparing handler to guess what to consume. It is much easier to simply resolve the logger from the IComponentContext and call ForContext on it. But this is my personal take.

So we have some options here:

1. provide the logger only for ReflectionActivator, which, I'd say, will cover all the expected uses, but, in theory, might break somebody's edge case
2. explicitly list the behavior for known activators (provide for Reflection, do not provide for Delegate and ProvidedInstance), which is same as above but covers for someone's custom activator just in case
3. create a switch, something like RegisterLogger(..., bool onlyForKnownConsumers: false), which will enable the behavior above for implementation cases like ours
4. replace the check with the strategy:

   interface ILoggerAttachmentStrategy
   {
     bool ShouldAttachToRegistration(IComponentRegistration registration, out PropertyInfo[] targetProperties)
   }

   with a default implementation from existing code and allow passing it from outside: RegisterLogger(..., ILoggerAttachmentStrategy strategy), which is a more complex version of 3 with a lot more control for the consumers.

I would personally vote for the option 2, with the option 4 being my next choice.

[srogovtsev]

Further investigation on our side has shown it is even worse than I thought. Consider the following totally benign registration (the full test is available here):

containerBuilder.RegisterType<DependencyWithoutLogger>();
containerBuilder.RegisterType<Component<DependencyWithoutLogger>>();

Let's resolve:

container.Resolve<Component<DependencyWithoutLogger>>();
VerifyLoggerCreation<DependencyWithoutLogger>(Times.Never);

Works as expected: no logger creation was invoked, we're good and safe.

Now let's complicate things a small bit (only on resolution side, I promise!)

//most web applications create a scope for each request, and quite often add some services to them
using (var scope1 = container.BeginLifetimeScope(builder => builder.RegisterType<Scoped1>()))
//and I want to exaggerate things a little bit
using (var scope2 = scope1.BeginLifetimeScope(builder => builder.RegisterType<Scoped2>()))
//this is just to show that if you don't add services, you're fine
using (var scope3 = scope2.BeginLifetimeScope())
{
  //And we're resolving our service some 5 times during one web request. Why not?
  for (var i = 0; i < 5; i++) scope3.Resolve<Component<DependencyWithoutLogger>>();

  VerifyLoggerCreation<DependencyWithoutLogger>(Times.Never);
}

Kaboom:

Expected invocation on the mock should never have been performed, but was 10 times

We are not consuming a logger anywhere, but we still got ten calls to ForContext (and a resolution before that, so it is quite a heavy operation).

This is due to the fact that when you create a scope with some services in it, Autofac creates an intermediate registry which forwards the resolution to parent scope. This changes the activator from Reflection, which we know how to handle, to Delegate which we don't, and which attaches a (totally redundant, in this case) Preparing handler to the registration.

I would say that this is a very compelling reason to avoid attaching to delegate registrations ever.

[nblumhardt]

Thanks for the analysis! Seems nasty.