I had a LogDebug sitting in a request handler that fires on every call. Debug is off in production, so I never thought about it. In my head, a disabled log line was free — the logger checks the level, sees it's off, returns. Then I was staring at an allocation profile for something unrelated and noticed that handler throwing off garbage on a code path that, as far as the output was concerned, did nothing at all. The log line nobody read was still allocating. So I went and measured exactly what it costs, and what the source generator buys back.
The call I'd written a thousand times
This is the shape of it. Structured logging, named placeholders, the style everyone (correctly) tells you to use:
logger.LogInformation("Order {OrderId} for {CustomerId} settled in {ElapsedMs} ms",
orderId, customerId, elapsedMs);
Looks clean. But that overload is LogInformation(string, params object?[]), and the compiler has to build that array before it can call anything. So at the call site it emits roughly new object[] { (object)orderId, (object)customerId, (object)elapsedMs }. Three value types, three boxes, one array, and all of it happens before the logger gets a chance to ask whether Information is even enabled. The level check lives inside the call. The allocation already happened on the way in.
I ran it a million times with the level on, then a million more with it off. Allocations come from GC.GetAllocatedBytesForCurrentThread, Release build, small Linux container, the exact same no-op logger sitting under both styles so the only thing that varies is what each one spends to get there. Not a lab. I care about the ratios.
Level ENABLED:
classic template + args 224 B/call ~480 ms
Level DISABLED (nobody reads these):
classic template + args 120 B/call ~90 ms
That 120 bytes on the disabled line is the part that bugged me. The level is off. Nothing gets formatted, nothing gets written, and I'm still paying 120 bytes a call to hand the logger three arguments it immediately throws away. On a handler doing a few thousand requests a second, that's megabytes of garbage a second for log lines that produce not one character of output.
And the 120 isn't a mystery. A three-slot object[] is 48 bytes. Each boxed value type (the long, the int, the double) is 24 bytes. 48 + 72 = 120. The number is almost suspiciously tidy once you know where it comes from.
The [LoggerMessage] version
The source generator has been around since .NET 6 and I'd mostly filed it under "nice for high-volume logging, I'll get to it." You declare a partial method and decorate it:
static partial class Log
{
[LoggerMessage(Level = LogLevel.Information,
Message = "Order {OrderId} for {CustomerId} settled in {ElapsedMs} ms")]
public static partial void OrderSettled(ILogger logger,
long orderId, int customerId, double elapsedMs);
}
At build time the generator fills in the body. The important part is what it generates: a check of IsEnabled first, and when it's enabled, a strongly-typed state struct that holds your arguments as long, int, double — their real types, no object, no array. Call it like Log.OrderSettled(logger, orderId, customerId, elapsedMs).
Same million-iteration run:
Level ENABLED:
[LoggerMessage] source-gen 104 B/call ~160 ms
Level DISABLED (nobody reads these):
[LoggerMessage] source-gen 0 B/call ~4 ms
Zero. Not "less." Zero bytes per call when the level is off, because the generated method guards on IsEnabled before it touches a single argument, and the arguments were never boxed to begin with. The disabled hot path is now a branch and a return.
The enabled numbers are worth a second look too. 224 versus 104. The gap is 120 bytes, the exact array-and-boxes figure from the disabled classic run. What's left, the 104 bytes both styles still spend when enabled, is just the formatted message string itself, which you need anyway if you're going to log anything. The source generator didn't find a trick to log for free. It stopped paying the boxing tax on top.
When I wouldn't bother
If a log statement runs occasionally (startup, a config reload, once per web request at the edge), this is noise. 120 bytes on something that happens a few hundred times total in a process lifetime is not a problem worth a partial method and a static class for. I reach for [LoggerMessage] specifically on the lines that sit inside loops and per-item handlers, the ones that run thousands of times a second whether or not anyone's listening. Everywhere else, the plain extension method is more readable and I leave it alone.
My honest opinion after measuring this: the headline feature of the source generator isn't the throughput on the enabled path, even though it's real. It's the zero on the disabled path. A LogDebug you can leave in a hot loop and forget about, because when Debug is off it costs nothing, changes how I write that code. I stop deleting diagnostic logs to "keep the hot path clean" and just guard them properly for free.
One caveat on reading these figures: the exact byte counts depend on argument types and count — more value-type arguments means more boxes on the classic side, so the gap widens. And the timings include my counting logger's trivial work, so treat them as ratios between the two styles on one machine, not as numbers you'll reproduce to the millisecond.
Here's the whole thing I ran, if you want to check my numbers on your own box:
using System.Diagnostics;
using Microsoft.Extensions.Logging;
sealed class CountingLogger(bool enabled) : ILogger
{
public long Chars;
public IDisposable? BeginScope<TState>(TState state) where TState : notnull => null;
public bool IsEnabled(LogLevel logLevel) => enabled;
public void Log<TState>(LogLevel level, EventId id, TState state,
Exception? ex, Func<TState, Exception?, string> formatter)
{
if (!IsEnabled(level)) return;
Chars += formatter(state, ex).Length;
}
}
static partial class Log
{
[LoggerMessage(Level = LogLevel.Information,
Message = "Order {OrderId} for {CustomerId} settled in {ElapsedMs} ms")]
public static partial void OrderSettled(ILogger logger, long orderId, int customerId, double elapsedMs);
}
static class Bench
{
const int Iterations = 1_000_000;
static void Measure(string label, bool enabled, Action<ILogger> logOnce)
{
var logger = new CountingLogger(enabled);
for (int i = 0; i < 1000; i++) logOnce(logger); // warm up
long before = GC.GetAllocatedBytesForCurrentThread();
var sw = Stopwatch.StartNew();
for (int i = 0; i < Iterations; i++) logOnce(logger);
sw.Stop();
long bytes = GC.GetAllocatedBytesForCurrentThread() - before;
Console.WriteLine($"{label,-34} {(double)bytes / Iterations,5:N0} B/call {sw.ElapsedMilliseconds,5} ms");
}
public static void Main()
{
long id = 840_215; int customer = 12; double ms = 3.74;
Console.WriteLine("Level ENABLED:");
Measure("classic template + args", true,
l => l.LogInformation("Order {OrderId} for {CustomerId} settled in {ElapsedMs} ms", id, customer, ms));
Measure("[LoggerMessage] source-gen", true, l => Log.OrderSettled(l, id, customer, ms));
Console.WriteLine("\nLevel DISABLED (nobody reads these):");
Measure("classic template + args", false,
l => l.LogInformation("Order {OrderId} for {CustomerId} settled in {ElapsedMs} ms", id, customer, ms));
Measure("[LoggerMessage] source-gen", false, l => Log.OrderSettled(l, id, customer, ms));
}
}
One package reference, Microsoft.Extensions.Logging.Abstractions, and it runs on .NET 10.
Have you got a hot path quietly boxing arguments for logs nobody reads? I'd check the disabled case first — that's where the free lunch is hiding. Tell me what you find.
— still benchmarking the things nobody asked me to benchmark
Top comments (0)