Don't box your logs

Introduction

.NET's default interface for logging (ILogger) can log any number and type of parameters in the log messages. Because of this, the parameters are passed as object to the log implementation, causing the boxing of value types.

In this post, I'll show how .NET Core removed the need for boxing when logging, focusing on the .NET 6 source generators.

CA1848: Use the LoggerMessage delegates

If you use an aggressive static code analysis strategy as I explained in this post, you probably received this message.

The documentation for the message states:

Use LoggerMessage to fix violations of this rule.

LoggerMessage provides the following performance advantages over Logger extension methods:

• Logger extension methods require "boxing" (converting) value types, such as int, into object. The > LoggerMessage pattern avoids boxing by using static Action fields and extension methods with strongly > typed parameters.

• Logger extension methods must parse the message template (named format string) every time a log > message is written. LoggerMessage only requires parsing a template once when the message is defined.

It talks about two problems: boxing of value types and parsing the message template every time the log method is called.

Looking at the extension methods for the ILogger interface, we can see why the boxing occurs. The args parameter is of type object, so it can accept work any number and any type of arguments (Generics wouldn't cover all permutations of params):

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

Going a little further we can see that the message is parsed every time the method is called:

public static void Log(this ILogger logger, LogLevel logLevel, EventId eventId, Exception? exception, string? message, params object?[] args)
{
    ThrowHelper.ThrowIfNull(logger);

    //The FormattedLogValues class calls the Format method of the LogValuesFormatter class.
    logger.Log(logLevel, eventId, new FormattedLogValues(message, args), exception, _messageFormatter);
}

Boxing and Unboxing

Boxing is the act of converting a value type to the object type or to an interface. Unboxing is the inverse process, converting an object or interface to a value type. Both operations are relatively expensive, but boxing is more expensive because it involves allocating memory on the heap.

Mihai Albert has a great post about boxing and its impacts on performance in C#.

Solution prior to .NET 6: LoggerMessage.Define

Prior to .NET 6, we could define delegates for log messages and use them later.

Declare a delegate with the message template and the arguments it accepts one time:

private readonly Action<ILogger, string, Exception?> _logQuoteAdded = 
    LoggerMessage.Define<string>(
        LogLevel.Information,
        new EventId(1, "QuoteAdded"),
        "Quote added (Quote = '{Quote}')");

Then, call the delegate when logging:

_logQuoteAdded(_logger, "Get busy living or get busy dying.", null);

This solved the problem of boxing and parsing messages at every call, but .NET 6 introduced a cleaner solution.

More information about LoggerMessage.Define here.

Solution in .NET 6: Source Generators

.NET 6 introduced the LoggerMessageAttribute. When used, it generates highly performant logging methods at compile time. We can define the logger methods with a fixed message and the specific parameters for that message. This avoids the boxing problem and the parsing of the message every time the method is called.

One thing that I find particularly good about this pattern is that the log messages are centralized in a class. This avoids problems like repeating messages in many classes and possibly different messages for the same log.

To use it, apply it to a partial method in a partial class:

public static partial class LogMessages
{
    [LoggerMessage(Level = LogLevel.Information, Message = "Customer logged in at {time}")]
    public static partial void LogCustomerLogin(this ILogger logger, DateTime time);
}

Then use this custom extension method to log:

_logger.LogCustomerLogin(DateTime.Now);

ℹ️ We can use the this keyword on the ILogger attribute, as in the above example, to use the source-generated method as an extension method of the ILogger properties.

More information here.

Benchmarks

I've run some benchmarks comparing the performance of the ILogger default extension methods and the source-generated logger methods, both with a different number of arguments and with log levels that are enabled and disabled.

From the results, we can see:

• For the default extension methods, even when logging an event with a log level that is disabled (Trace), boxing occurs and the memory is allocated on the heap, causing a possible garbage collection. We can manually check if the event level is enabled before logging, but I consider doing it every time a bad smell;

• With the source-generated method, no boxing occurs and no memory is allocated in the heap;

• The source-generated methods are faster even when no arguments are passed for the default extension methods.

The differences in speed is very little (nanoseconds for one log) and, probably, won't impact most of the applications, except for the ones that have log intensive operations. Even so, I believe using the source-generated logging methods is worthwhile because it improves code quality by defining specific log messages in one class.

⚠️ Error/StdDev/Median fields hidden for better visualization. Full results here.

❗ The benchmarks are not logging anywhere. The idea is to benchmark the logic in the logging method leaving the I/O operations out.

Source Code for the Benchmarks

github.com/dgenezini/LoggerBenchmarks

Like this post?

I post extra content on my personal blog. Click here to see.

Follow me

• Feedly

• RSS

• Linkedin

• Twitter

• Mastodon

References and links

• learn.microsoft.com/en-us/dotnet/core/exten..

• learn.microsoft.com/en-us/dotnet/api/micros..

• learn.microsoft.com/en-us/dotnet/core/exten..

• mihai-albert.com/2019/08/04/boxing-performa..

• learn.microsoft.com/en-us/dotnet/csharp/pro..