Measuring Python Logging Overhead

Before you optimise a logging pipeline, you need to know which of its four costs you are actually paying. This page builds a benchmark that attributes time to argument evaluation, the level check, record construction, and the write — and then re-runs it under concurrency, where the answer changes. It is for engineers who suspect logging is on the critical path and want a number rather than an opinion. It belongs to the Python logging performance and overhead guide, part of the Python logging fundamentals and structured data section.

The single most common measurement error is benchmarking against a sink that does no work, then concluding logging is cheap. It is cheap — right up to the handler.

Prerequisites

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

export PYTHONHASHSEED=0     # stable dict ordering between runs

Pin the interpreter to whatever production runs. Logging's hot path has changed between minor versions, so a number from 3.11 does not transfer to 3.13.

Implementation

Step 1 — Build a harness that reports medians, not means. A single timing run on a shared CI machine is noise. Take three batches and report the median; a mean is dragged around by whichever batch collided with another process.

# bench.py
import io
import logging
import time
from statistics import median

def ns_per_call(fn, n: int = 100_000, batches: int = 3) -> float:
    fn()                                          # warm caches and imports
    times = []
    for _ in range(batches):
        start = time.perf_counter_ns()
        for _ in range(n):
            fn()
        times.append((time.perf_counter_ns() - start) / n)
    return median(times)

Step 2 — Measure the disabled path, both call styles. This is the number that applies to every hot-path call site in the codebase, including the ones nobody looks at because "DEBUG is off in production anyway".

logger = logging.getLogger("bench")
logger.setLevel(logging.INFO)                     # DEBUG is disabled
logger.addHandler(logging.StreamHandler(io.StringIO()))

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

print("disabled f-string ", ns_per_call(lambda: logger.debug(f"row {row!r}")))
print("disabled %-args   ", ns_per_call(lambda: logger.debug("row %r", row)))

Step 3 — Attribute the record-construction cost field by field. Toggle one flag at a time and re-measure. Bundling them tells you the total; separating them tells you which one to switch off.

def emitted() -> None:
    logger.info("row %r", row)

logging.logProcesses = logging.logThreads = logging.logMultiprocessing = True
baseline = ns_per_call(emitted, n=20_000)

logging.logProcesses = False
no_pid = ns_per_call(emitted, n=20_000)

logging.logThreads = logging.logMultiprocessing = False
no_thread = ns_per_call(emitted, n=20_000)

print(f"all fields {baseline:.0f} ns · no pid {no_pid:.0f} ns · minimal {no_thread:.0f} ns")

Then do the same for caller information, which is controlled by the format string rather than by a flag: measure once with %(message)s and once with %(filename)s:%(lineno)d %(message)s, and the difference is what the stack walk costs you.

Step 4 — Swap in the real sink. Repeat the enabled-level measurement against the actual production handler — the file, the socket, the OTLP exporter — and subtract the null-sink number. What remains is the write.

real = logging.getLogger("bench.real")
real.setLevel(logging.INFO)
real.addHandler(production_handler())             # the one from your dictConfig
with_write = ns_per_call(lambda: real.info("row %r", row), n=5_000)
print(f"write cost ≈ {with_write - no_thread:.0f} ns")

Use fewer iterations here: five thousand writes to a real file is already a meaningful amount of I/O, and a hundred thousand will tell you about your disk's write cache rather than about logging.

Step 5 — Re-run under concurrency. Handler.handle() takes the handler's lock around emit(), so N threads logging to one handler do not get N times the throughput. This is the step that separates a benchmark from a prediction.

import threading

def concurrent(threads: int, per_thread: int = 20_000) -> float:
    barrier = threading.Barrier(threads)
    def worker():
        barrier.wait()                            # start together
        for _ in range(per_thread):
            real.info("row %r", row)
    workers = [threading.Thread(target=worker) for _ in range(threads)]
    start = time.perf_counter_ns()
    for w in workers: w.start()
    for w in workers: w.join()
    return (time.perf_counter_ns() - start) / (threads * per_thread)

for n in (1, 2, 4, 8):
    print(f"{n} threads: {concurrent(n):.0f} ns/call")

Configuration options

Verification

Run the whole matrix and check the shape of the result before trusting any single number.

python bench.py

Expected Output:

disabled f-string   4180 ns
disabled %-args      210 ns
all fields          9640 ns
no pid              9120 ns
minimal             8460 ns
with caller info   13980 ns
write cost ≈       21400 ns
1 threads: 31200 ns/call
2 threads: 48700 ns/call
4 threads: 79300 ns/call
8 threads: 142500 ns/call

Three things in that output are the actual findings: the disabled f-string costs twenty times the disabled percent-style call, caller information adds roughly 60 percent to an emitted record, and per-call cost more than quadruples from one thread to eight. The first is a lint rule, the second is a format-string decision, and the third is the argument for non-blocking logging with QueueHandler.

Then freeze the two numbers that matter as a CI assertion:

def test_hot_path_logging_stays_cheap(benchmark):
    logger = logging.getLogger("hot")
    logger.setLevel(logging.INFO)
    payload = {"id": 1}
    benchmark(lambda: logger.debug("row %r", payload))
    assert benchmark.stats["mean"] < 1e-6           # a disabled call must stay sub-microsecond

Expected Output:

test_bench.py::test_hot_path_logging_stays_cheap PASSED

Common mistakes

The benchmark says logging is free

Error signature: measured cost of a few microseconds per call, while production P99 moves with the log sink's health. Root cause: the handler wrote to io.StringIO, so the write — the only stage that can take milliseconds — was excluded. Remediation: run the enabled-level case against the real handler as well and report the difference explicitly as the write cost.

Results move 30 percent between runs

Error signature: consecutive runs disagree well beyond any change you made. Root cause: too few iterations, a single batch, or CPU frequency scaling on a laptop. Remediation: raise iterations until a batch takes tens of milliseconds, take the median of three, and pin the benchmark to a machine class in CI rather than comparing across runners.

The concurrency case is never run

Error signature: a queue is judged unnecessary from a single-threaded benchmark, then added six months later during an incident. Root cause: handler lock contention does not exist at concurrency one, which is where the benchmark stopped. Remediation: run the thread sweep at your real worker count. If the per-call cost climbs with threads, the lock is the finding, not the sink.

Turning the numbers into decisions

A benchmark that produces numbers nobody acts on is a slow way of confirming an intuition. Three thresholds are worth agreeing in advance, so the result of a run leads directly to a decision rather than to a discussion.

Is the disabled path free enough? Below roughly one microsecond per call, a disabled log call is invisible even in a tight loop, and no further work is justified. Above five microseconds, something is evaluating arguments at the call site — an f-string, a repr of a large object, a function call that produces the value — and the fix is at the call site rather than in the configuration. That is a lint-level rule and can be enforced mechanically.

Is the emitted path worth optimising? Compare the CPU cost per emitted record against the request's own budget. At 10 microseconds per record and 10 records per request, logging is 100 microseconds of a request that takes 40 milliseconds: a quarter of a percent, and not where the time is. At 10 records per row in a batch job processing 50 000 rows, the same number is five seconds per job, and it is worth attention. The absolute cost does not change; its significance does entirely.

Does the write need a queue? This is the only one of the three that is not really about CPU. If the measured write cost has a heavy upper tail — most writes fast, occasional writes in the milliseconds — the service's tail latency is coupled to the sink's health, and a queue decouples them regardless of the average. A flat, fast write distribution to a local pipe genuinely does not need one.

Making the benchmark part of the build

The value of these numbers decays quickly, because the thing they measure changes with every dependency upgrade and every new field in the formatter. Running the harness once during an investigation answers today's question; running it in CI answers the question you have not asked yet.

# tests/test_logging_perf.py
import logging
import pytest

@pytest.mark.benchmark(group="logging")
def test_disabled_call_stays_sub_microsecond(benchmark):
    logger = logging.getLogger("hot")
    logger.setLevel(logging.INFO)
    payload = {"id": 1, "items": list(range(20))}
    benchmark(lambda: logger.debug("row %r", payload))
    assert benchmark.stats["mean"] < 1e-6

@pytest.mark.benchmark(group="logging")
def test_emitted_record_stays_under_budget(benchmark):
    logger = logging.getLogger("emit")
    logger.setLevel(logging.INFO)
    benchmark(lambda: logger.info("row %r", {"id": 1}))
    assert benchmark.stats["mean"] < 30e-6

Expected Output:

tests/test_logging_perf.py::test_disabled_call_stays_sub_microsecond PASSED
tests/test_logging_perf.py::test_emitted_record_stays_under_budget PASSED

Two assertions, both loose enough that ordinary machine variation does not trip them, and both tight enough to catch the specific regressions that matter: an f-string reintroduced into a hot path, and a formatter that started doing something expensive. Pin them to a machine class in CI rather than comparing across runner types, because a shared runner's variance is larger than most of the effects being measured.

What not to measure

Two figures look informative and are not. Records per second from a loop with no other work tells you the maximum rate of a benchmark, not of a service, because a real service spends most of its time on something else and the logging path is never warm in the same way. And the memory cost of a log record is dominated by whatever the record references rather than by the record itself, so measuring sys.getsizeof on a LogRecord returns a number that is both accurate and useless.

Related

• Python logging performance and overhead — the parent guide: the full cost model and every knob.
• Rate limiting and sampling noisy loggers — what to do once the measurement says volume is the problem.
• Non-blocking logging with QueueHandler — the fix for a write cost you cannot reduce.
• Handler architecture for Python logging — where the lock sits and why it serialises.
• Benchmarking Python logging libraries — the same harness applied across structlog, Loguru and the standard library.

Frequently Asked Questions