As I am primarily working with “classic” .NET Framework 4.8 professionally, a project that has migrated through the years all the way from .NET Framework 1.1 to 4.8 just this past month, I always try to figure out how to do things that works both in current .NET and last-gen .NET Framework.
I recently enabled every possible static code analyzer Microsoft provides out of the box (Analysis Level: Latest All) in one of my private projects, and the first thing that caught my eye was “CA1848: For improved performance, use the LoggerMessage delegates…”.
Faster logging? It must be a big difference for Microsoft to set this recommendation as a warning and strongly recommend anyone to use it, so off I went to learn more.
As we’re in 2024, a lot of the sources I found on the matter focused purely on the newer Attribute-based version that is available with .NET 5.0 and newer, but since there are quite a few of us out here that are still using .NET Framework, I wanted to document how to get that performance boost for both .NET Framework 4.8 and .NET 8.0.
Requirements
.NET Framework 4.8 SDK (or/and .NET 8.0 SDK)
Nuget packages:
Microsoft.Extensions.Logging
BenchmarkDotNet
NET Framework 4.8
Step 1: Setup the projects
OBS. Both projects needs to be .NET Framework 4.8 OBS.
BenchmarkDotNet runner
Create a console application using Visual Studio and name it runner
Install the latest version of the NuGet-package BenchmarkDotnet ( 0.13.12.0 as I’m writing this)
Update Microsoft.Extensions.Logging to 8.0.0.0
BenchmarkDotNet, or one of its dependencies, references this library internally, but a much older one, and we need the newer version
Class library that generates logs
Create a new project within the same solution as a class library and name it logging
Install version 8.0.0.0 of the NuGet-package *Microsoft.Extensions.Logging *
Add a reference from runner to this project before continuing
Step 2: Code for the class library (logging)
This library will contain two classes; one that demonstrates the simplest version of how to log with ILogger and one that shows how to do “High-performance logging” with LogMessage.
SimpleLogging.cscsharp
{
using Microsoft.Extensions.Logging;
public class SimpleLogging
{
private readonly ILogger _logger;
public SimpleLogging(ILogger logger)
{
_logger = logger;
}
public void ThingThatLogs()
{
string message = “I need to be logged”;
_logger.LogInformation(“Something about {message} needs to be logged”, message);
}
}
}
HighPerformanceLogging.cs
{
using Microsoft.Extensions.Logging;
using System;
public class HighPerformanceLogging
{
private readonly Log _logger;
public HighPerformanceLogging(ILogger logger)
{
_logger = new Log(logger);
}
public void ThingThatLogs()
{
_logger.LogMessage(“I need to be logged”, null);
}
/// <summary>
/// Defines the possible EventId’s by also tying them to a human-readable name.<br/>
/// Used together with the parent class and the sibling class <see cref=”Log”/>.
/// </summary>
/// <remarks>
/// This could entirely be replaced by new’ing these up within <see cref=”Log”/>,<br/>
/// but having given them names will reduce the risk of re-using the same ID for things that shouldn’t be sorted together.<br/>
/// So in a real world scenario, you would have a selection of EventIDs in the private LogEvents-class, not just one.
/// </remarks>
internal static class LogEvents
{
public static readonly EventId ExampleEventId = new EventId(2, nameof(HighPerformanceLogging));
}
/// <summary>
/// Sets up the Action-delegate(s) and exposes the actual call(s) to send the log to the provided <see cref=”ILogger”/> instance.
/// </summary>
private class Log
{
private static readonly Action<ILogger, string, Exception> _createUserRequestedTemplate =
LoggerMessage.Define<string>(
LogLevel.Information,
LogEvents.ExampleEventId,
“Something about {message} needs to be logged”);
private readonly ILogger _logger;
public Log(ILogger logger)
{
this._logger = logger;
}
public void LogMessage(string message, Exception exception)
=> _createUserRequestedTemplate(_logger, message, exception);
}
}
}
Step 3: Code for the BenchmarkDotNet Runner (runner)
Program.cs
{
using BenchmarkDotNet.Running;
internal class Program
{
private static void Main()
{
BenchmarkRunner.Run<LogTests>();
}
}
}
LogTests.cs
{
using BenchmarkDotNet.Attributes;
using logging;
using Microsoft.Extensions.Logging;
[MemoryDiagnoser]
public class LogTests
{
private readonly ILogger _logger = LoggerFactory.Create(builder =>
builder.SetMinimumLevel(LogLevel.Trace))
.CreateLogger<Program>();
private SimpleLogging _sl;
private HighPerformanceLogging _hpl;
[GlobalSetup]
public void Setup()
{
_sl = new SimpleLogging(_logger);
_hpl = new HighPerformanceLogging(_logger);
}
[Benchmark]
public void SimpleLoggingBench()
{
_sl.ThingThatLogs();
}
[Benchmark]
public void HighPerformanceLoggingBench()
{
_hpl.ThingThatLogs();
}
}
}
Step 4: Run the benchmark
In Visual Studio, change from Debug to Release to ensure you’re seeing the performance you’d get in production
Right-click the project runner and click on Set as Startup Project
Start the program without the debugger attached and wait a moment (default keyboard-shortcut is CTRL + F5)
Results for .NET Framework 4.8
Intel Core i7-4771 CPU 3.50GHz (Haswell), 1 CPU, 8 logical and 4 physical cores
[Host] : .NET Framework 4.8.1 (4.8.9256.0), X64 RyuJIT VectorSize=256
DefaultJob : .NET Framework 4.8.1 (4.8.9256.0), X64 RyuJIT VectorSize=256
Method
Mean
Error
StdDev
Median
Gen0
Allocated
SimpleLoggingBench
127.761 ns
2.5809 ns
6.3310 ns
126.171 ns
0.0076
32 B
HighPerformanceLoggingBench
8.219 ns
0.2553 ns
0.7407 ns
7.999 ns
–
–
Just look at those numbers for a second.
An average (mean) of 127 nanoseconds for the simpler code versus a mere 8.2 nanoseconds for the fast one! That is quite the jump!
And while allocating 32B of data doesn’t sound like much, keep in mind that this is a very simple example and I’m using a very simple object, a string, to send in to be handled and merged with another string.
What if you want to add a bunch of Trace or Debug-level messages for those times when something is wrong, but you can’t replicate it while running the code with a debugger attached?
Just think how great it would be if the action of creating those log-messages doesn’t burden the running system as much, you would be free to turn on those higher logging levels more frequently while troubleshooting something in production, with a far smaller performance penalty.
.NET 5.0 and newer
The steps above can be copied verbatim to be used in a .NET 5.0 and newer project, so all I’ll show here is how to use the latest alternative:
Source Generator based LogMessage
using Microsoft.Extensions.Logging;
/// <summary>
/// The entire class needs to be partial, as this is a requirement for a Source Generator to work
/// </summary>
public partial class HighPerformanceLoggingWithAttributes
{
private readonly ILogger _logger;
public HighPerformanceLoggingWithAttributes(ILogger logger)
{
this._logger = logger;
}
/// <summary>
/// One noticable difference with the source generator version is that EventId is _only_ an <see cref=”int”/>, <br/>
/// whereas the other two versions uses an <see cref=”EventId”/> type where you can set your own <see cref=”EventId.Name”/>.<br/>
/// In this version, the name of the class this method resides in will automatically be set as the Name instead.<br/>
/// Also pay attention to the fact that this method is also set as `partial`, as this is a requirement for a Source Generator to work.
/// </summary>
/// <param name=”message”>Message to log.</param>
[LoggerMessage(
EventId = 3,
Level = LogLevel.Debug,
Message = “Something about {message} needs to be logged”)]
public partial void LoggingMethod(string message);
public void ThingThatLogs()
{
this.LoggingMethod(“I need to be logged”);
}
}
Results for .NET 8.0
Intel Core i7-4771 CPU 3.50GHz (Haswell), 1 CPU, 8 logical and 4 physical cores
.NET SDK 8.0.303
[Host] : .NET 8.0.7 (8.0.724.31311), X64 RyuJIT AVX2
DefaultJob : .NET 8.0.7 (8.0.724.31311), X64 RyuJIT AVX2
Method
Mean
Error
StdDev
Median
Gen0
Allocated
SimpleLoggingBench
62.424 ns
1.6184 ns
4.7465 ns
61.045 ns
0.0076
32 B
HighPerformanceLoggingBench
4.003 ns
0.1170 ns
0.2891 ns
4.015 ns
–
–
HighPerformanceLoggingWithAttributesBench
3.336 ns
0.1038 ns
0.3027 ns
3.228 ns
–
–
In .NET 8.0, the numbers might not feel quite as dramatic, 62 nanoseconds vs 3.3 to 4 nanoseconds, but the difference is the same with the simpler logging-code being a mind-boggling 15 times slower than the faster versions!
I know what I’ll be doing going forward when dealing with logging, how about you?
