Writing /

Sub-millisecond overhead at 100K req/s: what Tokio taught me about tail latency

11 min read 0 views
rusttokiogrpcperformanceobservability

The best change I ever made to that gateway was deleting a line of code that never printed anything.

I’ll come back to it. Some context first, because the number in the title means very little without the shape of the system around it.

For about a year and a half I owned a gRPC gateway at Sales Marker, Rust on Tokio, sitting in front of an estate of a couple of thousand vCPUs. Peak traffic ran north of 100,000 requests per second and the budget for added p99 latency was under a millisecond. I left in early 2026, so this is written with a few months of distance, which mostly means I’ve stopped being defensive about the parts we got wrong.

Why there was a gateway at all

Nobody sets out to add a network hop. We had one because the same three problems kept reappearing in every service and the answers kept diverging.

Multi-tenant rate limiting was the loudest. Per-tenant quotas enforced independently inside each replica aren’t quotas, they’re suggestions multiplied by your replica count, and the autoscaler gets a vote in what your customer’s contract means. That needs shared arithmetic, and shared arithmetic wants one place to happen.

Authorization was the same argument in different clothes. Every team validated tokens, and every team had a slightly different opinion about what a tenant scope meant when a request touched two tenants’ data. Four implementations, four sets of edge cases, four audits.

Routing was the least interesting and the most useful. Method to backend with weights, retries scoped to idempotent methods only, and a circuit breaker one team could tune without filing tickets against three others.

We looked at a mesh with per-pod sidecars, and I still think that’s right for plenty of shops. Not for us. A sidecar on every pod across that estate was real money, the rate limiting needed centralized state anyway, and I’d rather debug one Rust binary I understand than a control plane and a proxy I mostly understand.

The budget, and what a budget does to you

“Added p99 overhead under a millisecond” needs a definition or it’s marketing. Ours was: first byte of the request off the socket to last byte of the response onto it, minus the time the upstream took to answer, at the 99th percentile, over a five minute window, per method. Not an average across methods. Not a number from a load test on an idle cluster.

A millisecond sounds roomy right up until you write down what happens inside it. TLS, HTTP/2 framing and header decompression, a token signature check, a rate limit decision, a load balancing pick, a connection checkout, then all of that again in reverse on the way out. Each piece gets tens of microseconds if everyone behaves. And because it’s a p99 and not a mean, one request in a hundred is allowed to be your worst case, which means your worst case is the number you actually have to engineer.

The useful side effect of writing the budget down was that it became a design tool. Every feature proposal picked up a question: what does this cost in microseconds at p99, and who’s measuring? Two features died on that question and both deaths were correct. One was mine.

Never block the runtime

This is the first thing anyone tells you about Tokio and the last thing anyone actually enforces.

The mechanism is simple. A multi-threaded runtime has one worker thread per core, and tasks are cooperatively scheduled, so a task that doesn’t yield owns its worker until it’s done. If a worker stalls for forty milliseconds, everything queued behind it stalls too, including timers and I/O readiness. On a sixteen worker runtime that’s roughly one request in sixteen eating forty milliseconds, a p99 catastrophe produced by code that looks completely innocent.

And it always looks innocent, because blocking arrives as “just one sync call.” A config reload that uses std::fs::read_to_string because it runs rarely, until someone wires it to a per-request cache miss. A std::sync::Mutex guard held across an .await. Hostname resolution through getaddrinfo inside a client you didn’t write. The worst one I found was a dependency three levels deep that built a blocking HTTP client at first use, on the hot path, once per process, for about 90 milliseconds. Once per process is fine until you deploy fifty replicas during peak.

The discipline that worked was boring. Anything not provably microseconds of pure compute goes to spawn_blocking, and the banned functions live in clippy.toml under disallowed-methods so it fails in CI instead of in review, where I’d eventually stop noticing.

use tokio::task;
 
/// Legacy API keys are argon2-hashed: roughly 15 ms of CPU each.
/// That is approximately forever to a worker thread that also
/// owns a few thousand live connections.
async fn check_legacy_key(key: String, stored: String) -> Result<bool, AuthError> {
    task::spawn_blocking(move || verify_argon2(&key, &stored))
        .await
        .map_err(AuthError::Join)?
}

spawn_blocking isn’t free and it isn’t a license to be careless. Each call occupies a thread from the blocking pool for its whole duration, and once the pool saturates, new calls queue. Move something long-lived onto it and you’ve built a slower, harder-to-see version of the problem you were fixing. The other habit worth having is tokio_unstable enabled in staging so tokio-console can tell you which task is hogging a worker.

Bounded channels as a religion

Every internal queue in that gateway was bounded. Not most. Every one.

An unbounded channel is a promise that you have infinite memory and that nobody downstream will ever be slow, and both halves are false. What happens is that a consumer falls behind, the queue absorbs the difference, and queue depth becomes latency nobody can see. Then the pod gets OOM killed, and the graph you’d use to diagnose it died with it.

Bounding is only half of it. The other half is what you do when the bound is hit, and the default instinct is wrong. Awaiting on send() when the channel is full turns a capacity problem into a latency problem, and latency problems are invisible in your own metrics because your handler is still “working.” try_send turns it into an error, and an error can be counted, alerted on, and returned as RESOURCE_EXHAUSTED, which is at least honest.

use tokio::sync::mpsc::{self, error::TrySendError};
 
// 8192 came from an experiment, not from taste: it's the depth
// where the aggregator still drains faster than we fill it.
let (tx, mut rx) = mpsc::channel::<Sample>(8192);
 
match tx.try_send(sample) {
    Ok(()) => {}
    Err(TrySendError::Full(_)) => {
        SAMPLES_DROPPED.inc();
    }
    Err(TrySendError::Closed(_)) => {
        return Err(Status::internal("aggregator is gone"));
    }
}

Dropping metrics samples under load feels like sacrilege the first time you write it. It stopped feeling that way the first time I watched the gateway hold its latency SLO through an incident while cheerfully throwing away 4% of its own telemetry. Same reasoning per upstream: a Semaphore with try_acquire_owned capped in-flight requests to each backend, so a sick backend absorbed a fixed slice of our capacity rather than all of it.

Counting allocations instead of avoiding them

“Avoid allocations” turns into cargo cult almost immediately. The version I believe in: know how many allocations a request makes, and be able to say why each exists.

Ours was four, eventually. It started somewhere north of twenty, and nearly every removal was one of two patterns: per-request Strings built to be thrown away, usually to key a map or label a metric, and copies of request bodies made because someone needed to look at the payload and reached for to_vec().

The body copies went away with bytes. A Bytes clone bumps a reference count and slicing doesn’t copy, so the payload moves through authorization, rate limiting, and forwarding as views into one buffer. The strings went away with interning: tenant identifiers live as Arc<str> in a config snapshot that swaps atomically on reload, so the hot path clones a pointer. Metric labels became child handles resolved once at tenant registration, because with_label_values is a hash lookup plus, depending on your luck, an allocation.

Then we swapped the global allocator for jemalloc through tikv-jemallocator, four lines that moved p999 more than any code change that quarter. It’s embarrassing how good the return was, and fragmentation in a long-lived process churning small buffers is a tail latency problem that never shows up in a microbenchmark.

Averages lie, so we stopped using them

An average is a number you can improve while making every user unhappier.

Prometheus histograms are fine and we kept them for alerting, but they quantize, and the quantization lands exactly where you need resolution. If your top explicit bucket is 2.5ms, a p999 of 3ms and a p999 of 30ms are the same picture. For a while we were tuning by vibes.

So the gateway recorded its own overhead into an HDR histogram in process and exported real quantiles alongside the Prometheus buckets.

use hdrhistogram::sync::SyncHistogram;
use hdrhistogram::Histogram;
 
// 1 us to 60 s at three significant figures. A couple hundred KB
// of counters, and it will not lie to you about p99.9.
let hist = Histogram::&lt;u64&gt;::new_with_bounds(1, 60_000_000, 3)?;
let mut overhead: SyncHistogram&lt;u64&gt; = hist.into_sync();
 
// One recorder per worker, wait-free on the hot path.
let mut rec = overhead.recorder();
rec.saturating_record(elapsed_us);
 
// And on the reporting task, every 10 seconds:
overhead.refresh();
for q in [0.5, 0.99, 0.999, 0.9999] &#123;
    export(q, overhead.value_at_quantile(q));
&#125;

saturating_record rather than record was deliberate: better to clamp a wild 90 second outlier into the top bucket than to have the call fail and lose the sample. In the load harness we used record_correct with the expected sampling interval, because a generator that politely waits while the server is stalled under-reports the exact latency you’re hunting. Coordinated omission is why so many published benchmarks look better than the systems they describe.

The log line that cost 200 microseconds

Back to the deletion.

We’d been comfortably inside budget for months, p99 overhead around 900 microseconds. A release went out with nothing performance-shaped in it, and p99 drifted to 1.1 milliseconds and stayed there. No error rate change. No CPU change worth naming. Nothing in the diff that touched the request path in any way I could see by reading.

perf record against a production replica, folded into a flamegraph, and there was a fat little tower of malloc under the routing function. The cause was four lines above a tracing::debug! call:

let tag = format!("{}/{}", tenant.id, method);
tracing::debug!(%tag, "routing decision");

The macro is well behaved. At info level it never formats a thing. But tag was built outside the macro, on its own line, because the author wanted it in two log statements. So the format! ran on every request, produced a String nobody would ever read, and dropped it.

The direct cost of that allocation was maybe 180 nanoseconds. The p99 cost was around 200 microseconds, and I never fully closed the gap between those two numbers. Best theory, and it is a theory: 100,000 extra allocate-and-free cycles per second per replica pushed the allocator into slow paths often enough to matter, plus the cache lines it dirtied on a hot path that was otherwise tight. Deleting the line moved p99 back to 900 microseconds within one deploy, and re-adding it in staging reproduced the regression, so the causality is solid even if the mechanism is a guess. It still bugs me.

The transferable lesson isn’t about logging. It’s that at six figures per second, the cost of an operation and its tail cost are different quantities, and only one shows up in a benchmark.

The surprise: p999 was never our code

Once p99 was reliably inside budget we went after p999, which sat around 8 milliseconds and refused to move. I assumed for far too long that it was us. It was not.

HTTP/2 defaults SETTINGS_INITIAL_WINDOW_SIZE to 65,535 bytes per stream, and the connection level window starts at the same value. On a long-lived connection multiplexing thousands of streams, with responses comfortably larger than 64 KB, the sender runs out of window and stops until a WINDOW_UPDATE arrives. That stall is latency the client feels, and it is invisible if you instrument only your own handler, which is where all instrumentation naturally goes.

Raising both windows explicitly on the server (tonic exposes initial_stream_window_size and initial_connection_window_size) and on the client channels moved p999 more than a quarter’s worth of hot path work. We tried http2_adaptive_window and turned it back off, because it overrides the explicit limits and we preferred a number we chose to one that was usually smarter than us but occasionally not.

The other half was head of line blocking above the transport. TCP_NODELAY was already set, so this wasn’t Nagle. It was that a single connection serializes its writes: one large response ahead of yours delays your small one, and no amount of tuning your own code changes that. The fix was topological rather than clever. More connections per client, and the handful of big-payload methods moved to their own channel pool so they couldn’t sit in front of the small fast ones. We also set max_concurrent_streams, which defaults to unlimited, so one enthusiastic client couldn’t monopolize a connection.

None of that is Tokio’s fault or Tokio’s credit. That’s the point. The last order of magnitude of tail latency was a protocol and topology problem, and by the time we found it our Rust was already fine.

What I’d keep

The habits that earned their keep were the unglamorous ones: a written budget with an explicit definition, bounded queues everywhere with a decided answer for “full,” a known allocation count per request, and real quantiles instead of buckets. The clever optimizations mattered much less than I expected. Most of the wins came from removing work nobody had asked for.

The caveat I owe you is that almost none of this is worth doing for a normal service. That gateway sat on the critical path of every request in the company, so its p999 was the company’s p999 and the arithmetic was easy. The project I’m on now is a GPU fleet where the interesting numbers are measured in minutes and megawatts, and applying any of this would waste everyone’s time. Tail latency work is worth exactly what the tail is worth, and you should find that out before you start.