Bits of .NET

🔧 The Log Line That Ran Even When Nobody Was Listening

A source-generated logging method is supposed to skip the actual work of formatting a message entirely when its log level is disabled in configuration, which is the whole performance case for using it instead of a plain string interpolation. That guarantee covers the message template itself – it does not extend to whatever expression you pass in as an argument, because every argument is evaluated by the caller before the generated method is ever invoked. A seemingly innocent argument that calls a method, serializes an object, or walks a collection still runs in full on every single call, disabled log level or not, and the cost hides in code that looks like it should be free.

🔎 The Problem

public partial class OrderService
{
    [LoggerMessage(Level = LogLevel.Debug, Message = "Order snapshot: {Snapshot}")]
    partial void LogOrderSnapshot(string snapshot);

    public void Process(Order order)
    {
        // The generated method itself skips formatting when Debug
        // is disabled - but the argument expression right here is
        // evaluated by THIS line, before LogOrderSnapshot ever runs,
        // so SerializeFullSnapshot() executes on every single call
        // no matter what level is configured.
        LogOrderSnapshot(SerializeFullSnapshot(order));
    }

    string SerializeFullSnapshot(Order order)
    {
        // A full JSON serialization of a deep object graph - meant
        // to be a debug-only diagnostic, not something that runs on
        // every order in production with Debug logging turned off.
        return JsonSerializer.Serialize(order, DeepGraphOptions);
    }
}

✅ Fix: Keep Expensive Arguments Out of the Call Entirely

• Guard an expensive argument expression with an explicit IsEnabled check before building it, so the serialization or formatting work only happens when the configured log level would actually use the result.
• Pass the raw pieces the message template needs – an identifier, a count, a status – as separate structured arguments instead of pre-building one expensive composite string, letting the generated method’s own level check decide whether formatting ever happens.
• Reserve a full object dump for a dedicated, clearly named diagnostic method gated by its own explicit check, rather than folding it into a routine log call that runs on every request regardless of the configured level.

⚠️ Why This Is Easy to Miss

• The whole point of switching to source-generated logging is that the framework promises to skip unnecessary work, so it is easy to assume that promise covers everything inside the call, including the arguments, rather than just the formatting step after they arrive.
• A local development environment usually runs with verbose logging enabled anyway, so the expensive argument runs there regardless of the guard – the actual waste only becomes visible once production runs with a quieter configured level.