Use cached ILogger instances to avoid repeated creation of these instances

[gfoidl]

The basic "problem" is shown by this simple demo:

using Microsoft.Extensions.Logging;

ILoggerFactory loggerFactory = LoggerFactory.Create(builder => { });

ILogger logger1 = loggerFactory.CreateLogger("foo");
ILogger logger2 = loggerFactory.CreateLogger("foo");
Console.WriteLine(logger1 == logger2);                          // True

logger1 = loggerFactory.CreateLogger<Foo>();
logger2 = loggerFactory.CreateLogger<Foo>();
Console.WriteLine(logger1 == logger2);                          // False

logger1 = loggerFactory.CreateLogger(typeof(Foo));
logger2 = loggerFactory.CreateLogger(typeof(Foo));
Console.WriteLine(logger1 == logger2);                          // True

public class Foo { }

So for loggerFactory.CreateLogger("foo") and loggerFactory.CreateLogger(typeof(Foo)) cached instances of ILogger are returned. For loggerFactory.CreateLogger<Foo>() always a new instance of ILogger<Foo> is created.

This PR basically does

-loggerFactory.CreateLogger<Foo>();
+loggerFactory.CreateLogger(typeof(Foo));

where the ILogger

• isn't already cached in the instance that uses it (e.g. in a field)
• the type that uses the ILogger isn't registered in DI as singleton

[ghost]

Thanks for your PR, @gfoidl. Someone from the team will get assigned to your PR shortly and we'll get it reviewed.

[Kahbazi]

The generic method looks prettier! Can this issue be fixed in runtime? https://github.com/dotnet/runtime/blob/cd7e4cacce3b47a2560bc9ec746f0825a43f99d7/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/LoggerFactoryExtensions.cs

[amcasey]

The generic method looks prettier! Can this issue be fixed in runtime? https://github.com/dotnet/runtime/blob/cd7e4cacce3b47a2560bc9ec746f0825a43f99d7/src/libraries/Microsoft.Extensions.Logging.Abstractions/src/LoggerFactoryExtensions.cs

https://github.com/dotnet/runtime/issues/48473 😢

[amcasey]

I don't suppose you have any numbers indicating how many instantiations this saves? The change looks unobjectionable and is probably acceptable as a speculative improvement, but my intuition is that it doesn't actually help that much in most cases.

cc @captainsafia for MVC and @BrennanConroy for SignalR

[levicki]

I don't suppose you have any numbers indicating how many instantiations this saves?

I can't tell you how many instantiations it saves, but I just did a quick comparison with NLog provider by creating 10,000,000 instances of ILogger and ILogger<Program> and storing them into two separate arrays. I averaged run times of 3 program runs and the results are 1,016 ms for cached ILogger .vs. 1,882 ms for uncached ILogger<T>.

PrivateMemorySize64 was 100.44 MB for cached .vs. 330.52 MB for uncached.

Of course that's a contrived example, but it shows that both performance and memory are being wasted when using generic ILogger<T> (which is what most people use both in libraries and with dependency injection). I'll let the experts chime in and tell us how much performance and memory is wasted in real code, I am sure they have a way of testing it.

[martincostello]

I was curious what the perf difference would be, so I wrote a quick benchmark and ran it.

The TL;DR is that it's ~20% better in time and memory to use CreateLogger(Type) over CreateLogger<T>().

Benchmark

using BenchmarkDotNet.Attributes;
using BenchmarkDotNet.Diagnosers;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Logging.Abstractions;

namespace DotNetBenchmarks;

[MemoryDiagnoser]
public class ILoggerFactoryBenchmarks
{
    private static readonly ILoggerFactory Factory = NullLoggerFactory.Instance;

    [Benchmark(Baseline = true)]
    public ILogger CreateLogger_Generic()
    {
        return Factory.CreateLogger<MyClass>();
    }

    [Benchmark]
    public ILogger CreateLogger_Type()
    {
        return Factory.CreateLogger(typeof(MyClass));
    }

    private sealed class MyClass
    {
    }
}

BenchmarkDotNet v0.13.12, Windows 11 (10.0.22621.3007/22H2/2022Update/SunValley2)
12th Gen Intel Core i7-1270P, 1 CPU, 16 logical and 12 physical cores
.NET SDK 8.0.101
  [Host]     : .NET 8.0.1 (8.0.123.58001), X64 RyuJIT AVX2
  DefaultJob : .NET 8.0.1 (8.0.123.58001), X64 RyuJIT AVX2

Method	Mean	Error	StdDev	Ratio	RatioSD	Gen0	Allocated	Alloc Ratio
CreateLogger_Generic	41.95 ns	0.886 ns	1.505 ns	1.00	0.00	0.0153	144 B	1.00
CreateLogger_Type	32.98 ns	0.710 ns	1.956 ns	0.81	0.04	0.0127	120 B	0.83

[captainsafia]

Change looks sensible. https://github.com/dotnet/aspnetcore/pull/50184 was the first PR to introduce this modification to the codebase.

[levicki]

@captainsafia It would have been even better if CreateLogger<T> was fixed by adding caching so that every project can benefit instead of everyone having to stop using CreateLogger<T> to avoid the performance hit.

[adityamandaleeka]

/azp run

[azure-pipelines[bot]]

Azure Pipelines successfully started running 3 pipeline(s).

[adityamandaleeka]

Thanks @gfoidl and sorry for the delay in review.

[adityamandaleeka]

/azp run

[azure-pipelines[bot]]

Azure Pipelines successfully started running 3 pipeline(s).