Serilog massive performance hit when enabling Debug log level

Question

I'm using Serilog on a .NET Core Service Fabric application.
We noticed performance issues and after investigation it turns out that Serilog is the culprit.

We log ~2,000 Debug messages and it takes 10+ seconds.
This is even with only the Console sink configured and set to filter on Information log level only (so not displaying any Debug messages).
Setting the MinimumLevel to Information makes the same code run <1 second (even with sinks configured).

Our project uses:

• netcoreapp2.0
• Serilog NuGet package 2.8.0 (latest)

Is this the kind of performance that is expected from Serilog?

EDIT: I noticed the same behaviour on another (much) smaller project. That allowed me to isolate the issue: I had a custom enricher that was retrieving the ProcessId. Calling Process.GetCurrentProcess() is incredibly expensive. Doing that for every logging call was what was killing the performance. I stored the process Id in an instance field and the performance soared.

Answer 1

Filtering out debug-level events isn't the same as setting the minimum level; Serilog can be used for serialization of structured log data, so it's likely that construction of the Debug events is eating up the time.

This probably indicates an issue with your debug logging - Serilog itself is fast, but if your debug events are serializing arbitrary large things, e.g. request/response payloads, or DTOs, your app will end up doing a lot of reflection, property accessor calls on your objects (which could block, do I/O, and other crazy things), allocations, and garbage collection.

If debug events are using invalid message templates (i.e. by logging using $"..." string interpolation, or non-constant strings) then your app will also be wasting a lot of energy parsing these as format strings.

I.e. it's not that Serilog is slow here, but that your app is inadvertently getting it to do a lot of wasted work.

Using Debug and then a later Information filter on the console sink will cause all of this work to be done, then thrown away. Setting the minimum level to Information will prevent this work from being done in the first place.

In the long run, auditing your debug-level logging for use of non-constant message templates, @, and destructureObjects: true should help get things back to a sane level.

Answer 2

Logging to Console might make your application slower. Console logging is a blocking (synchronous) operation. Use Serilog.Sinks.Async to buffer the log calls and write the logs using a background thread.

Log.Logger = new LoggerConfiguration()
.MinimumLevel.Information()
.WriteTo.Async(a => a.Console())
.CreateLogger()

If logging Debug information is necessary, it can be logged to a file. I would recommend to restrict console logging to Information using restrictedToMinimumLevel option.

new LoggerConfiguration()
.MinimumLevel.Debug()
.WriteTo.Async((wt) => 
{
   wt.File("log.txt");
   wt.Console(restrictedToMinimumLevel: LogEventLevel.Information);
}, bufferSize: 1000);