How to measure and monitor Autofac resolve time of individual components

Question

I recently started working for an organization that has an enormous code base that uses Autofac as their DI Container of choice.

Unfortunately, not all developers follow best practices when it comes to writing their classes, which means they sometimes call external services and do other heavy lifting inside their constructors. This is a DI code smell, as injection constructors should be simple.

Considering the size of the application, and the number of developers working on the code, it is not feasible to review all existing classes one by one. Instead I would like to write an integration test that hooks into the Autofac pipeline and reports resolves that take a considerate amount of time.

How would I achieve such a thing? What interception points does Autofac expose that allows this measuring to take place?

With Simple Injector, I'm able to achieve this by registering a resolve interceptor, as shown in this example:

container.Options.RegisterResolveInterceptor((context, producer) =>
    {
        var watch = Stopwatch.StartNew();
        try
        {
            return producer.Invoke();
        }
        finally
        {
            if (watch.TotalElapsedMiliseconds > THRESHOLD)
            {
                Console.WriteLine(
                    $"Resolving {context.Registration.ImplementationType} " +
                    $"took {watch.TotalElapsedMiliseconds} ms.");
            }
        }
    },
    c => true);

How to achieve a similar result with Autofac?

Answer 1

Using an Autofac Module, you can hook onto the Preparing and Activating events:

Autofac registration:

builder.RegisterModule<TimeMeasuringResolveModule>();

TimeMeasuringResolveModule:

public class TimeMeasuringResolveModule : Module
{
    private ResolveInfo _current;

    protected override void AttachToComponentRegistration(
        IComponentRegistry componentRegistry, IComponentRegistration registration)
    {
        registration.Preparing += Registration_Preparing;
        registration.Activating += Registration_Activating;

        base.AttachToComponentRegistration(componentRegistry, registration);
    }

    private void Registration_Preparing(object sender, PreparingEventArgs e)
    {
        // Called before resolving type
        _current = new ResolveInfo(e.Component.Activator.LimitType, _current);
    }

    private void Registration_Activating(object sender, ActivatingEventArgs<object> e)
    {
        // Called when type is constructed
        var current = _current;
        current.MarkComponentAsResolved();
        _current = current.Parent;

        if (current.Parent == null)
        {
            ResolveInfoVisualizer.VisualizeGraph(current);
        }
    }
}

ResolveInfo:

public sealed class ResolveInfo
{
    private Stopwatch _watch = Stopwatch.StartNew();

    public ResolveInfo(Type componentType, ResolveInfo parent)
    {
        ComponentType = componentType;
        Parent = parent;
        Dependencies = new List<ResolveInfo>(4);

        if (parent != null) parent.Dependencies.Add(this);
    }

    public Type ComponentType { get; }
    public List<ResolveInfo> Dependencies { get; }

    // Time it took to create the type including its dependencies
    public TimeSpan ResolveTime { get; private set; }

    // Time it took to create the type excluding its dependencies
    public TimeSpan CreationTime { get; private set; }
    public ResolveInfo Parent { get; }

    public void MarkComponentAsResolved()
    {
        ResolveTime = _watch.Elapsed;
        CreationTime = ResolveTime;

        foreach (var dependency in this.Dependencies)
        {
            CreationTime -= dependency.ResolveTime;
        }
    }
}

ResolveInfoVisualizer:

public static class ResolveInfoVisualizer
{
    public static void VisualizeGraph(ResolveInfo node, int depth = 0)
    {
        Debug.WriteLine(
            $"{new string(' ', depth * 3)}" +
            $"{node.ComponentType.FullName} " +
            $"({node.ResolveTime.TotalMilliseconds.ToString("F1")} ms. / " +
            $"/ {node.CreationTime.TotalMilliseconds.ToString("F1")} ms.)");

        foreach (var dependency in node.Dependencies)
        {
            VisualizeGraph(dependency, depth + 1);
        }
    }
}

Instead of logging to the Debug Window, you should typically use the output in a unit test.

WARNING: The TimeMeasuringResolveModule is NOT thread-safe. Considering the performance overhead of this module, you should only use it as part of a single integration test.

Also note that although this module does generate object graphs, it does not output a representive object graph, but only consists of the objects that are actually activated during that resolve. Already initialized singletons, for instance, will not show up in the graph, as they are effectively no-ops. For visualizing truthful object graphs, a different method should be used.