High-Performance Logging: the LoggerMessage Source Generator, IsEnabled and Allocation Cost

Version note: The code in this post was built and run with .NET 10, Microsoft.Extensions.Telemetry.Abstractions 10.11 and BenchmarkDotNet 0.15.8.

Guess First

The minimum level in production is Information. The cart service has this line: logger.LogDebug("Cart {CartId} has {ItemCount} items, total {CartTotal}", cartId, itemCount, total). Debug is off, so this line will never be written anywhere. Does each call still allocate memory? If so, how many bytes? And guess this one too: when you write the same line at Information, with the level on, which is faster, the call with a message template or the $"..." interpolation that CA2254 complains about?

The answer to the second question surprises most people. We'll measure both with BenchmarkDotNet.

The Price You Pay Even When the Level Is Off

In the ASP.NET Core Web API (Application Programming Interface) series post "Logging in ASP.NET Core: ILogger, Log Levels, Structured Logging and Serilog" we briefly introduced the LoggerMessage source generator and said "guard expensive arguments with IsEnabled". This post is the in-depth version of that introduction: why it's expensive, how expensive, and what convention to set up in a team.

LogDebug, LogInformation and their siblings are extension methods on ILogger. Their signature looks like this: LogDebug(this ILogger logger, string? message, params object?[] args). That signature hides two costs paid before you even enter the method. The first is params object?[]: every call creates a new array. The second is boxing: value types such as int and decimal are put into boxes on the heap when they're converted to object. All of this happens at the call site, before the level check. Even if the logger later says "Debug is off" and drops the line, the array and the boxes already exist and the garbage collector has work to do.

The classic fix is wrapping the call in if (logger.IsEnabled(LogLevel.Debug)). It works, but adding three lines of if to every log line isn't a discipline anyone can sustain. The cleaner way is to let the compiler generate the check and the typed parameters.

An Event Catalog with [LoggerMessage]

In the first post of the series we reduced the Bookstore order flow to three events. Now we collect those events and the cart summary in a single static partial class:

using Microsoft.Extensions.Logging;

namespace Bookstore.Orders;

// Event catalog: every order-related log event lives here, ids are unique per class.
public static partial class OrderLog
{
    [LoggerMessage(EventId = 1001, Level = LogLevel.Information,
        Message = "Order {OrderId} placed for customer {CustomerId}: {LineCount} lines, total {OrderTotal}")]
    public static partial void OrderPlaced(this ILogger logger, Guid orderId, int customerId, int lineCount, decimal orderTotal);

    [LoggerMessage(EventId = 1002, Level = LogLevel.Information,
        Message = "Order rejected for customer {CustomerId}: {RejectReason} on {Isbn} (requested {Requested}, available {Available})")]
    public static partial void OrderRejected(this ILogger logger, int customerId, string rejectReason, string isbn, int requested, int available);

    [LoggerMessage(EventId = 1003, Level = LogLevel.Warning,
        Message = "Payment for customer {CustomerId} succeeded after {PaymentAttempts} attempts")]
    public static partial void PaymentRetried(this ILogger logger, int customerId, int paymentAttempts);

    [LoggerMessage(EventId = 1004, Level = LogLevel.Debug,
        Message = "Cart {CartId} has {ItemCount} items, total {CartTotal}")]
    public static partial void CartSummary(this ILogger logger, int cartId, int itemCount, decimal cartTotal);
}

The caller now writes logger.OrderPlaced(order.Id, order.CustomerId, request.Lines.Count, order.Total). The template text, the level and the EventId are in one place; it's impossible to pick the wrong level or spell a placeholder differently at the call site. The method name becomes the EventName too: when you give an EventId but no EventName, the generator uses nameof(OrderPlaced). The JSON (JavaScript Object Notation) console output is identical to the handwritten version from the first post:

{"EventId":1001,"LogLevel":"Information","Category":"Bookstore.Orders","Message":"Order 01a1b8de-8d15-7651-b472-6d4f3064e0f6 placed for customer 42: 1 lines, total 91.0","State":{"OrderId":"01a1b8de-8d15-7651-b472-6d4f3064e0f6","CustomerId":42,"LineCount":1,"OrderTotal":91.0,"{OriginalFormat}":"Order {OrderId} placed for customer {CustomerId}: {LineCount} lines, total {OrderTotal}"}}

The logger.CartSummary(7, 3, 120.5m) call right after it in the same program produced no output, because the minimum level is Information. The real question is the price of that silence.

What Does the Generator Produce?

If you add <EmitCompilerGeneratedFiles>true</EmitCompilerGeneratedFiles> to the project, the generated code is written under obj/Debug/net10.0/generated/. The code generated for CartSummary (verbatim from the file):

private static readonly global::System.Action<global::Microsoft.Extensions.Logging.ILogger, global::System.Int32, global::System.Int32, global::System.Decimal, global::System.Exception?> __CartSummaryCallback =
    global::Microsoft.Extensions.Logging.LoggerMessage.Define<global::System.Int32, global::System.Int32, global::System.Decimal>(global::Microsoft.Extensions.Logging.LogLevel.Debug, new global::Microsoft.Extensions.Logging.EventId(1004, nameof(CartSummary)), "Cart {CartId} has {ItemCount} items, total {CartTotal}", new global::Microsoft.Extensions.Logging.LogDefineOptions() { SkipEnabledCheck = true });

[global::System.CodeDom.Compiler.GeneratedCodeAttribute("Microsoft.Extensions.Logging.Generators", "10.0.15.2326")]
public static partial void CartSummary(this global::Microsoft.Extensions.Logging.ILogger logger, global::System.Int32 cartId, global::System.Int32 itemCount, global::System.Decimal cartTotal)
{
    if (logger.IsEnabled(global::Microsoft.Extensions.Logging.LogLevel.Debug))
    {
        __CartSummaryCallback(logger, cartId, itemCount, cartTotal, null);
    }
}

Three things stand out. The template is parsed once, when the class loads, with LoggerMessage.Define and turned into a static delegate; it isn't parsed on every call. The parameters stay typed as int, int, decimal; there's no object[] and no boxing. And the IsEnabled check is on the method's first line, so the delegate is never entered when the level is off.

When you set SkipEnabledCheck = true, that if disappears and the method calls the delegate directly. That's useful if you already check on the caller side; for example, if you ask IsEnabled once outside a loop and write hundreds of lines inside it. Otherwise leave it alone; the default behavior is the right one.

Instance Methods and Primary Constructors

You can also define an event as the service's own private method instead of an extension method. The generator looks for an ILogger field or primary constructor parameter in the class:

public sealed partial class CartService(ILogger<CartService> logger)
{
    public void Checkout(CheckoutInfo checkout)
    {
        CheckoutStarted(checkout.CartId);
    }

    // instance method: the generator finds the ILogger in the primary constructor
    [LoggerMessage(EventId = 2001, Level = LogLevel.Information, Message = "Checkout started for cart {CartId}")]
    private partial void CheckoutStarted(int cartId);
}

In the generated method body, logger.IsEnabled(...) refers directly to the primary constructor parameter. Primary constructor support arrived with .NET 9; before that the generator only saw fields, and you had to write private readonly ILogger _logger = logger; by hand.

Which one to choose? An extension-method catalog is good when several classes use the same event (for example, when both the API and a background job write order events) and when you want to answer "where are all our events?" with one file. An instance method is tidier for events that belong only to that service and shouldn't be exposed. Making one of the two the team rule is better than mixing them.

Let's Measure: BenchmarkDotNet

To imitate a real sink, I wrote a provider that formats the message and throws it away; that way the formatting cost at an enabled level is measured too:

[MemoryDiagnoser]
[SimpleJob(launchCount: 1, warmupCount: 5, iterationCount: 10)]
public class LoggingBenchmarks
{
    private ILogger _logger = null!;
    private ILoggerFactory _factory = null!;
    private readonly int _cartId = 7;
    private readonly int _itemCount = 3;
    private readonly decimal _total = 120.5m;

    [GlobalSetup]
    public void Setup()
    {
        // Information is on, Debug is off; the provider formats every message and drops it
        _factory = LoggerFactory.Create(b => b
            .SetMinimumLevel(LogLevel.Information)
            .AddProvider(new FormattingNullProvider()));
        _logger = _factory.CreateLogger("Bookstore.Orders");
    }

    [Benchmark(Baseline = true)]
    public void Disabled_Extension() =>
        _logger.LogDebug("Cart {CartId} has {ItemCount} items, total {CartTotal}", _cartId, _itemCount, _total);

    [Benchmark]
    public void Disabled_IsEnabledGuard()
    {
        if (_logger.IsEnabled(LogLevel.Debug))
        {
            _logger.LogDebug("Cart {CartId} has {ItemCount} items, total {CartTotal}", _cartId, _itemCount, _total);
        }
    }

    [Benchmark]
    public void Disabled_SourceGenerated() => _logger.CartSummary(_cartId, _itemCount, _total);

    [Benchmark]
    public void Enabled_Interpolated() =>
        _logger.LogInformation($"Cart {_cartId} has {_itemCount} items, total {_total}");

    [Benchmark]
    public void Enabled_Extension() =>
        _logger.LogInformation("Cart {CartId} has {ItemCount} items, total {CartTotal}", _cartId, _itemCount, _total);

    [Benchmark]
    public void Enabled_SourceGenerated() => _logger.CartSummaryInfo(_cartId, _itemCount, _total);
}

CartSummaryInfo is the Information-level twin of CartSummary (EventId 1005). The real result with dotnet run -c Release, on a Mac with an Apple M5 (Arm64) processor and the .NET 10.0.13 runtime:

| Method                   | Mean       | Error     | StdDev    | Ratio | RatioSD | Gen0   | Allocated | Alloc Ratio |
|------------------------- |-----------:|----------:|----------:|------:|--------:|-------:|----------:|------------:|
| Disabled_Extension       | 19.6024 ns | 0.8057 ns | 0.5329 ns |  1.00 |    0.04 | 0.0153 |     128 B |        1.00 |
| Disabled_IsEnabledGuard  |  0.4106 ns | 0.0201 ns | 0.0105 ns |  0.02 |    0.00 |      - |         - |        0.00 |
| Disabled_SourceGenerated |  0.6254 ns | 0.3260 ns | 0.2156 ns |  0.03 |    0.01 |      - |         - |        0.00 |
| Enabled_Interpolated     | 40.9263 ns | 2.2785 ns | 1.5071 ns |  2.09 |    0.09 | 0.0105 |      88 B |        0.69 |
| Enabled_Extension        | 82.1528 ns | 1.6964 ns | 1.1221 ns |  4.19 |    0.12 | 0.0257 |     216 B |        1.69 |
| Enabled_SourceGenerated  | 46.7951 ns | 3.8526 ns | 2.5483 ns |  2.39 |    0.14 | 0.0105 |      88 B |        0.69 |

The answer to the first question is in the first row: the disabled Debug line allocates 128 bytes on every call. The math adds up: a three-element object[] is 48 bytes, two boxed ints are 24 bytes each, and a boxed decimal is 32 bytes. An API that serves 10,000 requests per second and runs five such lines per request produces about 6.4 MB of garbage per second while logging nothing. The source-generated version and the IsEnabled-guarded version allocate zero and stay under a nanosecond.

The answer to the second question is interesting: at an enabled level, interpolation (41 ns, 88 B) is twice as fast as the extension method with a message template (82 ns, 216 B). That's because interpolation produces a single string, while the extension method does the array, the boxing, the template lookup in a cache and the formatting. But interpolation buys that speed by killing structured logging, and it still builds the string when the level is off. The source-generated version (47 ns, 88 B) combines the good sides of both: speed close to interpolation, the same allocation (all 88 bytes are the message string produced by the sink) and the properties preserved.

These numbers are below a microsecond; nobody should lose sleep over a single log line. The difference shows up on hot paths that run tens of thousands of times per second, and in GC (Garbage Collector) pressure.

[LogProperties]: Expanding an Object into Properties

Sometimes you want to log a whole object instead of individual parameters. The Microsoft.Extensions.Telemetry.Abstractions package brings the [LogProperties] attribute for that:

public sealed record CheckoutInfo(int CartId, int ItemCount, decimal Total, string CustomerEmail);

[LoggerMessage(EventId = 2002, Level = LogLevel.Information, Message = "Checkout completed")]
private partial void CheckoutCompleted([LogProperties] CheckoutInfo checkout);

Output:

{"EventId":2002,"LogLevel":"Information","Category":"Bookstore.Orders.CartService","Message":"Checkout completed","State":{"Message":"checkout.CustomerEmail=ada@example.com,checkout.Total=120,5,checkout.ItemCount=3,checkout.CartId=7,{OriginalFormat}=Checkout completed","checkout.CustomerEmail":"ada@example.com","checkout.Total":120.5,"checkout.ItemCount":3,"checkout.CartId":7,"{OriginalFormat}":"Checkout completed"}}

Each property of the record became a separate property with the checkout. prefix. And so did checkout.CustomerEmail: if someone adds a phone number to the record tomorrow, it quietly enters the log too. You can leave sensitive fields out with [LogPropertyIgnore] and drop the prefix with OmitReferenceName:

public sealed record SafeCheckoutInfo(
    int CartId,
    int ItemCount,
    decimal Total,
    [property: LogPropertyIgnore] string CustomerEmail);

public static partial class SafeCheckoutLog
{
    [LoggerMessage(EventId = 2003, Level = LogLevel.Information, Message = "Checkout completed")]
    public static partial void CheckoutCompleted(this ILogger logger,
        [LogProperties(OmitReferenceName = true)] SafeCheckoutInfo checkout);
}

{"EventId":2003,"LogLevel":"Information","Category":"Bookstore.Orders","Message":"Checkout completed","State":{"Message":"Total=120,5,ItemCount=3,CartId=7,{OriginalFormat}=Checkout completed","Total":120.5,"ItemCount":3,"CartId":7,"{OriginalFormat}":"Checkout completed"}}

Ignoring isn't the only option; logging the email masked, meaning redaction and data classification, is the topic of this series' "Sensitive Data in Logs" post.

There's a detail that's easy to miss here: the moment you add this package to the project, the package's own generator (Microsoft.Gen.Logging) takes over from the SDK's (Software Development Kit) LoggerMessage generator and produces all [LoggerMessage] methods. That's why the "Message" field inside State above and the reversed order of the properties look different. The generated code is different too: it writes the parameters into a KeyValuePair<string, object?> array, meaning with boxing. When I ran the same benchmark with this package, the disabled level still allocated zero, but the enabled level changed:

| Enabled_SourceGenerated  | 56.8422 ns | 2.6046 ns | 1.7228 ns |  2.89 |    0.11 | 0.0200 |     168 B |        1.31 |

168 bytes instead of 88, 57 ns instead of 47. Still better than the extension method (216 bytes), but "I added the Telemetry package and nothing changed" isn't true either. If you need features like redaction and enrichment, the price is reasonable; if not, think before adding the package just for [LogProperties].

Let the Compiler Catch Your Mistakes

A quiet benefit of the source generator is compile-time checking. Here's the real output when I wrote {CartId} in the template and named the parameter basketId:

Broken.cs(7,6): error SYSLIB1014: Template 'CartId' is not provided as argument to the logging method (https://learn.microsoft.com/dotnet/fundamentals/syslib-diagnostics/syslib1014)
Broken.cs(8,79): warning SYSLIB1015: Argument 'basketId' is not referenced from the logging message (https://learn.microsoft.com/dotnet/fundamentals/syslib-diagnostics/syslib1015)

Make the same mistake with an extension method and the compiler says nothing; the property name comes out wrong in the log, and you only notice when a query returns no results.

The compiler doesn't catch everything. According to the documentation, using the same EventId in two methods should produce a SYSLIB1006 warning; in my build with the .NET 10.0.402 SDK, giving EventId = 3001 to two methods in the same class produced no warning, and the generator happily generated both methods. Don't leave EventId uniqueness to the compiler; keeping the catalog in one file and writing a simple reflection test is more reliable.

In Production

Split EventId ranges by bounded context or module: orders in the 1000s, payments in the 2000s, inventory in the 3000s, and so on. In the log tool, the filter EventId >= 1000 and EventId < 2000 alone means "all logs of the order module". It's a dimension independent of the category; it doesn't break when code moves from one namespace to another.

Once an EventId has shipped, don't reuse it for a different meaning. Saved queries, dashboards and alerts in the log tool may depend on it. You can fix the template text; if the meaning changes, give it a new id.

Raising the CA1848 analyzer rule to a warning is the cheapest way to steer a team toward source-generated methods. But don't try to convert every line: writing a catalog method for a log written once at application startup brings nothing. Focus on hot paths, meaning code that runs per request and inside loops.

Do the measurement in your own environment too. The numbers here were taken on an Apple M5 with a fake provider; the cost of a real sink (Serilog, an OpenTelemetry exporter) comes on top, and that's usually the dominant part. We'll cover the sink side in this series' "Serilog Sinks" post.

Common Pitfalls

First, thinking the IsEnabled guard is needed only for expensive arguments. The measurement showed that even three simple numbers mean 128 bytes; an "expensive" argument is expensive because of boxing even when it isn't a method call.

Second, passing an expensive argument to a source-generated method: logger.CartSummary(cart.Id, cart.Items.Count, CalculateTotal(cart)). The generator's IsEnabled check is inside the method; CalculateTotal runs at the call site, before the check. If there's a truly expensive computation, still wrap the call in IsEnabled.

Third, the exception parameter. If the method signature has a parameter of type Exception, the generator puts it into the log's exception field, not into the template. Don't add a separate placeholder for the exception in the template; the generator warns about that, because the exception is already carried in the log's own field, with its stack trace.

Fourth, using [LogProperties] on large object graphs. Transitive = true expands nested objects too; it dumps all lines of an Order and its customer into a single event. The event's size and the risk of sensitive data grow together.

Fifth, treating the generated code as "magic" and never looking at it. Turn on EmitCompilerGeneratedFiles once, read it, then turn it off. Seeing which generator runs and how parameters are carried is the only way to understand the 88 versus 168 byte difference above.

A Small Experiment

★☆☆ Add Disabled_Interpolated to the benchmark: _logger.LogDebug($"Cart {_cartId} has {_itemCount} items, total {_total}"). Measure how many bytes interpolation allocates at a disabled level and compare it with Disabled_Extension.

★★☆ Add a PaymentFailed event (EventId 1006, Error) that takes an Exception parameter to OrderLog. Find in the file under obj/.../generated how the exception is passed to the LoggerMessage.Define delegate.

★★★ Write a unit test that scans all [LoggerMessage] attributes with reflection and fails if an EventId repeats within the same assembly. Make the test go red with this post's 3001 collision, then fix it.

Our events are now cheap and consistent. In the next post we move to the infrastructure that carries them: setting up Serilog in depth, catching startup failures with a bootstrap logger, configuration from appsettings, enrichers, and request logging that produces a single summary event per request.