Skip to content

Use cached ILogger instances to avoid repeated creation of these instances#53200

Merged
adityamandaleeka merged 1 commit intodotnet:mainfrom
gfoidl:cached_logger
Mar 29, 2024
Merged

Use cached ILogger instances to avoid repeated creation of these instances#53200
adityamandaleeka merged 1 commit intodotnet:mainfrom
gfoidl:cached_logger

Conversation

@gfoidl
Copy link
Member

@gfoidl gfoidl commented Jan 7, 2024

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

@gfoidl gfoidl requested review from a team, BrennanConroy and halter73 as code owners January 7, 2024 13:43
@ghost ghost added area-mvc Includes: MVC, Actions and Controllers, Localization, CORS, most templates community-contribution Indicates that the PR has been added by a community member labels Jan 7, 2024
@ghost
Copy link

ghost commented Jan 7, 2024

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

@Kahbazi
Copy link
Member

Kahbazi commented Jan 16, 2024

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
Copy link
Member

amcasey commented Jan 17, 2024

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
Copy link

levicki commented Jan 18, 2024

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
Copy link
Member

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
Copy link
Contributor

Change looks sensible. #50184 was the first PR to introduce this modification to the codebase.

@levicki
Copy link

levicki commented Jan 23, 2024

@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.

@ghost ghost added the pending-ci-rerun When assigned to a PR indicates that the CI checks should be rerun label Jan 30, 2024
@wtgodbe wtgodbe removed the pending-ci-rerun When assigned to a PR indicates that the CI checks should be rerun label Feb 13, 2024
@dotnet dotnet deleted a comment Feb 13, 2024
@dotnet-policy-service dotnet-policy-service bot added the area-infrastructure Includes: MSBuild projects/targets, build scripts, CI, Installers and shared framework label Feb 13, 2024
@wtgodbe wtgodbe removed the area-infrastructure Includes: MSBuild projects/targets, build scripts, CI, Installers and shared framework label Feb 13, 2024
@dotnet-policy-service dotnet-policy-service bot added the pending-ci-rerun When assigned to a PR indicates that the CI checks should be rerun label Feb 20, 2024
@adityamandaleeka
Copy link
Member

/azp run

@dotnet-policy-service dotnet-policy-service bot removed the pending-ci-rerun When assigned to a PR indicates that the CI checks should be rerun label Mar 15, 2024
@azure-pipelines
Copy link

Azure Pipelines successfully started running 3 pipeline(s).

@adityamandaleeka
Copy link
Member

Thanks @gfoidl and sorry for the delay in review.

@dotnet-policy-service dotnet-policy-service bot added the pending-ci-rerun When assigned to a PR indicates that the CI checks should be rerun label Mar 23, 2024
@adityamandaleeka
Copy link
Member

/azp run

@dotnet-policy-service dotnet-policy-service bot removed the pending-ci-rerun When assigned to a PR indicates that the CI checks should be rerun label Mar 29, 2024
@azure-pipelines
Copy link

Azure Pipelines successfully started running 3 pipeline(s).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

area-mvc Includes: MVC, Actions and Controllers, Localization, CORS, most templates community-contribution Indicates that the PR has been added by a community member

Projects

None yet

Development

Successfully merging this pull request may close these issues.

8 participants