0

I use Serilog async logging and while doing performance testing with multiple users we found that serilog is taking all the CPU (up to 100%). ASP.net code creates log file using Serilog Async (log.info, log.warning, log.error) and it has logging on all web pages due to security logging requirements. CPU usage spikes after 2 hours and remains 100% continuously and system is getting major performance hit.

We also tested application without SeriLog enabled, the application does not spike up to 100% CPU usage.

I would really appreciate if I get any help here. I can share code (logger class) I created if needed.

enter image description here

And how the logging is configured:

var logConfig = new LoggerConfiguration()
            .MinimumLevel.Information()
            .WriteTo.Async(logSink =>
            {
                logSink.File(
                    logFilePath,
                    rollingInterval: RollingInterval.Day,
                    retainedFileCountLimit: null,
                    outputTemplate: OutputTemplate,
                    hooks: new HeaderWriter(header),
                    flushToDiskInterval: TimeSpan.FromSeconds(10),
                    shared: true
                    );
            });
        Log.Logger = logConfig.CreateLogger();
ORION
  • 2,374
  • 2
  • 22
  • 31
  • 2
    Can you share your logger configuration? Also I suggest looking at the serilog's SelfLog. Are there any error messages? – Tolyandre Jan 15 '21 at 17:22
  • @Tolyandre The input is appreciated. I've added the configuration to the post as requested. – ORION Jan 15 '21 at 18:21
  • "We also tested application without Serilog logging into file and system is working complete file with no CPU spike so it has to do something with Serilog async." What does this even mean? – Ian Kemp Jan 15 '21 at 18:45
  • 1
    @IanKemp I meant that when SeriLog disabled, the application does not spike up to 100% CPU usage. – ORION Jan 15 '21 at 18:53
  • Then the obvious answer is that you are making too many async logging calls, which are using up all of the threadpool threads, causing threadpool starvation, causing your application to spike to 100% while the threadpool spins waiting for one of those threads to free up so you can log again. In short: you're logging too much, stop doing that. And [don't log async either](https://learn.microsoft.com/en-us/dotnet/core/extensions/logging#no-asynchronous-logger-methods). – Ian Kemp Jan 15 '21 at 19:11
  • 1
    @IanKemp that's a lot of inferences from little input ;) the Async Sink does not induce parallelism in that manner – Ruben Bartelink Jan 15 '21 at 23:18
  • Also that Async logging link is not completely relevant - see some [stuff I summarised in a another answer](https://stackoverflow.com/a/53935578/11635) – Ruben Bartelink Jan 15 '21 at 23:37

1 Answers1

1

Some thoughts on further investigation Serilog performance:

  1. Look if there any messages in SelfLog. Normally SelfLog is empty. If there are any, fix them.
Serilog.Debugging.SelfLog.Enable(Console.Error);
  1. Serilog parses and caches every template (up to a fixed size limit) https://github.com/serilog/serilog/wiki/Writing-Log-Events#message-template-recommendations. Logging templates is better than variable messages:
// Don't:
Log.Information("The time is " + DateTime.Now);

// Do:
Log.Information("The time is {Now}", DateTime.Now);

If you log large strings, log them as property to prevent parsing and caching.

  1. Don't accidentally destructure objects with inappropriate properties:
  • of type Task, Stream, etc
  • property getter doing a lot of work
  • property getter that throws
// Don't

// Destructuring entire Request with @ will generate a lot of useless data
Log.Information("Got request {@HttpRequest}", HttpContext.Request);

if you want to log such complex objects, define Destructure.ByTransforming() or IDestructuringPolicy.

Tolyandre
  • 154
  • 3
  • 5