logging vs print: Throughput Lab

Intro — what this post promises

Is logging “just print with levels”? This lab counts lines/s for print vs logging.INFO through a StreamHandler to /dev/null and StringIO, plus a disabled logger and a level-filtered debug() call. The formatting story is measured, not assumed.

Related links:

• string concat vs join localhost lab
• set vs list membership localhost lab
• python re vs str methods localhost lab
• json vs orjson vs msgpack localhost lab
• base64 vs hex encode localhost lab
• pathlib vs os.path localhost lab
• sorted vs heapq vs bisect localhost lab
• Why your average latency graph is lying (p50 / p95 / p99)

Lab honesty (1 Oct 2026 IST): Python 3.13.5. 20,000 lines per batch. Formatter: %(levelname)s %(name)s %(message)s. Affiliates: 0. Not a journald/syslog/network handler study — local stream only.

Verdict up front: print to /dev/null ~5.14M lines/s. INFO logging to /dev/null ~159k (~0.031×, ~6282 ns/line). Pre-formatting the message only moves that to ~178k — the LogRecord + handler dominates, not % interpolation. A disabled logger stays near print (~5.09M).

Arms

Lab topology

N = 20000 lines / repeat, 7 repeats, p50
Message: request id / path / status / elapsed
Sinks: /dev/null and io.StringIO
No propagation; one StreamHandler

Script: lab-evidence/51-logging-vs-print/results/run_lab.py.

Lead table — lines/s (p50)

Formatting is not the cliff

Lazy % vs preformatted on /dev/null: 159,195 vs 178,343 lines/s — about 1.12×, roughly 674 ns saved. The remaining ~5607 ns is record construction, formatter, and the handler lock/write even when the sink is /dev/null.

So: do pass args to log.info(fmt, *args) so a disabled/filtered call can skip interpolation — that path is cheap (filtered debug ~4.59M/s). Do not expect pre-building the string to make an enabled INFO logger competitive with print.

isEnabledFor then info on an enabled logger matches the slow path (~159k/s). The guard only helps when the level is off.

StringIO vs /dev/null is a small gap next to the logging tax (print StringIO even slightly faster here — buffer, no device).

Pitfalls

1. Benchmarking only logger.disabled and concluding logging is free — the hot path is an enabled handler.
2. Blaming f-strings inside info(f"...") — you pay interpolation even when filtered. Use % args or isEnabledFor.
3. Root logger + propagate — extra handlers multiply this cost. This lab sets propagate = False.
4. /dev/null is not production — a file, queue, or network handler is slower still.

When to pick what

Reproduce

python3 lab-evidence/51-logging-vs-print/results/run_lab.py

Evidence: /workspace/lab-evidence/51-logging-vs-print/results/.

Closing

Enabled logging is a different cost class than print. On this box print to /dev/null is ~5.14M lines/s; INFO StreamHandler is ~159k (~32× slower). Preformatting saves only ~674 ns. A disabled or filtered logger stays near ~5.1–4.6M/s. Log the lines you mean; don’t log inside the inner loop unless you measured the level as off.