Is this the proper way to time how long object creation takes?

[DavidYawCSpeed]

I'm dealing with a startup issue in my application, where the constructors of the various objects may be taking longer than they should.

Since they're all created by Simple Injector, I want to add some logging to output the object creation times. Since many of the components are GUI objects, I don't have access to the base classes to add logging there.

I think I've hit on the solution, but I'm not sure if this is the most proper way to log object creation times. Is there something more appropriate besides ExpressionBuilding/Built?

So far, it seems to be working and getting reasonable results: Most classes take 0.5 to 1 millisecond, the first class in a new assembly takes a little longer, some classes that I know do work in their constructors take even longer.

Application notes:

• Using all Singleton lifestyles, so creation of any particular type only happens once. Therefore, never need to worry about logging the time to perform a second instantiation.

private Dictionary<Type, Stopwatch> timers = new Dictionary<Type, Stopwatch>();
private HashSet<Type> alreadyLogged = new HashSet<Type>();

container.ExpressionBuilding += (s, e) =>
{
    Type type = e.KnownImplementationType;

    if (!alreadyLogged.Contains(type))
        timers.Add(type, Stopwatch.StartNew());
};

container.ExpressionBuilt += (s, e) =>
{
    ConstantExpression constantExpression = e.Expression as ConstantExpression;

    if (constantExpression is null)
    {
        // So far, I haven't seen this.
        logger.Warn("I don't know how to handle a {0} for {1}", 
            e.Expression.GetType(), e.RegisteredServiceType);
        return;
    }

    Type type = constantExpression.Value!.GetType();

    if (alreadyLogged.Contains(type))
    {
        // Do nothing.
    }
    else if (timers.TryGetValue(type, out Stopwatch timer))
    {
        logger.Info("Instantiation: {0:F3}ms for {1}", timer.Elapsed.TotalMilliseconds, type);
        timers.Remove(type);
        alreadyLogged.Add(type);
    }
    else
    {
        // I see this mostly for SimpleInjector.Internals.ContainerControlledCollection. 
        // I'll filter those out later.
        logger.Info("Instantiation: nothing for {0}", type);
        alreadyLogged.Add(type);
    }
};

[dotnetjunkie]

where the constructors of the various objects may be taking longer than they should.

If you can, prevent doing anything at all inside your constructors, except checking preconditions and storing dependencies. Make sure you've read this: Injection Constructors should be simple. This means: don't do any I/O and don't call any injected dependencies from within the constructor.

That being said, you might still want to find out which constructors are causing this. So read on.

This is actually a complicated issue, which is why this is on the backlog for a long time already. But as you can see in that issue (please do read it), there are quite some (still unanswered) design questions, which prevents us from implementing it.

The method you chose is actually quite unreliable, because it only measures the time it takes to build the expression trees. This typically doesn't say anything about the time it takes to create the object, because -in most cases- the object is only created after the ExpressionBuilt event finished. The exception, of course, is the building of singletons, because Simple Injector in that case produces an ConstantExpression, which contains the created instance. This means that in your particular case that solely concerns singletons, you measure both expression tree creation and instance creation. In case of a noticeably slow constructor, the time to create and compile the expression tree might be insignificant to the total amount spent, so this method might work out great in your particular case, especially when you're just interested in spotting the slow constructor, not in the 'exact science' of figuring out how long it took to run the constructor. Still, something to take into consideration.

Problem, however, is that I don't really have a better solutions at hand for you. As described (again) here the 'proper' way to implement this is by intercepting the ExpressionBuilding event and replace the given Expression with one that wraps the the creation with some logging. In essence that means that you would do something as follows:

public static class CreatorInterceptionExtensions
{
    public static void ApplyInterceptor(
        this ContainerOptions options,
        Func<Func<object>, object> interceptor,
        Predicate<Type> predicate = null)
    {
        var container = options.Container;

        container.ExpressionBuilding += (s, e) =>
        {
            if (predicate != null && !predicate(e.KnownImplementationType)) return;

            // Compile the expression for the creation of the component to a Func<object> factory.
            Delegate factory = Expression.Lambda(typeof(Func<object>), e.Expression).Compile();

            // Replace the original expression with a new one that intercepts the
            // creation of the component using the interceptor,
            // i.e.: () => (T)interceptor.Invoke(factory)
            e.Expression = Expression.Convert(
                Expression.Invoke(
                    Expression.Constant(interceptor),
                    Expression.Constant(factory)),
                e.Expression.Type);
        };
    }
}

Usage:

// Only initialize the container using this method in DEBUG or during debugging, because it WILL
// severely impact the performance of the container itself.
if (Debugger.IsAttached) container.Options.ApplyInterceptor(factory =>
{
    var watch = Stopwatch.StartNew();

    object instance = factory();

    long ms = watch.ElapsedMilliseconds;

    if (ms > 0)
    {
        // TODO: Do here what you need to report those slow performing constructors here
        Console.WriteLine(
            $"Creating {instance.GetType().ToFriendlyName()} took {ms} milliseconds.");
    }

    return instance;
});

This allows measuring the creation of any registration, not only singletons and possibly allows other interesting analysis.

[DavidYawCSpeed]

Agreed, constructors should be simple. Most of ours are. But if it's a GUI control, I'm at the mercy of the GUI framework.

Thank you for providing that solution. It does exactly what I need, and it catches the classes where I have a creation delegate instead of registering the type and letting Simple Injector find the constructor. I had used another version of "wrap the Expression" from StackOverflow (https://stackoverflow.com/questions/30126396/simple-injector-tracing-times), but it caused other problems. (It somehow changed the lifestyle of some components, and that created a lifestyle mismatch where Singleton depends on Unknown.)

With this, most of the classes are reported as taking under 0.01 milliseconds, which makes more sense for the trivial classes than the 0.5 to 1 milliseconds that was reported with the previous method. The GUI classes continue to take significantly longer, 20 to 200 milliseconds, depending on the type of control it's loading.

[dotnetjunkie]

Thank you for pointing at that old Stack Overflow answer. I updated that answer to be in line with the code snippet given above, because this is a better and more-reliable solution compared to using RegisterResolveInterceptor and ExpressionBuilt.