'WriteToProviders:true' causes memory leak with EventSourceLoggerProvider

[spolaore]

Description
UseSerilog(writeToProviders: true) is causing Microsoft.Extensions.Logging.EventSource.EventSourceLogger instances to leak in memory. Honestly I'm not sure if this is something that could be prevented on serilog's side or should be addressed on dotnet core runtime or, maybe, just better documented on serilog's aspnetcore. As of now, our workaround has been removing EventSourceLoggerProvider from service collection as we don't need to write into it.

Reproduction
A reproduciple sample can be found here: https://github.com/spolaore/serilog-leak

Steps to reproduce:

1. dotnet new webapi (with dotnet core 3.1 or net 5)
2. Wire up serilog with write to providers feature enabled:

Host.CreateDefaultBuilder(args)
  .UseSerilog((context, services, configuration) => configuration
    .ReadFrom.Configuration(context.Configuration)
    .ReadFrom.Services(services)
    .Enrich.FromLogContext(), writeToProviders: true)
.ConfigureWebHostDefaults(webBuilder =>
{
  webBuilder.UseStartup<Startup>();
});

3. Run it inside a linux container
4. Run load test with bombardier: bombardier --http1 -k -c 1 -d 100s https://localhost:443/weatherForecast

Expected behavior
Expected not to observe EventSourceLogger objects leaking in heap

Relevant package, tooling and runtime versions

• Serilog 4.1.0
• net5.0 framework
• mcr.microsoft.com/dotnet/sdk:5.0

Additional context

heapdumps-writeToProviders-enabled.zip
heapdump-writeToProviders-disabled.zip

After load testing the reproduciple sample, this is the heap dump generated with dotnet-gcdump tool:

[nblumhardt]

Thanks for the heads-up!

This looks like it's due to EventSourceLoggerProvider holding on (permanently?) to all of the EventSourceLoggers that it creates:

https://github.com/dotnet/runtime/blob/main/src/libraries/Microsoft.Extensions.Logging.EventSource/src/EventSourceLoggerProvider.cs#L36

I'm not sure why this design is used. We should be able to get around it by caching loggers, I guess.

[raphaabreu]

Hello @nblumhardt, I have been struggling with this as well for quite a while.

It seems that the EventSourceLoggerProvider is the only one (at least that I could find) that has this sort of behavior. All other ones either create brand new loggers or have internal caches to recycle previous instances.

Moreover, it seems that the default LoggerFactory implementation does provide a general cache for ILoggers: https://github.com/dotnet/runtime/blob/main/src/libraries/Microsoft.Extensions.Logging/src/LoggerFactory.cs#L128

Is Serillog calling the other registered ILoggerProviders directly for this behavior to be observed?

[spolaore]

@nblumhardt let me know in case you need any help or further actions from my side.

[nblumhardt]

Thanks @spolaore and @raphaabreu 👍

I think we'll want to take a similar approach to MEL, here. Yes, Serilog calls the other providers directly (it completely replaces LoggerFactory when enabled).

Help would be welcome if anyone can take a closer look; the relevant code is:

https://github.com/serilog/serilog-extensions-logging/blob/dev/src/Serilog.Extensions.Logging/Extensions/Logging/LoggerProviderCollectionSink.cs#L60

[ivanmonteiro]

I'm also experiencing memory leak but I'm not using writeToProviders: true.
Instead, I'm using the Readme's configuration instructions:

Log.Logger = new LoggerConfiguration()
            .MinimumLevel.Override("Microsoft", LogEventLevel.Information)
            .Enrich.FromLogContext()
            .WriteTo.Console()
            .CreateLogger();

and

    public static IHostBuilder CreateHostBuilder(string[] args) =>
            Host.CreateDefaultBuilder(args)
                .UseSerilog() // <-- Add this line
                .ConfigureWebHostDefaults(webBuilder =>
                {
                    webBuilder.UseStartup<Startup>();
                });
    }

[nblumhardt]

@ivanmonteiro not sure what's going on in your case, but if you're load testing with a lot of concurrency, it could just be that System.Console can't keep up. First step would be to try removing WriteTo.Console() and see if that makes a difference - Serilog.Sinks.Async and a fixed-size buffer will help, if so.

If not, to avoid derailing this thread, can you please move your comment to a new issue with some additional info about how you're exercising the code? Thanks! 👍

[abergs]

We're seeing this in 2024 -- any advice what's the best mitigation?

[ivanmonteiro]

We're seeing this in 2024 -- any advice what's the best mitigation?

nblumhardt's advice to use Serilog.Sinks.Async helped a lot.
But I still see increased memory consumption using Serilog but it is manageable for me.
It still amazes me that a logging framework uses more memory than the OS and the application combined.
Without serilog my app uses ~100mb and with serilog >300mb under heavy load.

[ivanmonteiro]

We're seeing this in 2024 -- any advice what's the best mitigation?

@abergs reducing the log level also helped