If you’ve ever turned a service’s log level up to INFO in production, told yourself the debug lines are free now, and moved on, this one is for you. I did exactly that once. A request handler with a couple of chatty logger.debug(...) lines in the hot loop, flipped to INFO before the deploy, and I filed it under “handled.” The lines weren’t printing anymore. I assumed that meant they weren’t running.
The CPU profile disagreed. The debug lines were near the top, for a log level that emitted nothing.
The problem
A disabled log line is not free. Python’s logging does check the level and drop the line, but it checks inside logger.debug(...), and by the time you call logger.debug(...) you’ve already built the argument. If that argument is an f-string that concatenates a few fields and calls json.dumps on a payload, all of that work happens first, every call, and then the logger looks at the level and throws the finished string away. You paid to produce a message nobody will ever read.
I wanted to see the number, so I put a DEBUG line behind a logger set to INFO and ran it a million times three different ways: an eager f-string, a lazy %-style call, and one wrapped in an isEnabledFor guard.
What a disabled DEBUG line costs, per call
json.dumps of the order payload, on every call, and only then does logging look at the level and drop it: 89.8x the cost of the guard, 3.7x the cost of deferred %-formatting, for zero output. Measured on Python 3.12.13, 1,000,000 iterations, median of 5. Results in benchmarks/logging-hot-path/results/exp1_disabled_debug.csv.The eager version cost 5,260 ns a call. The isEnabledFor guard cost 59. Nothing was logged in any of the three, so that whole gap is pure waste, work done to produce a string that gets dropped one stack frame later.
Here is the shape of it:
# eager: builds the message every time, then logging drops it
logger.debug(f"processed order {order_id}: {json.dumps(payload)}")
# lazy: %-formatting is deferred, only runs if the record is emitted
logger.debug("processed order %s: %s", order_id, payload)
# guarded: skips even the call overhead when the level is off
if logger.isEnabledFor(logging.DEBUG):
logger.debug("processed order %s: %s", order_id, payload)
The lazy form is the one most people already know they should use, and it does help: 1,420 ns instead of 5,260, because the %s interpolation is deferred until logging decides to emit, which it never does here. But json.dumps(payload) in the eager form runs no matter what, because you called it, not the logger. The guard is the only version that skips the argument-building entirely, and on a genuinely hot path that 59-vs-5,260 difference is the one worth caring about.
None of this matters on a line that runs a thousand times a day. It matters a lot on a line that runs inside the loop that runs on every request.
When the line does print, where does it print
Turning debug off gets you out of the first hole. The second one shows up on the lines you actually do want, the INFO lines, and it’s about where the write happens, not whether it happens.
A plain FileHandler does its work on the thread that called logger.info(...). The formatting, the write, and if you care about durability the flush and fsync, all of it runs inline, so your request latency now includes a disk write. Python’s logging.handlers ships a fix for this: a QueueHandler on the caller that just drops the record onto a queue, and a QueueListener on a background thread that drains the queue and does the actual I/O. The caller pays for an enqueue. The disk pays on someone else’s thread.
I timed each logger.info(...) call on the calling thread, 50,000 of them, writing to a durable sink both ways.
Per-call latency on the calling thread, sync vs async handler
p99 (µs)
p99.9 (µs)
The tail is where it hurts. At p99.9 the synchronous handler was 5,752 µs, the async one was 24.6, and the sync worst case was a 31 ms fsync stall sitting right in the middle of a request. Move the I/O to a background thread and the caller stops caring about disk weather.
One honest caveat, because it changes the picture. My first version of this experiment used a plain buffered FileHandler with no fsync, and async lost: the OS page cache swallowed the writes so cheaply that the queue-and-thread machinery just added overhead, and async tail latency came out worse than sync. That run is in the repo under results/attempts/ with a note. The chart above uses a durable sink that flushes and fsyncs every record, which is what forces the same real I/O cost to be paid, and the only variable left is which thread pays it. If your logs go to a buffer the kernel flushes lazily, async buys you much less. If they go somewhere that actually blocks, a socket, a slow disk, a full pipe, it buys you the whole tail.
The cheapest fix is to not log the line at all
The last one isn’t about cost per line, it’s about how many lines. At Twitter-or-any-large-service scale the expensive thing about an INFO line that fires on every event is that it fires on every event. Most of those lines are identical in shape and nobody reads 999 out of 1,000 of them. So don’t write them: sample. Log one in a hundred, keep a counter, move on.
Logging every event vs sampling one in a hundred
Log bytes written, 1M events
Workload throughput (ops/sec)
100x fewer lines, 100x fewer bytes, and the workload ran 48.6x faster, because 99 iterations out of 100 skipped the whole logging call. The throughput jump is really just the first two experiments cashing out at volume: every line you don’t log is an argument you don’t build and a write you don’t do.
The catch is obvious and worth saying out loud. Sampling throws away individual events, so it’s great for “how often does this happen” and useless for “show me the exact request that failed.” Sample the chatty success path, keep every error, and know which of your log lines are which.
The takeaway
Three separate holes, three separate fixes, and the good news is they’re all cheap:
- A disabled log line still runs your argument code. Guard hot-path debug lines with
isEnabledFor, or at least pass args lazily with%sinstead of building an f-string. The line that prints nothing was still costing me 5,260 ns. - A synchronous handler puts disk latency on your request thread. A
QueueHandlerplus a backgroundQueueListenermoves the I/O off the caller and flattens the tail, from a 5,752 µs p99.9 down to 24.6. It trades a little durability for it: records sitting in the queue are lost if the process dies, so don’t put your audit log behind it. - The cheapest line is the one you never write. Sample high-volume INFO down to 1% and you get 100x less data and most of the CPU back, as long as you keep every error and know you’ve given up per-event detail.
The one thing to remember: logging is code that runs on your hot path, and it charges you even when it produces nothing. Treat it like any other thing in that loop and measure it.
The harness, the three experiments, and the raw CSVs are on GitHub, including the buffered-sink attempt where async lost. These are numbers from a laptop and a Docker VM, not a capacity plan: the ratios travel, the absolute microseconds depend on how your disk and your fsync behave, and Experiment 2 in particular is a shape, async an order of magnitude under sync, not a fixed figure. Python 3.12.13.
Comments