Serilog async high CPU usage upto 100%

Question

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.

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();

Can you share your logger configuration? Also I suggest looking at the serilog's SelfLog. Are there any error messages? — Tolyandre
@Tolyandre The input is appreciated. I've added the configuration to the post as requested. — ORION
"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
@IanKemp I meant that when SeriLog disabled, the application does not spike up to 100% CPU usage. — ORION
@IanKemp that's a lot of inferences from little input ;) the Async Sink does not induce parallelism in that manner — Ruben Bartelink

Tolyandre Tolyandre · Accepted Answer · 2021-01-15T20:35:12

Some thoughts on further investigation Serilog performance:

Look if there any messages in SelfLog. Normally SelfLog is empty. If there are any, fix them.

Serilog.Debugging.SelfLog.Enable(Console.Error);

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.

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.

Serilog async high CPU usage upto 100%

1 Answers