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..."](https://learn.microsoft.com/en-us/dotnet/fundamentals/code-analysis/quality-rules/ca1848). 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 1. Create a console application using Visual Studio and name it **runner** 2. Install the latest version of the NuGet-package **BenchmarkDotnet** ( **0.13.12.0** as I'm writing this) 3. Update **Microsoft.Extensions.Logging** to **8.0.0.0** 1. `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 1. Create a new project within the same solution as a class library and name it **logging** 2. Install version **8.0.0.0** of the NuGet-package **Microsoft.Extensions.Logging ** 3. 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 ```csharp namespace logging { 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 ```csharp namespace logging { 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); } ///

/// Defines the possible EventId's by also tying them to a human-readable name.
/// Used together with the parent class and the sibling class . ///

/// /// This could entirely be replaced by new'ing these up within ,
/// but having given them names will reduce the risk of re-using the same ID for things that shouldn't be sorted together.
/// So in a real world scenario, you would have a selection of EventIDs in the private LogEvents-class, not just one. /// internal static class LogEvents { public static readonly EventId ExampleEventId = new EventId(2, nameof(HighPerformanceLogging)); } ///

/// Sets up the Action-delegate(s) and exposes the actual call(s) to send the log to the provided instance. ///

private class Log { private static readonly Action _createUserRequestedTemplate = LoggerMessage.Define( 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 ```csharp namespace runner { using BenchmarkDotNet.Running; internal class Program { private static void Main() { BenchmarkRunner.Run(); } } } ``` #### LogTests.cs ```csharp namespace runner { 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(); 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 1. In Visual Studio, change from **Debug** to **Release** to ensure you're seeing the performance you'd get in production 2. Right-click the project `runner` and click on **Set as Startup Project** 3. Start the program without the debugger attached and wait a moment *(default keyboard-shortcut is `CTRL + F5`)* ### Results for .NET Framework 4.8 ``` BenchmarkDotNet v0.13.12, Windows 10 (10.0.19045.4651/22H2/2022Update) 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` ```csharp namespace logging; using Microsoft.Extensions.Logging; ///

/// The entire class needs to be partial, as this is a requirement for a Source Generator to work ///

public partial class HighPerformanceLoggingWithAttributes { private readonly ILogger _logger; public HighPerformanceLoggingWithAttributes(ILogger logger) { this._logger = logger; } ///

/// One noticable difference with the source generator version is that EventId is _only_ an ,
/// whereas the other two versions uses an type where you can set your own .
/// In this version, the name of the class this method resides in will automatically be set as the Name instead.
/// 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. ///

/// Message to log. [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 ``` BenchmarkDotNet v0.13.12, Windows 10 (10.0.19045.4651/22H2/2022Update) 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?

flatrick

CA1848 High-performance logging in .NET Framework 4.8 and .NET 5.0+

Join Our Newsletter. No Spam, Only the good stuff.