Our API was slow. Not down, not throwing — just mysteriously, expensively slow under load. The p99 crept up month over month. We scaled out servers to keep latency sane. The cloud bill climbed. Everyone had a theory and nobody had a cause.
We blamed the database. We blamed the ORM. We blamed the new framework version. We blamed, briefly and unfairly, the intern.
The actual culprit was a line none of us would have looked at twice:
logger.info(`Request payload: ${JSON.stringify(req.body)}`)
I only found it because I was profiling something else. That's the part that still bothers me.
Why a log line nobody reads can still cost you money
Here's the thing that line does that isn't obvious: it does all its work before the logger gets a vote.
In production our log level was warn. So logger.info(...) was a no-op — the logger took the finished string, checked the level, and dropped it on the floor. Every time. We were paying full price to build a thing we had already decided to throw away.
Walk through what "build it" means on a hot path that runs on every single request:
-
JSON.stringify(req.body)serializes the entire request body. Some of ours were small. Some were a few hundred KB of nested arrays. - The template literal concatenates that into a new string — another full copy in memory.
- All of that garbage gets allocated, then handed to the logger, which looks at the level and says "nope," and now the garbage collector has to clean up megabytes of strings nobody ever saw.
The logging was free. The preparing to log was the tax. And we paid it on every request, forever, for output that physically never left the process.
The rule: your code isn't just what it computes. It's also what it prepares to compute and then discards. On a cold path that's invisible. On a hot path it's the bill.
How it hid for so long
This is the uncomfortable part, because the line is correct. It compiles, it does exactly what it says, it passed review (I approved it). In a unit test it's instant — one call, tiny payload, who'd notice.
It only becomes a problem at the intersection of three things that no single person was looking at together:
- it's on a path that runs on every request (volume),
- the payload is sometimes large (cost per call),
- the log level means the result is always thrown away (pure waste).
Each of those is fine alone. Stacked, they turned a debugging convenience into a line item. And because the symptom was "the whole service is a bit slow and a bit expensive," it pointed at everything except the one line responsible. Slowness with no single owner is the hardest kind to find — there's no stack trace for "death by a thousand allocations."
The rule: the expensive bugs aren't the ones that break something. They're the ones that quietly tax something that runs a million times a day.
The one-line fix
The fix is to stop building the string yourself and let the logger decide whether it's even worth building.
// ❌ Builds and serializes the string ALWAYS — even when it's dropped
logger.info(`Request payload: ${JSON.stringify(req.body)}`)
// ✅ Pass the object. The logger serializes lazily — only if this level will log.
logger.info('Request payload: %o', req.body)
Pass the object, not a pre-built string. Now the serialization is the logger's problem, and a decent logger only does it if the level is actually going to print. At warn in prod, req.body is never touched. At debug locally, you get your full payload. Same code, and the cost appears exactly when the value does.
If your logger doesn't support lazy args, the explicit guard does the same job:
if (logger.isLevelEnabled('info')) {
logger.info(`Request payload: ${JSON.stringify(req.body)}`)
}
Uglier, but it makes the point visible: nothing gets built unless someone's going to read it.
What changed
I'm not going to hand you a fake precision — I'll tell you the shape of it, because the shape is the lesson.
- p99 latency dropped sharply once the per-request allocation and GC pressure went away. The service stopped doing a pile of pointless work on the critical path.
- We scaled back down. We'd been running extra instances purely to absorb the overhead of garbage we generated and deleted. Those instances came off.
- Annualized, the instance reduction was in the tens of thousands of dollars. For us it rounded to about $40k/year — not from a clever optimization, but from deleting work we were doing for no reason at all.
The ROI on that one line was the best of anything I shipped that quarter, and I shipped real features that quarter. That ratio should make you a little uncomfortable. It does me.
The rule: the highest-leverage performance work is usually not making the slow thing fast. It's finding the fast thing you're doing a million times for nothing.
Go check your own hot paths
You almost certainly have one of these. Not necessarily a log line — the pattern is wider than logging:
- Eager serialization that gets discarded — building a string/JSON for a log, a metric tag, or an error message that only matters on the unhappy path.
- Work done before a guard instead of behind it — computing a value, then checking whether you needed it.
-
Debug conveniences that outlived the debugging — the
console.logyou added to find a bug in 2023 that's still running in 2026.
Find the three or four functions that run on every request. Read them not for correctness — they're correct — but for waste: what are they building that they then throw away? That's where the money is.
The rule: hot paths don't care about your intentions. They run millions of times. A "harmless" line in the wrong place is a tax you pay on every request until someone, by accident, reads the right log.
Disclosure: I build on xenition, a workspace assistant that builds and runs agents — and agents are merciless at generating exactly this kind of "correct but wasteful" code, because a clean, confident diff hides a pointless allocation just as well as it hides a logic bug. A lot of my "read hot paths for waste, not just correctness" paranoia is earned on our own systems. Read it as a builder's bias; I'd rather name it than hide it.
What's the dumbest expensive line you've ever shipped — the one that was individually correct and collectively a disaster? I'll go first in the comments, and I want the horror stories: the ones that only turned up because someone was looking for something else.
Top comments (15)
Passing the object fixes the cost, but I'd also look at what that line does on the day someone flips the level to info to debug an incident: it writes the full request body into the log store, which on most APIs means tokens, email addresses, or whatever users paste into forms. So the same line that was a silent tax at warn turns into a data-handling problem at info. Since it got through review once, a lint rule that flags template literals or JSON.stringify inside logger calls seems like a cheaper guard than counting on someone to spot it next time.
build996's incident-day point is the one that bites in Laravel land too. PHP evaluates the concatenation before Monolog ever sees the call, so Log::info("payload: " . json_encode($body)) pays the encode tax no matter what the level guard says. the context array form defers the formatting to the formatter, which only runs when a handler actually takes the record. of course the day someone flips the level during an incident the tax comes right back, now with tokens in the log store. I always grep for json_encode inside log calls after reading one of these.
The level-flip-comes-with-tokens detail is the one I'd pin to the wall. We got bitten by its sibling: our redaction lived at the call site —
log.debug("payload: %s", redact(body))looked safe, until an on-call engineer flipped DEBUG on during an incident at 3am and every authorization header in the request stream sailed into the log store for the next 90 minutes.The structural lesson: lazy formatting defers the cost to the handler, which is right for the $40k problem — but it also defers the redaction to the same moment, so level and privacy become coupled through the same door. We moved redaction into the formatter layer (one choke point between records and sinks) precisely so the incident-time level flip can't unlock it. Cost of debug: pay at the handler. Privacy: enforced at the handler, never at the call site.
The grep habit you describe (
json_encodeinside log calls) we run as CI now, not a habit — a one-line lint regex catches the serialization tax, and a second one catches call-site redaction. Habits die on incident nights; CI doesn't.the formatter-layer redaction is the better version of the point i was fumbling toward. you're right that lazy formatting couples level and privacy through the same door — i'd only ever thought about it as a cost problem. and CI over habit is the correct take; my grep habit has exactly the failure mode you describe, it just hasn't bitten me on a bad night yet.
The "hasn't bitten me on a bad night yet" line is exactly why the CI gate earns its keep — a habit is measured by its worst night, not its median one. Grepping at 2am under an incident is a different person than grepping at noon with coffee, and the check runs as the noon person on behalf of the 2am one.
One concrete artifact in case the grep habit wants a floor to stand on: the cheapest gate that catches the call-site-redaction family is a two-line audit in CI — (1) grep for redaction-adjacent helper names appearing at call sites (
redact(,mask(,sanitize(outside the formatter module) and fail on hits, (2) a self-test that feeds a known secret throughlogger.debug(...)at disabled level and asserts the secret string never appears in the captured sink. Check (2) is the one that catches lazy-formatting leaks that check (1) can't see — it tests behavior, not style, so nobody can game it by renaming the helper.And when the privacy rule lives at the sink, the "level flip comes with tokens" incident becomes automatically true at every call site forever, which is the whole point: the property should be a function of where formatting happens, not of what each caller remembered.
Glad it landed — the thread was the better for your fumbling, that's how the exchange works.
Check 2 is the one I'd steal. The lint rule is good hygiene, but the self-test actually proves the property instead of just discouraging the pattern. Borrowing that.
Exactly! Same problem, different language. 😄 The scary part is that fixing the performance issue doesn't automatically fix the privacy risk. One log-level change during an incident could expose sensitive data. Your grep habit is a great practical tip, and automating that check in CI would make it even better. Thanks for sharing the Laravel perspective!
the privacy angle is the one people underestimate. the perf fix gets reviewed; the 3am log-level flip during an incident doesn't. agree on the CI check, I keep a similar grep in pre-commit.
That's a really good catch! I was so focused on the performance cost that the privacy risk deserves just as much attention. A simple log-level change during an incident could expose sensitive data. Centralized redaction and lint rules sound like a much better long-term fix than relying on code reviews alone. Thanks for adding this perspective!
The detail that logging was off while the stringify still ran is the kind of thing that hides forever if you only look at errors. You were paying to build a string nobody would see.
I have seen the same shape on client systems: work that happens before a guard, or a sync that allocates heavily and then decides nothing needs writing. One bounded piece of work that helps is a short list of hot-path checks with a clear pass or fail: allocation spikes under load, log prep cost at warn level, and a few known expensive calls. Each check is small enough to price and re-run after changes.
Did you end up adding a lint or CI rule for stringify inside log calls, or was finding this one enough for now?
That's a great approach! Small, repeatable hot-path checks are much more useful than waiting for another expensive surprise. 😄 This definitely made me rethink how we review logging code. A CI rule for eager serialization is the logical next step, along with checking allocation costs under load. Catching these issues before production is always cheaper than discovering them on the cloud bill. Thanks for sharing!
Eager evaluation of template literals before log-level filtering is such a silent performance killer in Node.
Because template literals evaluate expressions synchronously on the caller side before passing the string into
logger.info(), the event loop is forced to serialize the entire body object, allocate heaps for the formatted string, and trigger V8 GC pressure on every single request — even when log level is set to WARN and the string gets discarded immediately.Passing lazy getters or checking level guards (e.g.
logger.isInfoEnabled() && ..., or structured loggers like Pino that take object references directly without string interpolation) completely eliminates the serialisation overhead on filtered levels. Great reminder to audit hot-path logging!Exactly! The tricky part is that the log never gets written, so it's easy to assume there's no cost. Meanwhile, the event loop is doing all that unnecessary work on every request. Pino and proper level guards are great solutions. It's one of those tiny details that can make a huge difference at scale. Appreciate you adding the Node.js perspective!
The "pay to build what you already decided to throw away" framing is the real bug class here — the logger's level check happening after string construction is just one instance of it.
I run into the twin in data pipelines: Python's
logging.debug("payload: " + json.dumps(body))looks free at DEBUG-off, but the concatenation runs on every call — the f-string variant is worse,json.dumpsexecutes first, logger never votes. The fix is the boring one people skip:log.debug("payload: %s", body)passes the arguments, so the formatting only happens if the level passes. One-character-class change, hot path goes from serializing every request to serializing the ones you keep.The audit question generalizes your find beautifully: for every log line on a hot path — who pays for the string, and do they get a refund when the level says drop? We added a rule to our crawler's code review checklist after our own version of this: "no function calls inside a debug-level log argument." The profiler found it for us too, on a run we were profiling for something else.
Love that framing — “who pays for the string, and do they get a refund?” 😄 It's amazing how the same tiny mistake shows up across different languages. And the fact that your profiler caught it while looking for something else makes it even more relatable. Adding that rule to code reviews is a smart move. Thanks for sharing your experience!