.NET 6 introduced a new feature called Compile-time logging source generators. The compiler will do some magic to create a logging functions. And you ask yourself now: Why do we need this? This concept is called: a simple function. Well yes and no. The benefit of the source code generator is, that a lot of stuff is done during compile time. We can avoid things like boxing, allocations and unnecessary copies. So it is more of an evolution. Sure it has it's limitations. We will see which ones.
What is a source code generator?
A make it very brief here. A source code generator is part of your compiler which generated source code, hence the name. The idea is that you provide a skeleton and the source code generator fills this for you. It involves normally 2 to 3 components. We need a partial class to extend the class (for example we introduce new methods on this very class). Depending what the generator does, we need a partial function because we want to extend a certain function. And most often we need an attribute, which indicates where we want to generate new source code. The Microsoft site about source generators holds some more information for you.
Logging source code generator
Well let's dive into the code and check out how it is used.
public partial class UserCreationService
{
private ILogger _logger;
public UserCreationService(ILogger logger)
{
_logger = logger;
}
public void LogCreateUserBad(User user)
{
// That is the "worst" approach as you lose structured logging
// Helpers like JetBrains Resharper or Rider will even warn you
var when = DateTime.UtcNow;
_logger.LogInformation($"Creating user: {user} at {when}");
}
public void LogCreateUserTraditionally(User user)
{
var when = DateTime.UtcNow;
_logger.LogInformation("Creating user: {User} at {When}", user, when);
}
// The function has to be partial as the source code generator has to provide the implementation
// We can also set the LogLevel and an EventId
// The source code generator will automatically look for an `ILogger` field to log its stuff
[LoggerMessage(Message = "Creating user: {user} at {when}", Level = LogLevel.Information, EventId = 1)]
public partial void LogCreateUser(User user, DateTime when);
}
And we can use it like a regular function:
var logger = LoggerFactory.Create(l => l.AddConsole()).CreateLogger(typeof(UserCreationService));
var userService = new UserCreationService(logger);
var user = new User("Steven", "Giesel");
userService.LogCreateUser(user, DateTime.Now);
Just prints:
info: UserCreationService[1]
Creating user: User { FirstName = Steven, LastName = Giesel } at 07/26/2022 19:23:39
Let's disect what the Roslyn compiler generates for us. For that we have to edit our csproj file and add the following item into the. PropertyGroup group:
<EmitCompilerGeneratedFiles>true</EmitCompilerGeneratedFiles>
This tells the compiler *not to remove any generated file. If you compile your project you can head to the obj folder. There you will find something like this:
obj/
+- debug/ # Depends if you built in debug or release mode
¦ +- net6.0/
¦ ¦ +- generated/
¦ ¦ ¦ +- Microsoft.Extensions.Logging.Generators/
¦ ¦ ¦ ¦ +- Microsoft.Extensions.Logging.Generators.LoggerMessageGenerator/
¦ ¦ ¦ ¦ ¦ +- LoggerMessage.g.cs
Generated file:
partial class UserCreationService
{
[global::System.CodeDom.Compiler.GeneratedCodeAttribute("Microsoft.Extensions.Logging.Generators", "6.0.6.12309")]
private static readonly global::System.Action<global::Microsoft.Extensions.Logging.ILogger, global::User, global::System.DateTime, global::System.Exception?> __LogCreateUserCallback =
global::Microsoft.Extensions.Logging.LoggerMessage.Define<global::User, global::System.DateTime>(global::Microsoft.Extensions.Logging.LogLevel.Information, new global::Microsoft.Extensions.Logging.EventId(1, nameof(LogCreateUser)), "Creating user: {user} at {when}", new global::Microsoft.Extensions.Logging.LogDefineOptions() { SkipEnabledCheck = true });
[global::System.CodeDom.Compiler.GeneratedCodeAttribute("Microsoft.Extensions.Logging.Generators", "6.0.6.12309")]
public partial void LogCreateUser(global::User user, global::System.DateTime when)
{
if (_logger.IsEnabled(global::Microsoft.Extensions.Logging.LogLevel.Information))
{
__LogCreateUserCallback(_logger, user, when, null);
}
}
}
So the generator also checks whether or not a given LogLevel is enabled in the first place, saving even more resources if not needed. A simple word to the usage of that feature: This is most useful for structured logging where you have a well-defined form. If you want to aggregate over complex objects, well then you are a bit out of luck because this will not work with this approach.
We saw that the generated log function is a instance method, which automatically looks for a field which has the ILogger type. We can also define a static version, which accepts an ILogger as argument. Something like this:
[LoggerMessage(Message = "Creating user: {user} at {when}", Level = LogLevel.Information, EventId = 1)]
public static partial void LogStaticVersion(ILogger logger, User user, DateTime when);
That are the very basics. Now the cool part: Error-Handling and I don't even mean runtime things. I mean things you can make wrong during development. Things like: I forgot to apply the partial keyword on my function! Here comes the neat thing: You will get compiler errors for that.
public partial class NoPartialFunction
{
[LoggerMessage(Message = "Creating user: {user} at {when}", Level = LogLevel.Information, EventId = 1)]
public static void LogStaticVersion(ILogger logger, User user, DateTime when);
}
Will result in an error:
Program.cs(11, 5): [SYSLIB1010] Logging methods must be partial
Okay that was a obvious one as the compiler would throw errors anyway. Let's see what happens if you define arguments in the message, which you don't provide as argument:
public partial class MissingArgument
{
[LoggerMessage(Message = "Creating user: {lastName}, {firstName}", Level = LogLevel.Information, EventId = 1)]
public static partial void LogStaticVersion(ILogger logger, string firstName);
}
Will result in:
Program.cs(11, 6): [SYSLIB1014] Template 'lastName' is not provided as argument to the logging method
The name 'lastName' does not exist in the current context
Perfect! We get compiler errors! That is awesome! Now we come to the last part, let's compare the 3 methods above in a benchmark. But one thing I don't want to test is the actual logging to a console or even to a file. That would be very fragile and error-prone. That is why I create a logger which literally does nothing, so it can't temper with our outcome:
public class NoLogger : ILogger
{
public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Exception? exception, Func<TState, Exception?, string> formatter)
{ }
public bool IsEnabled(LogLevel logLevel) => true;
public IDisposable BeginScope<TState>(TState state) => default;
}
Now we are good to go and can implement the benchmark itself. Here the setup:
[MemoryDiagnoser]
public class Benchmark
{
private readonly UserCreationService _service = new(new NoLogger());
private readonly User _user = new("Steven", "Giesel");
private readonly DateTime _now = DateTime.UtcNow;
[Benchmark]
public void LogCreateUserBad() => _service.LogCreateUserBad(_user, _now);
[Benchmark]
public void LogCreateUserTraditionally() => _service.LogCreateUserTraditionally(_user, _now);
[Benchmark]
public void LogCreateUser() => _service.LogCreateUser(_user, _now);
}
And the results:
| Method | Mean | Error | StdDev | Gen 0 | Allocated |
|--------------------------- |-----------:|----------:|----------:|-------:|----------:|
| LogCreateUserBad | 351.207 ns | 1.1014 ns | 0.9764 ns | 0.3133 | 656 B |
| LogCreateUserTraditionally | 87.850 ns | 0.3526 ns | 0.3298 ns | 0.0305 | 64 B |
| LogCreateUser | 9.624 ns | 0.0251 ns | 0.0222 ns | - | - |
As expected the string interpolation is the worst. Not only in terms of performance, but also in allocations. Remember this is just one simple line. If you have a web api with multiple thousand requests, this adds up. Our logging via the source generator is clearly the winner. Zero allocations and faster!
Conclusion
This approach is perfect for structured logging. It is efficient in regards to performance and allocations. As long as you don't want to log complex objects this approach is a win-win.
