.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.
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):
Going a little further we can see that the message is parsed every time the method is called:
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#.
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:
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
.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
Then use this custom extension method to log:
ℹ️ We can use the
thiskeyword on the
ILoggerattribute, as in the above example, to use the source-generated method as an extension method of the
More information here.
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.
|E1||ExtensionMethodOneVariable||127.640 ns||0.0178||56 B|
|E1d||ExtensionMethodOneVariableDisabled||93.791 ns||0.0178||56 B|
|E2||ExtensionMethodTwoVariables||146.952 ns||0.0279||88 B|
|E2d||ExtensionMethodTwoVariablesDisabled||155.544 ns||0.0280||88 B|
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.