Python Logging Performance and Overhead

Logging is never the bottleneck until the day it is — a debug line inside a per-row loop, a JSON formatter running on the request thread, a network handler that blocks when the collector goes slow. This guide gives backend engineers and SREs a cost model for a Python log call, a way to measure each stage, and the specific knobs that remove each cost. It is part of the Python logging fundamentals and structured data section, and the concrete walkthroughs are in measuring Python logging overhead and rate limiting and sampling noisy loggers.

The headline: a log call that is filtered out costs a few hundred nanoseconds, a log call that is emitted costs single-digit microseconds of CPU, and the write costs whatever the sink costs — which is the only one of the three that can be measured in milliseconds.

Prerequisites

The measurement work needs nothing but the standard library; the pins below are for the benchmark harness and the async example.

pip install "pytest-benchmark>=4.0.0,<6.0.0" \
            "python-json-logger>=2.0.7,<4.0.0"

export PYTHONHASHSEED=0        # keep dict ordering stable between benchmark runs

Concept and architecture

A call to logger.info(...) runs a fixed sequence, and each step can be removed independently.

The level check comes first. Logger.isEnabledFor() compares the requested level against the cached effective level — a walk up the logger hierarchy that Python memoises in Logger._cache and invalidates whenever any level changes. It is a dictionary lookup and a comparison. The important part is what happens before it: Python evaluates the arguments at the call site, so logger.debug(f"row {row!r}") builds that string whether or not DEBUG is enabled.

Record construction allocates a LogRecord and fills roughly twenty attributes, several of which call into the interpreter: os.getpid(), threading.current_thread(), and time.time(). Three module-level flags — logging.logProcesses, logging.logThreads, logging.logMultiprocessing — switch off the ones you do not print.

Caller inspection is the expensive optional step. Logger.findCaller() walks the stack frame by frame, skipping logging's own frames, to fill filename, lineno, funcName and optionally stack_info. It runs only when the record needs those fields — which, in practice, means whenever your format string mentions them.

Filters and formatting run next, on the calling thread unless a queue intervenes. A JSON formatter serialising a dozen fields is on the order of ten microseconds; a redaction filter running a dozen regexes can be more.

The write is the one that matters. A StreamHandler to a pipe that something is actively draining is fast. The same handler when the reader stalls, a FileHandler doing a rotation check, or an HTTP handler waiting on a collector — those block the calling thread for as long as the sink takes. This is why non-blocking logging with QueueHandler is a latency control, not a micro-optimisation.

Step-by-step implementation

Step 1 — Fix the call sites that pay before the level check. The rule is mechanical: no f-strings, no .format(), no string concatenation, and no repr() of anything large in a logging call. Pass the values; let the formatter interpolate them if it ever needs to.

# pays the cost on every iteration, even with DEBUG off
logger.debug(f"processed row {row!r} in {elapsed:.3f}s")

# pays nothing until a handler actually formats the record
logger.debug("processed row %r in %.3fs", row, elapsed)

# for arguments that are expensive to produce at all
if logger.isEnabledFor(logging.DEBUG):
    logger.debug("plan: %s", explain_query(sql))      # only run the explain if it will be logged

Step 2 — Turn off the record fields nothing reads. These three flags are module-level and take effect for every record created afterwards. Set them at startup, next to dictConfig.

import logging

logging.logProcesses = False        # skips os.getpid() per record
logging.logThreads = False          # skips threading.current_thread() per record
logging.logMultiprocessing = False  # skips the multiprocessing import path per record

Only do this once you have confirmed no format string, no filter and no formatter reads process, thread, threadName or processName. In a containerised service where every process is one replica and thread identity is carried in your own structured fields, all three are dead weight.

Step 3 — Keep caller inspection out of hot paths. %(filename)s:%(lineno)d is genuinely useful in development and genuinely expensive in a loop. Drop it from the production format string; when a wrapper function makes the reported line useless anyway, use stacklevel to point at the real caller instead of paying twice.

def log_with_context(logger, level, msg, *args, **kwargs):
    # stacklevel=2 reports the caller of this helper, not this line
    logger.log(level, msg, *args, stacklevel=2, **kwargs)

Step 4 — Move formatting and I/O off the request path. A QueueHandler in front of the real handlers converts a variable-cost write into a bounded enqueue. The caller builds the record and puts it on a queue; a listener thread runs the filters, formatters and handlers.

import queue
from logging.handlers import QueueHandler, QueueListener

log_queue: queue.Queue = queue.Queue(maxsize=10_000)     # bounded — always
listener = QueueListener(log_queue, *concrete_handlers, respect_handler_level=True)
listener.start()
logging.getLogger().addHandler(QueueHandler(log_queue))

The queue must be bounded and must have an explicit overflow policy, or you have traded a latency problem for a memory problem. The full treatment — drop policies, shutdown draining, what happens to exc_info at the boundary — is in handler architecture.

Step 5 — Shed volume at the source. When one logger produces thousands of near-identical records a second, no amount of queue tuning helps; the records still have to be built, serialised and stored. Rate-limit or sample that logger specifically, keeping a count of what was suppressed. That is the subject of rate limiting and sampling noisy loggers.

Configuration reference

Async and concurrency considerations

Under asyncio, a synchronous handler is worse than slow: it blocks the event loop, so one stalled write delays every other request the loop is serving. The observable symptom is a P99 that correlates with the log sink's health rather than with your own code, and it does not show up in a single-threaded benchmark at all.

Threads add a second effect. Handler.handle() acquires the handler's lock around emit(), so concurrent loggers serialise on it. With four worker threads writing to one StreamHandler, formatting and writing are effectively single-file, and the queue depth you measure at concurrency four is not four times what you measured at concurrency one.

import asyncio, logging

async def handler(request):
    # a synchronous handler here blocks the loop for the duration of the write
    logging.getLogger("api").info("request %s", request.path)
    return await do_work(request)

The fix is the same in both cases — a queue in front — but the measurement has to be done under the real concurrency, which is the point most benchmarks miss.

Production code examples

A measurement harness you can run in CI to catch a regression the day it lands, rather than in an incident three months later. It times the four paths that matter and prints a table.

# bench_logging.py — run with: python bench_logging.py
import io
import logging
import time
from statistics import median

def time_call(fn, n: int = 100_000) -> float:
    """Median nanoseconds per call over three batches."""
    batches = []
    for _ in range(3):
        start = time.perf_counter_ns()
        for _ in range(n):
            fn()
        batches.append((time.perf_counter_ns() - start) / n)
    return median(batches)

logging.logProcesses = logging.logThreads = logging.logMultiprocessing = False
sink = logging.StreamHandler(io.StringIO())          # a sink with no I/O cost
sink.setFormatter(logging.Formatter("%(asctime)s %(levelname)s %(message)s"))
logger = logging.getLogger("bench")
logger.addHandler(sink)
logger.setLevel(logging.INFO)

row = {"id": 42, "email": "a@example.com", "items": list(range(20))}

cases = {
    "disabled, f-string":   lambda: logger.debug(f"row {row!r}"),
    "disabled, %-args":     lambda: logger.debug("row %r", row),
    "enabled, %-args":      lambda: logger.info("row %r", row),
    "enabled, guarded":     lambda: logger.isEnabledFor(logging.INFO) and logger.info("row %r", row),
}

print(f"{'case':<22}{'ns/call':>10}")
for name, fn in cases.items():
    print(f"{name:<22}{time_call(fn):>10.0f}")

Expected Output:

case                     ns/call
disabled, f-string          4180
disabled, %-args             210
enabled, %-args             9640
enabled, guarded            9720

The absolute numbers depend on the machine; the ratios do not. A disabled f-string call costs roughly twenty times a disabled percent-style call, and an emitted record costs roughly fifty times a discarded one. That second ratio is the argument for sampling rather than for micro-optimising the call site.

For a service, wire the same idea as a pytest-benchmark test with a threshold, so CI fails when someone reintroduces an f-string into a hot loop:

def test_disabled_debug_is_cheap(benchmark):
    logger = logging.getLogger("hot")
    logger.setLevel(logging.INFO)                    # DEBUG is off
    row = {"id": 1}
    result = benchmark(lambda: logger.debug("row %r", row))
    assert benchmark.stats["mean"] < 1e-6            # under a microsecond per call

Expected Output:

test_perf.py::test_disabled_debug_is_cheap PASSED
------------------ benchmark: 1 tests ------------------
Name                        Mean        StdDev
test_disabled_debug     215.3 ns       9.1 ns

Common mistakes

Benchmarking with a null handler and shipping to a network sink. A benchmark whose handler writes to io.StringIO measures the CPU stages and nothing else. It is the right tool for comparing call styles and the wrong one for capacity planning — the real cost is the write, and the write is exactly what the harness removed.

Raising the log level to fix a performance problem. It reduces the number of records emitted, which helps, but every f-string call site keeps paying full price, and the loop that produced the volume still runs. Fix the call sites and sample the noisy logger; the level is a blunt instrument that also removes the records you wanted.

Adding a queue and leaving it unbounded. queue.Queue() with no maxsize never blocks and never drops — it grows. Under a sink outage that is an out-of-memory kill instead of a latency spike, usually at the worst possible moment. Bound it and decide explicitly what gets shed first.

Measuring single-threaded. Handler locks serialise emit() across threads, so the interesting contention only appears at your real worker count. A benchmark at concurrency one systematically under-reports the cost of a synchronous handler in a threaded WSGI server.

Leaving caller information in the production format string. %(filename)s:%(lineno)d forces a stack walk on every emitted record. It is worth it in development; in a service that emits thousands of records a second it is several percent of a core, spent re-deriving something the logger name already tells you.

Sampling errors. Every sampling scheme should exempt WARNING and above. Errors are rare by definition, and the one you dropped is the one the incident was about.

Budgeting the pipeline end to end

Per-call cost is only half the picture. The other half is what a log record costs after it leaves the process, and that number decides how much of the first half is worth optimising.

A rough model, for a service emitting 2 000 records per second per replica across twenty replicas: 40 000 records per second, at roughly 600 bytes each once serialised, is about 24 MB/s or two terabytes a day before compression. Ingestion is usually billed on that volume, retention on the compressed result, and query cost on how much has to be scanned. Against those numbers, ten microseconds of CPU per record is 0.4 of a core across the fleet — real, but an order of magnitude less significant than the storage.

That ratio has a practical consequence: reduce record count before reducing per-record cost. Every technique on this page divides into those two categories, and they are not equally valuable.

The last row is the one worth revisiting periodically. Services accumulate log calls that made sense during a migration three years ago and have not been read since; a query for the record shapes nobody has ever filtered on usually finds several of them.

Where the budget actually goes

Two shapes account for most surprises. The first is a per-item log call inside a loop that processes a batch: one record per row in a 50 000-row import is 50 000 records for a job that produced one business outcome, and the fix is to log the outcome plus a count rather than each item. The second is a debug call left at INFO after an investigation, which is invisible in code review because the line looks identical to a legitimate one.

# 50 000 records for one job
for row in rows:
    logger.info("imported row %s", row.id)

# one record, and the same information
logger.info("import finished", extra={"rows": len(rows), "failed": failures, "duration_s": elapsed})

The second form is also better telemetry: rows and failed are fields you can chart, whereas fifty thousand individual records are something you can only count.

Deciding what to keep

A record earns its place if someone would query it. In practice that reduces to three categories: records that describe a state change worth auditing, records that carry a failure with enough context to act on, and records that mark a boundary — a request starting, a job finishing — that other records hang off. Anything that does not fall into one of those is a candidate for deletion or for a metric, and a metric is almost always cheaper: a counter increment is nanoseconds and one series, against microseconds and several hundred bytes of storage for the equivalent record.

The test for the third category is worth applying literally: open the log search, filter for that record shape over the last thirty days, and look at whether anyone ever narrowed it further. A record shape that only ever appears in an unfiltered tail view is a record shape nobody reads, and deleting the call is both the cheapest optimisation available and an improvement to the signal-to-noise ratio of everything around it. Records that fail the test rarely fail it narrowly.

That substitution is the single largest saving available in most services, and it is a design decision rather than a tuning one. The instrument choice behind it is covered in choosing between Counter, Gauge, Histogram and Summary.

Related

• Python logging fundamentals and structured data — the parent section: record schema, logger hierarchy, and the handler graph.
• Measuring Python logging overhead — the benchmark harness in detail, including under concurrency.
• Rate limiting and sampling noisy loggers — shedding volume at the source without losing the signal.
• Non-blocking logging with QueueHandler — the queue wiring, drop policies, and shutdown draining.
• Handler architecture for Python logging — where each cost sits in the graph.
• How to configure Python logging for production — the baseline configuration these knobs modify.

Frequently Asked Questions