Using pre-compiled message templates in ILogger

I saw a Rider suggestion not long ago to use pre-compiled message templates with ILogger methods. Something like the following:

Message template should be compile time constant

It turns out message templates are a thing. It sounded interesting, so I got curious to check what the performance would look like compared to interpolated string formatting (my current default way of string formatting).

Let's find out. To measure and compare performance, we'll be using BenchmarkDotNet.

The goal is to compare the performance of the code generated for interpolated strings and message templated strings. And while we are on it, let's also check the string.Format performance.
Here is a small benchmark test we'll run:

[MemoryDiagnoser]
[Orderer(BenchmarkDotNet.Order.SummaryOrderPolicy.FastestToSlowest)]
[RankColumn]
public class BenchmarkLogging
{
    private static readonly ILogger Logger;
    private static readonly Random Random;

    private int Data => Random.Next();

    static BenchmarkLogging()
    {
        Logger = new LoggerFactory().CreateLogger("Logger");
        Random = new Random();
    }

    [Benchmark]
    public void Templated()
    {
        Logger.LogInformation("data: {Data}", Data);
    }

    [Benchmark]
    public void Interpolated()
    {
        Logger.LogInformation($"data: {Data}");
    }

    [Benchmark]
    public void Formatted()
    {
        Logger.LogInformation(String.Format("data: {0}", Data));
    }
}

internal class Program
{
    public static void Main(string[] args)
    {
        BenchmarkRunner.Run<BenchmarkLogging>();
    }
}

The full project is available here.

Compiling in release configuration, running our benchmark, checking the results, and the winner is...

...message templates!

Almost four times as fast as interpolated string and string.Format.

Interestingly enough string.Format shows the same result as interpolated string formatting. The generated code appears to be the same in my case:

// [33 13 - 33 69]
IL_0000: ldsfld       class [Microsoft.Extensions.Logging.Abstractions]Microsoft.Extensions.Logging.ILogger logging_performance.BenchmarkLogging::Logger
IL_0005: ldstr        "data: {0}"
IL_000a: ldarg.0      // this
IL_000b: call         instance int32 logging_performance.BenchmarkLogging::get_Data()
IL_0010: box          [mscorlib]System.Int32
IL_0015: call         string [mscorlib]System.String::Format(string, object)
IL_001a: call         !!0/*object*/[] [mscorlib]System.Array::Empty<object>()
IL_001f: call         void [Microsoft.Extensions.Logging.Abstractions]Microsoft.Extensions.Logging.LoggerExtensions::LogInformation(class [Microsoft.Extensions.Logging.Abstractions]Microsoft.Extensions.Logging.ILogger, string, object[])

// [34 9 - 34 10]
IL_0024: ret

Checking the documentation, and now I feel embarrassed because it states exactly this.

If an interpolated string has the type string, it's typically transformed into a String.Format method call. The compiler may replace String.Format with String.Concat if the analyzed behavior would be equivalent to concatenation.

Oops 😳

And what about the code that is generated for message templates?

// [27 13 - 27 57]
IL_0000: ldsfld       class [Microsoft.Extensions.Logging.Abstractions]Microsoft.Extensions.Logging.ILogger logging_performance.BenchmarkLogging::Logger
IL_0005: ldstr        "data: {Data}"
IL_000a: ldc.i4.1
IL_000b: newarr       [mscorlib]System.Object
IL_0010: dup
IL_0011: ldc.i4.0
IL_0012: ldarg.0      // this
IL_0013: call         instance int32 logging_performance.BenchmarkLogging::get_Data()
IL_0018: box          [mscorlib]System.Int32
IL_001d: stelem.ref
IL_001e: call         void [Microsoft.Extensions.Logging.Abstractions]Microsoft.Extensions.Logging.LoggerExtensions::LogInformation(class [Microsoft.Extensions.Logging.Abstractions]Microsoft.Extensions.Logging.ILogger, string, object[])

// [28 9 - 28 10]
IL_0023: ret

Interesting. But not particularly clear. Now I got curious how exactly ILogger does its magic with the message templates. Maybe I will investigate this later.

So, key takeaways from the above are:

1. Using message templates with ILogger seems to be a Good Thing
2. Next time I should read the documentation carefully before writing a blog post