Logging is an essential part of any software. But did you know the built-in logging from Microsoft actually has some flaws? Flaws that could hurt the performance and memory consumption of your application? In this post, I will highlight the problems with the default logging solution from Microsoft, as well as several ways on how to improve this.

Small heads up ☝🏻. Since we’re talking about performance, it doesn’t always mean that the most optimized solution is the best solution for your specific use case.

The problem

Most of you probably already know this, but in .NET - and most other languages - you have different log levels that you can configure. Like Information, Warning, Error, etc.

You probably also know that we can configure when something is logged based on the log level and our current environment. We could for example configure our log level to be on Information if we are running our application locally, while in production we could use a more appropriate log level like Warning.

So let’s consider the following log statement:

var loggerFactory = LoggerFactory.Create(builder =>
{
    builder.AddConsole().SetMinimumLevel(LogLevel.Warning);
});

logger.LogInformation("Hi! I'm currently {age} years old", 26);

Because my log level is Warning here, this log should be ignored right? Wrong!

Yes of course, the log doesn’t get shown in the console, but the log statement still gets executed. But Jarne, that can’t be that bad can it? Wrong again!

Let’s press F12 here on the LogInformation method and see what it looks like under the hood:

public static void LogInformation(this ILogger logger, string? message, params object?[] args)
{
    logger.Log(LogLevel.Information, message, args);
}

Now at first sight, this might seem harmless, and in low-level usage cases, it actually is quite harmless. But let’s talk about that last parameter, the args. This is an object array, meaning that if this method gets called, any value types you put in as parameters for your logging template, now get boxed into an array. This array needs to be put on the heap, and that is going to cost you memory. Apart from the memory, this is also going to cost you raw performance, since the execution of this method isn’t stopped. Only the output is ignored.

The poor man’s solution

One thing we could do to prevent the unnecessary execution of a log statement, is to check whether a specific log level is enabled. We can do that by writing the following:

if (_logger.IsEnabled(LogLevel.Information))
{
    logger.LogInformation("Hi! I'm currently {age} years old", 26);
}

Now this feels a little inconvenient doesn’t it? 🤔 Having to place this check everywhere. But bear with me here. Let’s first run some benchmarks and see what sort of a difference this change already makes.

Running some benchmarks

I will be using BenchmarkDotNet for running all of the benchmarks in this blog post. I can certainly recommend this NuGet library when you quickly want to test the performance of a piece of code. 🧪

Consider the following scenario where I have configured a minimum LogLevel of Warning. Let’s benchmark the following four use cases:

private const string LogMessageWithParameters = "This is a log message with parameters {First}, {Second}";
private const string LogMessage = "This is a log message";

// Other code ...

[Benchmark]
public void Log_WithoutIf()
{
    _logger.LogInformation(LogMessage);
}
    
[Benchmark]
public void Log_WithIf()
{
    if (_logger.IsEnabled(LogLevel.Information))
    {
        _logger.LogInformation(LogMessage);
    }
}

[Benchmark]
public void Log_WithoutIf_WithParams()
{
    _logger.LogInformation(LogMessageWithParameters, 69, 420);
}
    
[Benchmark]
public void Log_WithIf_WithParams()
{
    if (_logger.IsEnabled(LogLevel.Information))
    {
        _logger.LogInformation(LogMessageWithParameters, 69, 420);
    }
}

Here are the results that came back:

When we look at the Log_WithIf method, we can already see a huge difference, relatively speaking of course. From 12ns on my local machine to 1.5ns.

If we compare this against the log statements with parameters, then the performance is even more grim, why? Because now we also need to box those value types into that args array. And that costs extra time, and also memory, in this case 88 bytes.

Hmm… only 88 bytes, that seems manageable right? Spoilers ahead…

The real world impact

Let’s say that we are building an application with high traffic, like a stock broker app, or maybe a MMO game engine. I can imagine that in these scenarios, you would have quite a lot of log statements, for debugging reasons of course.

To ‘mimic’ that behaviour, I’m going to place a debug log inside of a loop that will be executed 30 million times. Which is not unrealistic on servers with high traffic.

for (var i = 0; i < 30_000_000; i++)
{
    logger.LogDebug("It's always {MagicNumber}", 42);
}

My Rider IDE has built-in memory profiling. After I ran this, I’ve gotten a yellow outline around my log statement. When I hover over this, I get the following warning message:

That’s about 1.6 gigabytes of allocated memory right there. Imagine what this would do with your garbage collection time. Just with log statements alone, the performance of this application would be severely suffering.

What can we do here?

Since placing these if-statements everywhere also doesn’t seem like a great idea, let’s talk about some other options. 💡

Create a logging adapter

If you don’t want to depend on third party NuGet packages for your logging, then this could already be a good solution. You can simply wrap your logging statements, like so:

public class LoggerAdapter<T>(ILogger<T> logger)
{
    public void LogInformation(string message)
    {
        if (logger.IsEnabled(LogLevel.Information))
        {
            logger.LogInformation(message);
        }
    }

    public void LogInformation<T0, T1>(string message, T0 arg0, T1 arg1)
    {
        if (logger.IsEnabled(LogLevel.Information))
        {
            logger.LogInformation(message, arg0, arg1);
        }
    }
}

Notice the second method in particular, since we are not already passing our arguments in a boxed args array, we would only suffer the performance penalty when we would actually do the logging. That does also mean that for every extra parameter you introduce, you would need to make a new method overload. That’s only a minor nuisance in my opinion, because now your logs will be more clear and concise on the outside.

The performance with the log adapter is a little slower than just doing the straight if-check, since you are having that method inside of your call stack. It’s about a 2.5ns difference. ☝🏻

Use a NuGet library for logging

If you don’t mind using some extra NuGet packages, then SeriLog is a great one. Instead of writing your own logger adapter, SeriLog has actually already done that for you! It also comes with a lot of other great stuff that we won’t cover in this blog post.

Anyway, when we go and have a look at the internals, we see the following code:

public void Information<T0, T1>(string messageTemplate, T0 propertyValue0, T1 propertyValue1)
{
    Write(LogEventLevel.Information, messageTemplate, propertyValue0, propertyValue1);
}

// Other code ...

public void Write<T0, T1>(LogEventLevel level, string messageTemplate, T0 propertyValue0, T1 propertyValue1)
{
    // Avoid the array allocation and any boxing allocations when the level isn't enabled
    if (IsEnabled(level))
    {
        Write(level, messageTemplate, [propertyValue0, propertyValue1]);
    }
}

Wait… isn’t that exactly the code we’ve been writing all along? You bet we are! They are also just passing their parameters as generics here, and that comment you see inside of the Write method, that isn’t mine. It’s from the library itself to remind us all on why we are doing it like this.

So in short, if you don’t want to deal with all of this fuss and just have a solution that works out of the box, then SeriLog is a great option.

Even more performance!

But what if you do actually need to log something? Can we optimize that as well? Certainly! 🔥

There is a way to define your logs beforehand. For this we can use LoggerMessage.Define, which is also part of the built-in logging solution from Microsoft.

Instead of writing something like this:

_logger.LogInformation("I'm jarne, born in {YearOfBirth} and I'm currently {age} years old.",
     1998, 26);

We can write the following:

private static readonly Action<ILogger, int, int, Exception?> IntroductionLogMessageDefinition =
    LoggerMessage.Define<int, int>(LogLevel.Information, 0, 
        "I'm jarne, born in {YearOfBirth} and I'm currently {age} years old.");

public static void LogIntroduction(this ILogger logger, int yearOfBirth, int age)
{
    IntroductionLogMessageDefinition(logger, yearOfBirth, age, null);
}

We’re effectively creating a delegate that is statically defined and compiled beforehand. So at the moment of execution, the log is already good to go.

Luckily, there is a more readable way of writing this. We could use source code generation. Now that sounds really fancy, but this is the only thing you’ll need to write:

public static partial class LoggerMessageDefinitionsGen
{
    [LoggerMessage(EventId = 0, Level = LogLevel.Information,
        Message = "I'm Jarne, born in {YearOfBirth} and I'm currently {age} years old.")]
    public static partial void LogIntroduction(this ILogger logger, int yearOfBirth, int age)
}

We just specify all of our log-information inside an attribute, and .NET will do the rest. 🤘🏼 Because this is a partial class, .NET can generate out the implementation for us in a separate file.

Now if we go and have a look at that file, then you’ll notice it looks pretty much the same as what we wrote earlier with the delegate example:

It even generated out the IsEnabled check. Now if you don’t want that, you can give an extra optional parameter to the attribute: SkipEnabledCheck = true. I can imagine scenarios where we define error logs, which in general should be enabled for all environments.

Now what this will do from a performance standpoint, is actually amazing. 🚀

Let’s see some numbers

Consider the following code for benchmarking. Notice that I’ve introduced a FakeLogger. It’s a custom implementation that will execute the log, but output nothing to the console. Otherwise, this would produce a lot of output during the benchmarking process. The fact that the FakeLogger does not output anything, has no impact on the performance we want to measure during this benchmark. Because remember, we also didn’t output anything with our previous benchmark, so we’re effectively measuring the same thing.

private readonly ILoggerFactory _loggerFactory = LoggerFactory.Create(builder =>
{
    builder.AddFakeLogger().SetMinimumLevel(LogLevel.Information);
});

private readonly ILogger<LoggingBenchmarksV3> _logger;

public LoggingBenchmarksV3()
{
    _logger = new Logger<LoggingBenchmarksV3>(_loggerFactory);
}

[Benchmark]
public void LoggerMessageDef()
{
    _logger.LogIntroduction(69, 420);
}

[Benchmark]
public void LoggerMessageDef_SourceGen()
{
    _logger.LogIntroductionGen(69, 420);
}

Here are the results that came back:

The time it took to execute a log with parameters was basically cut in half. Also notice that there was no memory allocated. These solutions don’t make use of an underlying args array for their parameters. This is currently one of the best ways to do high performance logging in .NET.

These solutions also come with some downsides. Every log message you have will need to be defined separately. In my eyes only a small price to pay if you are using specific logs very frequently. And you are still able to mix and match with other solutions, not all your logs have to be implemented in this way. Apart from that, you are also required to specify an eventId, which is 0 in my case. It could be useful for grouping your logs. Also the optional Exception? you can pass to the log statement is mandatory.

Credits

Most of the knowledge you gain isn’t gathered out of thin air, but based on discoveries/research from others. In specific to this blog post, I’ve gotten a lot of knowledge and inspiration from the logging series Nick Chapsas did a while back on his YouTube channel, so it’s only fair that I give him credit for this. The ideas for this blog post were gathered from the following videos:

• You are doing .NET logging wrong. Let’s fix it
• High-performance logging in .NET, the proper way

If you liked the content of this blog post, be sure to check out his YouTube channel as well! 🎬