Lazy Formatting and Expensive Log Arguments

A debug statement that is never emitted can still cost milliseconds on every call, because Python evaluates a function's arguments before the function runs — and the logger's level check happens inside the function. This page covers exactly what is deferred and what is not, why f-strings defeat the level check, and the patterns that make disabled logging genuinely free on a hot path. It is a task article under logging performance and overhead, part of the Python logging fundamentals and structured data section.

Prerequisites

The standard library is all that is needed. A benchmark harness makes the measurements in the verification section reproducible.

pip install "pyperf>=2.7.0,<3.0.0"

Implementation

Step 1 — Pass arguments to the logger instead of pre-formatting. The logging module substitutes arguments into the message only when a handler formats the record, and a record discarded by the level check is never formatted. Passing arguments separately therefore defers all string building until it is certain to be needed. It also keeps the message template constant, which means records group correctly in a log store — a second benefit that is often worth more than the first.

import logging
log = logging.getLogger("orders")

# formatting deferred; template constant and groupable
log.debug("order %s total %d items %d", order.id, order.total, len(order.items))

# formatting happens now, even if DEBUG is disabled
log.debug(f"order {order.id} total {order.total} items {len(order.items)}")

Step 2 — Guard genuinely expensive arguments. Deferral covers formatting, not evaluation: Python evaluates every argument expression before calling any function. An argument that serialises a large object, walks a data structure or queries something is computed in full and then thrown away. An explicit level check around the call skips the evaluation entirely, at the cost of one comparison that the logging module caches.

if log.isEnabledFor(logging.DEBUG):
    log.debug("order snapshot %s", json.dumps(order.to_dict(), default=str))

Step 3 — Use a lazy wrapper where a guard is awkward. Guards are clear but noisy when repeated. A small wrapper whose string conversion performs the work gives the same effect inside an ordinary log call: the wrapper object is created cheaply, and the expensive computation runs only if a formatter converts it to a string.

class Lazy:
    """Defer an expensive computation until the record is actually formatted."""
    __slots__ = ("_fn",)

    def __init__(self, fn):
        self._fn = fn

    def __str__(self) -> str:
        return str(self._fn())

log.debug("order snapshot %s", Lazy(lambda: json.dumps(order.to_dict(), default=str)))

Step 4 — Apply the same thinking to structured fields. Fields passed through extra are evaluated at the call too. A structured log call building a large dictionary of context pays for it whether or not the record is emitted. The guard applies unchanged; with structlog, a processor that computes expensive fields — placed after the level filter in the processor chain — achieves the same deferral declaratively, as described in writing custom structlog processors.

Step 5 — Keep side effects out of log arguments. An argument whose evaluation changes state — incrementing a counter, consuming an iterator, advancing a cursor — runs or does not run depending on the log level if it is guarded, and always runs if it is not. Either way the program's behaviour now depends on logging configuration, which is the kind of bug that appears only when somebody lowers a level to investigate a different problem.

# a consumed iterator changes behaviour depending on whether this line runs
log.debug("first item %s", next(items))          # don't

first = next(items)                              # do: side effect independent of logging
log.debug("first item %s", first)

Step 6 — Measure the disabled path. On a genuinely hot path, confirm the statement is free when its level is disabled. The comparison of the three forms in a tight loop makes the cost visible and settles arguments about whether a guard is worth its noise.

Where expensive arguments hide

The obvious case — json.dumps of a large object in a debug statement — is easy to spot in review. Several less obvious forms are worth knowing, because they look cheap at the call site.

Implicit __repr__ and __str__. Passing an ORM object or a large dataclass as an argument looks free, and with deferred formatting it is — until the record is emitted, at which point the object's representation is computed. Some representations are expensive: an ORM object whose __repr__ loads related objects triggers queries during formatting. Under a QueueHandler, that formatting happens on the listener thread, possibly after the request's database session has closed, which produces errors that appear to come from nowhere.

Properties and descriptors. order.total looks like an attribute read and may be a property that computes a sum over line items, loading them from the database if they are not already loaded. Used as a log argument it runs at the call, regardless of level.

Comprehensions building context. extra={"ids": [i.id for i in items]} builds the list whether or not the record is emitted. For a handful of items this is nothing; for ten thousand it is a measurable allocation on every call.

Calls into other systems. A log argument that calls a cache, a feature flag service or a configuration lookup to include its current value in the record performs a network round trip on every call. This is rare and devastating when it happens on a hot path.

The pattern common to all four is that the cost is not visible at the call site and appears in a profile as time spent in the called function rather than in logging. Profiles that show unexpected time in serialisation or property access from logging call sites — see measuring Python logging overhead — point straight at them.

The level check itself

It is worth understanding why the disabled path is cheap when the arguments are, because it explains the numbers above and a subtle way to make them worse.

Each logger caches the result of its effective level computation. The first call at a given level walks up the logger hierarchy to find the effective level and stores the answer; subsequent calls read the cached value. That cache is invalidated whenever any logger's level changes, anywhere in the process. In normal operation that never happens after startup, and the check costs a dictionary lookup.

Two patterns defeat the cache. The first is changing log levels frequently at runtime — for example, from a request handler that raises a logger's level for one request and lowers it again. Each change clears every logger's cache, and the next call on every logger pays for the full hierarchy walk. The runtime level changes described in changing log levels at runtime are fine because they happen rarely; per-request toggling is not.

The second is creating loggers dynamically — a logger per request, per tenant, or per object, named with a unique identifier. Each new logger is added to the manager's registry permanently, the registry grows without bound, and the first check on each new logger pays for a walk. A fixed set of module-level loggers, with variable context carried as fields rather than in logger names, keeps the check cheap and the registry small.

With both avoided, the disabled path really is a function call and a lookup, and the only thing that can make it expensive is what the caller computes before making the call — which is what the rest of this page is about.

Configuration options

Verification

Measure the forms in a tight loop with the statement's level disabled.

import json, logging, timeit

log = logging.getLogger("bench"); log.setLevel(logging.INFO)
payload = {"items": list(range(500)), "meta": {"k": "v" * 200}}

cases = {
    "guarded":  lambda: log.isEnabledFor(logging.DEBUG) and log.debug("x %s", json.dumps(payload)),
    "args":     lambda: log.debug("x %s %s", 1, "a"),
    "f-string": lambda: log.debug(f"x {1} {'a'}"),
    "expensive":lambda: log.debug("x %s", json.dumps(payload)),
}
for name, fn in cases.items():
    per_call = timeit.timeit(fn, number=100_000) / 100_000 * 1e6
    print(f"{name:10s} {per_call:8.2f} µs")

Expected Output: the expensive argument dominating by two to three orders of magnitude.

guarded        0.09 µs
args           0.24 µs
f-string       0.97 µs
expensive    246.10 µs

Common mistakes

f-strings in log calls. Error signature: formatting cost on every call and messages that cannot be grouped. Root cause: the string built before the logger is called. Remediation: pass arguments separately.

Assuming deferral covers arguments. Error signature: a disabled debug statement showing up in a CPU profile. Root cause: arguments evaluated before the call. Remediation: guard expensive arguments.

Expensive representations formatted off-thread. Error signature: database errors raised from the log listener thread. Root cause: an ORM object's __repr__ running during deferred formatting after its session closed. Remediation: log identifiers, not objects.

Side effects in arguments. Error signature: behaviour that changes when a log level changes. Root cause: a consuming or mutating call inside a log argument. Remediation: compute first, then log the result.

Guarding everything. Error signature: code dense with level checks around trivial statements. Root cause: applying the expensive-argument pattern universally. Remediation: guard only where measurement shows cost.

Frequently Asked Questions