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...
For further actions, you may consider blocking this person and/or reporting abuse
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.
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!