Logger message + Serilog = performance issues?

Question

As Microsoft suggests, I tried using their high-performance logging approach (also known as the LoggerMessage pattern) with the Serilog logger. For some reason, it did not provide any performance boost and, quite the opposite, resulted in worse performance. Consider the following benchmark:

[MemoryDiagnoser]
public class SerilogBenchmark
{
    private static readonly ILogger<SerilogBenchmark> Logger;
    private static readonly string LogStringTemplate = "User {Username} {Email} has logged in.";
    private static Action<Microsoft.Extensions.Logging.ILogger, string, string, Exception?> LoggerAction =
        LoggerMessage.Define<string, string>(
            LogLevel.Information,
            new EventId(1, "Login"),
            LogStringTemplate);


    static SerilogBenchmark()
    {
        var services = new ServiceCollection();

        Log.Logger = new LoggerConfiguration()
            .WriteTo.TextWriter(TextWriter.Null)
            .CreateLogger();

        services.AddLogging(builder =>
        {
            builder.ClearProviders();
            builder.AddSerilog(dispose: true);
        });

        var serviceProvider = services.BuildServiceProvider();
        Logger = serviceProvider.GetRequiredService<ILogger<SerilogBenchmark>>();
    }

    [Benchmark]
    public void TestLogExtension()
    {
        Logger.LogInformation(LogStringTemplate, "User", "foo@bar.com");
    }

    [Benchmark]
    public void TestLogAction()
    {
        LoggerAction(Logger, "User", "foo@bar.com", null);
    }
}

Results are following:

So, "high-performance logging" rewarded me with 50% more memory allocation and 25% worse performance.

Could someone please help me understand what might be wrong here and how to achieve a performance gain when using logger messages with Serilog as the logger?

Answer 1

Those two are doing slightly different things - the LogAction actually results in the EventId present in the log too, so the "equivalent" would be:

[Benchmark]
public void TestLogExtension()
{
    Logger.LogInformation(new EventId(1, "Login"), LogStringTemplate, "User", "foo@bar.com");
}

Which "on my machine" results in:

Method	Mean	Error	StdDev	Median	Gen0	Allocated
TestLogExtension	1.792 us	0.0659 us	0.1933 us	1.799 us	0.1259	792 B
TestLogAction	1.742 us	0.0575 us	0.1685 us	1.696 us	0.1259	792 B

Arguably no meaningful difference here (actually I'm surprised that there are none extra allocations since LoggerExtensions.LogInformation accepts params object?[] args which should result in extra array allocated).

But your test use-case does not utilize the listed in the docs cases for optimization happening:

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.

While second point possibly is not completely true due to potential cashing (for example on the Serilog side), the first one can be a significant when you are logging a lot of value types (like int's, Guid's etc.)

Also see the Log level guarded optimizations section.