One line of Python, and a 3× drop in p99 | SoundCloud Backstage BlogWe removed one log statement from a service’s hot path this week. Its 99th-percentile response latency fell from a steady ~48ms to ~18ms, and CPU usage dropped by about the same factor. The cleanest way to see it: before the change, p99 never went below 40ms at any hour of any day. After it, p99 never went above 40ms. The two distributions barely touch.

In the first hour after the deploy - the daily traffic trough - p99 touched 5ms. That number is real, and it is not the one to quote. The difference between those two readings is most of what this post is about.

The interesting part isn’t the number. It’s that we spent a while looking for the cost in the wrong place, and the thing that eventually found it was measurement rather than code reading.

Some context

If you listen to SoundCloud for free, you hear ads. How many and how often isn’t a fixed schedule; the backend decides it per listening session. Part of that decisioning now runs through an internal service: a request comes in describing the current session, and the service returns an action - show an ad pod of a given size, or don’t - along with a cooldown.

Two properties matter for this story:

first, it sits directly in the ad-serving request path, so its latency is not an offline concern; it’s user-facing

second, it serves several policy variants behind the same API, and those variants don’t all use the same inputs.

That second property is where the bug came from.

The API contract, and a caller that doesn’t need it

The service’s decision endpoint accepts a posteriors field: the per-action statistical state a Bayesian policy needs in order to pick an action. Callers that want a learned policy send it.

But not every variant is a learned policy. Some run a fixed policy - a deterministic rule with no per-action state at all. Those callers send no posteriors, by design, because there is nothing meaningful to send.

The endpoint had a validation guard that looked, in essence, like this:

# Log warning for missing actions<br>missing_actions = all_actions - provided_actions<br>if missing_actions:<br>logger.warning(<br>"Posteriors missing for actions",<br>request_id=request.request_id,<br>missing_actions=missing_actions,<br>for action in missing_actions:<br>MISSING_POSTERIORS.labels(segment_id=request.segment_id, missing_action=action.name, version=version).inc()

The intent was reasonable: if a caller sends posteriors for some actions but omits others, that’s a real anomaly worth surfacing. The implementation didn’t distinguish that case from “this caller sent none at all, as expected.”

The action space has four entries, so a caller that sends nothing has all four “missing.” For every fixed-policy request the service emitted a structured warning and four metric increments. For zero signal. And that turned out to be effectively all of its traffic: every policy variant then receiving requests tripped the guard, on every request. Not a hot path with an occasional expensive branch - a hot path with an unconditional one.

Worth being precise about scope. This service sits behind SoundCloud’s ad-serving stack - a high-volume, continuously-hot path that decides ad load for listening sessions across the platform, around the clock. It currently takes the experiment-allocated slice of that traffic, which is already substantial, and the intent is for ad-load decisioning like this to cover a growing share of free-tier listening. Whatever the guard cost per request, it cost it on 100% of them - and that alone was enough to hold p99 nearly three times above where it needed to be. At the volume this is heading for, that is not a rounding error.

None of this was gratuitous. The warning and the counter were deliberate instrumentation - MISSING_POSTERIORS fed a dashboard panel that let us watch, per policy variant, whether callers were sending the state they were supposed to. The log line had been there for a while. Nothing was broken. Alerts were quiet. It simply cost more than anyone had priced in.

The wrong theory first

The initial hypothesis was string formatting: building the log message - serialising the set of missing actions, interpolating the request ID - on every request, and paying for that work whether or not anything consumed it. That’s a well-known Python cost and a plausible culprit.

We never isolated it with a benchmark, and we should be honest about that. What argues against it is the memory graph: if the cost had been building strings and objects we immediately discarded, we would expect the win to show up in allocation. Per-pod memory moved only from ~170–175MB to ~150–160MB - real, but nowhere near proportional to the latency change. The cost was in writing the line, not building it.

That distinction matters because it changes the general lesson. “Don’t format strings you might not log” is a micro-optimisation. “Don’t emit a log line on 100% of hot-path traffic” is an architectural...