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

Patrik — Sat, 20 Jul 2024 16:44:44 +0000

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
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

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

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

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);
        }

        /// <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

namespace runner
{
    using BenchmarkDotNet.Running;

    internal class Program
    {
        private static void Main()
        {
            BenchmarkRunner.Run<LogTests>();
        }
    }
}

LogTests.cs

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<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

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`

namespace logging;

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

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?

DEV Community: Patrik