The day `format!` ate half our CPU: hunting allocations in a Rust hot path

Our market-data pipeline runs on a single mid-sized VPS: a fleet of small Rust daemons that ingest order-book feeds from several exchanges, merge them many times a second, and serve the result over WebSockets and REST. It had been getting slower for weeks in the way that never triggers an alert. No incident, no red dashboard. Just a load average that had crept up to almost triple its old baseline.

One evening we profiled it properly. By the end of the night the aggregator had gone from 73% of a core to 52%, the ingest daemon from 40% to 11.6%, and the whole fleet's CPU roughly halved. Almost all of it came from one class of bug: a cheap-looking line inside a loop that runs hundreds of thousands of times per second.

This is the story, including the two optimizations that did nothing and the measurement bug that nearly sent us down the wrong road.

A guess, disproved in production

The aggregator parses hundreds of kilobytes of order-book JSON per cycle, many times a second. Faced with 73% of a core and that number, the obvious hypothesis writes itself: JSON parsing dominates, so swap serde_json for simd-json and collect the win.

We did the swap by the book. The parser change was pinned by a differential test asserting value-equality between both parsers across every payload shape we produce, including the one real divergence we found (bare integer -0 parses as a float in one library and an integer in the other; our serializer can never emit it, and a dedicated test documents that). Clean deploy, correct output.

CPU after: 73%. Exactly where it started.

The estimate had come from a benchmark harness we wrote earlier that day, and the harness was lying. It replayed captured payloads through the full pipeline with a hardcoded now timestamp. The pipeline has a staleness gate: snapshots older than 60 seconds are dropped. Our fake now was far ahead of the captured data, so the merge stage silently processed an empty set, and the harness reported that parsing was 72% of the work. The tell was sitting in the output the whole time: 0.09 ms to merge dozens of order books is not plausible. A benchmark number that looks too good is a bug in the benchmark until proven otherwise.

What perf said instead

We stopped estimating and installed perf on the box. Ten seconds of samples from the live aggregator, sorted by cumulative cost:

19.47%  pipeline::bucket::py_round
18.30%  libc malloc
16.34%  alloc::fmt::format
14.35%  core::fmt::float_to_decimal_common_exact
13.11%  libc cfree

The top symbol was a six-line function:

/// Python round(x, ndigits): round-half-to-even on the true
/// decimal value. Format then re-parse reproduces it exactly.
pub fn py_round(x: f64, ndigits: usize) -> f64 {
    format!("{x:.ndigits$}").parse().unwrap()
}

This function is not stupid. The pipeline was ported from Python, and its output is verified byte-for-byte against the original implementation. Python's round() is round-half-to-even computed on the true decimal value of the float, which is hard to reproduce numerically. Formatting through the standard library's correctly-rounded float printer and parsing back reproduces it exactly, ties included. It is a correct and clever parity trick.

It was also being called once per price level, per exchange, per asset, on every cycle. Every call allocated a heap String, ran the exact float-to-decimal algorithm, freed the String. The profiler attributed 19.5% of the daemon's CPU to it, and over half of that was allocator traffic and formatting plumbing rather than digit math.

The fix keeps the trick and deletes the allocation: format through the same core::fmt path into a 64-byte stack buffer, with a heap fallback for values too wide to fit (nothing that is a price or a quantity ever is).

let mut b = StackBuf { buf: [0u8; 64], len: 0 };
if write!(b, "{x:.ndigits$}").is_ok() {
    core::str::from_utf8(&b.buf[..b.len]).unwrap().parse().unwrap()
} else {
    format!("{x:.ndigits$}").parse().unwrap() // |x| ~ 1e50+, never a price
}

Same formatting algorithm, so the digits are bit-identical by construction. We pinned that with a 20,000-case fuzz sweep comparing to_bits() against the original heap expression at every precision the code uses, then verified the test can fail by injecting a one-digit precision bug and watching it go red.

The same profile showed malloc and free at about 11-12% flat. The daemon was the last hot one still on glibc's allocator while parsing thousands of small JSON nodes across concurrent tasks; switching it to jemalloc matched the rest of the fleet. Those two changes together: 73% to 52% of a core, output byte-identical, cycle rate unchanged.

The same disease in every organ

With py_round fixed, we swept the other daemons for the same shape, point-verifying each hit in code before touching anything. Three more instances, in descending order of cost:

The serializer allocated two Strings per price level. The ingest daemon publishes each exchange's book as JSON. The serializer built a Vec<[String; 2]> (one to_string() for price, one for quantity, per level), fed that into a serde_json::json! tree, then serialized the tree into yet another String. At up to a thousand levels per side, across dozens of exchange-asset streams, many times a second, that is on the order of a million short-lived allocations per second in one process. The replacement writes the JSON in a single pass into one pre-sized String. The test that made this safe to do in an evening asserts byte-identity against the original json! expression over fixture books larger than production ever publishes, including key order, escaping, decimal scale, and the null case. Result: the daemon went from 40% of a core to 11.6%.

A band sum filtered the whole book. Computing order-book imbalance over a narrow price band was implemented as .iter().filter(|p| p >= lo) over a BTreeMap that holds up to a thousand levels per side, on every message, to sum the dozen levels inside the band. BTreeMap is ordered; .range(lo..) returns the same elements without comparing every key. Sums are exact decimals, so the result is identical. The inclusivity of both bounds is pinned by a test with levels sitting exactly on the band edges, which goes red if either bound becomes exclusive.

Symbol matching allocated per trade. To route a trade frame to its asset, the trade daemon compared the incoming symbol against format!("{}USDT", asset.to_uppercase()) for each of a handful of candidate assets. Per frame, at hundreds of frames a second. The mapping is a compile-time constant; a suffix strip plus a case-sensitive byte compare does it with zero allocations. The differential test walks every asset and a set of near-miss symbols (lowercase, wrong suffix, trailing garbage, the empty string) and asserts the acceptance set is unchanged, because the old == was case-sensitive and the new code had better be too. While there, the same daemon's flush loop was awaiting one Redis round trip per trade; it now sends one pipelined burst per batch.

What we deliberately did not fix

An audit like this produces more findings than you should act on. Three we left alone, with reasons written down next to the code:

The per-message metrics call in two exchange adapters looked like pure waste, since a throttle discards most results. Reading the code closer: that call is also the crossed-book detector, and on a crossed book it has a side effect, invalidating the book and forcing a resynchronization. Deferring it to the publish tick would change when resyncs fire. The expensive part of the call was already gone via the range() fix, so the remaining cost did not justify touching failure-recovery semantics.

A four-pass loop over parsed JSON in another consumer would save maybe 1-2% of a core, in a module whose output is verified against a reference implementation with subtle per-level error semantics. Below threshold; not worth the parity risk.

And the simd-json swap that started this whole story measured null, twice, so it stays only because it is harmless and well-tested. We wrote the null result down in the commit message. Future readers deserve to know what was already tried.

Scoreboard and takeaways

Daemon	Before	After
Aggregator	73% of a core	52%
Ingest	40%	11.6%
Microstructure	11% (one sample)	4.0%
Trades/CVD	~7% (one sample)	2.8%
Fleet total	100% (baseline)	~50%

What we would tell our past selves:

1. Profile the process, not your model of it. Our mental model said "JSON parsing", a broken benchmark agreed with the model, and production disagreed with both. perf record -g on the live daemon settled it in ten seconds.
2. An implausibly fast benchmark number is a bug report about the benchmark. 0.09 ms to merge dozens of books should have stopped us a day earlier than it did.
3. The expensive line rarely looks expensive. Every fix in this story removed a format!, a to_string(), or a Value tree that read as idiomatic, reviewable Rust. What made them bugs was the loop around them.
4. Byte-identity tests are what make aggressive optimization boring. Every rewrite here was pinned to the old implementation's exact output, and every pin was verified to fail under an injected bug before we trusted it. That is the difference between an evening of confident deletes and a week of "did we break the numbers?"
5. Write down the nulls and the "no"s. The optimization that did nothing and the optimization you refused both carry information. Commit messages are where it survives.