Serilog massive performance hit when enabling Debug log level

6
votes

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.

1
.net-coreserilog
You can use Log.IsEnabled to make your log statements conditional. I'm pretty sure select is not broken wrt serilog - I and many others have lots of debug logging with no such impacts. Having said all this, if you are sending a lot of messages via the console sink and they're not being filtered out, the writing, if not wrapped in Serilog.Sinks.Async will affect the perf of your mainline processing (but you seem to be ruling that out) - Ruben Bartelink

1 Answers

3
votes

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.