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.
I only found it because I was profiling something else. That's the part that still bothers me.
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.
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 fix is to stop building the string yourself and let the logger decide whether it's even worth building.
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.
Uglier, but it makes the point visible: nothing gets built unless someone's going to read it.
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.