DEV Community

Cover image for A single HTTP request failed. Twenty-six hours later, CPU tripled.
Vitalii Buhaiov for MarketTrace

Posted on • Edited on

A single HTTP request failed. Twenty-six hours later, CPU tripled.

The box runs eight vCPUs and sits at roughly 12% CPU. That is its steady state.

One Wednesday morning it jumped to 28%, drifted up toward 47%, and stayed there for three days. Nothing was down. Every service reported active. No errors in any log. The data served to the front end was live and correct.

The only symptom was a number on a graph, and nothing at that timestamp explained it.

The cause turned out to be a single failed HTTP request, 26 hours earlier.

The system, briefly

A market-data pipeline we run — the backend behind markettrace.ai: four exchanges, seven assets, all of it Rust talking to Redis. Two pieces matter for this story.

An order-book ingester keeps live order books. A separate trade-tape ingester consumes executed trades and writes them into per-(asset, venue) Redis streams. Downstream, seven candle aggregators (one per asset) fold that trade tape into candles.

Each aggregator has two modes. Normally it reads incrementally from a saved per-venue cursor. If the cursors are unusable it falls back to a full rebuild: read every venue's entire 26-hour window and rewrite the whole cell hash. For the busiest asset that is about 58,000 fields per cycle.

Act 1: the correlation that wasn't

The reflex when a graph steps up is to find what shares its timestamp. So: deploys that morning, none. Config changes, none. Traffic, flat. Service restarts, nothing within hours of the jump.

We widened the window and found nothing there either. That is a disorienting result, because the search itself feels sound. You are asking "what changed when the number changed," and the answer is that nothing did.

What a timestamp correlation can and cannot see. It assumes cause and symptom share a moment. That holds for crashes, deploys, and traffic spikes. It fails completely against state that latches: something writes a flag, the flag sits there, and a different condition reads it much later. At the moment the graph moves, the code is doing exactly what it has been doing all along. The change already happened, somewhere off-screen.

Act 2: finding what was burning

Since correlation gave us nothing, we went for attribution instead: which process is spending the CPU.

pidstat put it on the seven candle aggregators. Together they had gone from 0.17 cores to 1.44. Not one of them. All seven.

That also explains why the graph drifted instead of stepping: a full rebuild re-reads every trade in the 26-hour window, so the burn scales with how busy the tape is. The 1.44 cores was one afternoon's snapshot; on livelier days the same loop cost more.

Seven independent processes, one per asset, sharing no state, simultaneously deciding to do more work. That narrowed things fast, because there is exactly one decision they all make independently and identically: incremental or full rebuild.

const WINDOW_S: i64 = 93_600; // 26 hours
const VENUES: &[&str] = &["a", "b", "c", "d"];

/// The incremental path applies only if every venue's cursor is present and fresh.
fn use_incremental(cursors: &HashMap<String, String>) -> bool {
    VENUES.iter().all(|v| {
        let id = cursors.get(*v).map(String::as_str).unwrap_or("0-0");
        id != "0-0" && cursor_age_ms(id) < WINDOW_S * 1000
    })
}
Enter fullscreen mode Exit fullscreen mode

There it is. .all() over the venue list, evaluated separately inside each of the seven processes. One venue with a bad cursor flips this to false everywhere at once.

.all() is a fan-out. A predicate over a collection reads as conservative and local. It is neither. It couples the health of every item to the weakest one, and if the surrounding code runs in N independent processes, it couples all N of them too. Hold that thought, though: this line is not the bug, and we will come back to why.

Act 3: the dead venue that looked alive

One venue's cursor read "0-0" in all seven assets. That value is what the read helper returns when a range query comes back empty. No trades in the window.

Which made no sense, because that venue was obviously up. Its order books were streaming. Everything on the front end that depended on it was live.

Depth and trades come from two different daemons. The order-book ingester was fine. The trade-tape ingester had not written a single trade from that venue in three days.

And now the 26 hours has an explanation. The cursor does not go stale the instant trades stop; it ages out. Trades stopped at 06:17 on the 28th. The cursors crossed WINDOW_S at 08:17 on the 29th. Twenty-six hours, to the minute, which is why nothing was happening when the graph moved.

Jul 28  06:17:14   trade-tape ingester restarts, one REST call fails
        06:17:23   order-book ingester restarts, the same REST call succeeds
                   |
                   |  26 hours. Trades missing. CPU flat at 12%. Nothing alerts.
                   v
Jul 29  08:17      cursors age past the 26h window
                   full rebuild engages on all seven assets, CPU 12% -> 28-47%
                   |
                   |  3 days. CPU elevated. Still nothing alerts.
                   v
Jul 31             CPU investigated for an unrelated reason
Enter fullscreen mode Exit fullscreen mode

Three separate signals had a chance to catch this. All three reported honestly, and all three were useless:

Signal What it measured What it missed
systemctl is-active the process exists whether it is doing anything
trade-stream length entries present in the stream retention is MINID-based, trimmed relative to the newest entry, so a dead stream holds its final ~6 hours forever and looks full
the startup log line the boot banner printed it prints once, at boot, and it read 0 multipliers instead of 7

The stream one is our favourite, in the way a bruise is your favourite. Length-based staleness checks silently assume writes are still arriving. When they stop, the stream freezes at a plausible-looking length and stays there indefinitely.

There was also a red herring we chased for a while. An archival worker logs across N streams every minute, and N had dropped from 28 to 21. That looks like seven dead streams. It is not: the number counts streams that received a trade in that minute, and thin pairs routinely go a minute without one. Correct log line, wrong reading, time gone.

Act 4: the root cause, and a nine-second coincidence

Three of the four venues go straight to their WebSocket. One quotes size in contracts rather than base currency, so before its socket is useful you need a REST call for the per-instrument multiplier.

That preflight was written like this:

// The multiplier table the socket needs to convert contract sizes.
let multipliers = fetch_multipliers().await;

if !multipliers.is_empty() {        // <-- the gate is OUTSIDE the retry loop
    run_forever(|| {                // backoff, reconnect, indefinitely
        run_socket(multipliers.clone())
    })
    .await;
}
Enter fullscreen mode Exit fullscreen mode

The reconnect loop was right there. It had backoff. It handled every socket failure correctly and would have retried forever.

It never ran once. The socket was never spawned, so there was nothing to reconnect. A single transient REST failure at boot removed the venue for the entire lifetime of the process.

The nine seconds explain the rest. The order-book ingester restarted nine seconds after the trade-tape ingester and made the same REST call against the same endpoint successfully. One transient blip, and the two daemons landed on opposite sides of it. That is why the venue looked healthy from every angle a human would check: half of it was.

The fix is small. Move the fetch inside the loop so a failure costs one backoff instead of the process lifetime:

/// One session attempt: fetch the multipliers, then run the socket with them.
/// Returning early hands control back to run_forever's backoff.
async fn session(fetch: Fetch, run: Run) {
    let multipliers = fetch().await;
    if multipliers.is_empty() {
        eprintln!("multiplier fetch failed, retrying with backoff (venue NOT skipped)");
        return;
    }
    eprintln!("{} multipliers", multipliers.len());
    run(multipliers).await;
}

run_forever(|| session(fetch_multipliers, run_socket)).await;
Enter fullscreen mode Exit fullscreen mode

fetch and run are parameters rather than direct calls so both branches can be asserted without a network. The empty-map branch has a test that fails if the early return is deleted, which we checked by deleting it.

Note the second eprintln!. The count now prints on every reconnect instead of once at boot, which turns a line nobody reads into a line that repeats while wrong.

Act 5: the half of the causal path that was not a bug

Four things had to line up. Our first instinct was to change all four. Two of them were correct.

The .all() fan-out is a deliberate fail-safe, and the comment above it lays out the reasoning. The 26-hour freshness bound sits several times above the tape's own ~6-hour retention, and the margin is deliberate: retention is anchored to the newest entry rather than the clock, so after a multi-hour gap a cursor can be under 26 hours old and still point below the stream's trimmed head. An incremental read from there resumes at the head and silently skips everything in between, corrupting a band of candles with no gap counter anywhere. Falling back to a full rebuild is the safe answer to "I am not certain what I missed." Removing the condition would have traded correctness for CPU, which is exactly the trade whoever wrote that comment refused.

The "0-0" latch is honest too. It is what an empty range query returns, and it means what it says. It also cleared itself in about ninety seconds once real trades arrived.

So the CPU burn came from a component that was working as designed, reacting correctly to bad input, in a system where nothing told anyone the input was bad. The fix touched neither of them. The candle aggregators, the processes that actually spent the CPU, were not modified at all.

Act 6: what actually changed

Three things, and only the first is about this bug.

The preflight moved inside the retry loop, so one transient now costs one backoff.

The ops collector gained a question it had never asked: how old is the newest trade? It already walked all 28 (asset, venue) streams every cycle and read each one's HEAD entry for an unrelated lag metric. Computing "how old is the oldest HEAD, and which stream is it" in that same loop cost zero additional Redis round-trips. That single number would have caught this incident on day one, and it would also have caught an earlier one where a Redis restart left every daemon active and silently frozen.

The thresholds came out of the healthy data. The worst gap between trades on a healthy thin pair was 133.9 seconds, so: warn at 900 seconds, critical at 3600. Warn deliberately does not page, because the thinnest pairs idle long enough overnight to make that a nightly false alarm.

A cron job pages on critical every fifteen minutes, deduplicated to at most one page per six hours.

Worst-case detection went from three days to seventy-five minutes.

One thing the fix cannot do is recover the data. Those three days of trades from that venue are gone, because nothing was writing them down while they happened. The candles for that window are permanently thinner than they should be. Detection latency is not an abstract metric. It is the width of the hole in your data.

What we check now

  • Which preflights sit outside their retry loop? A retry loop protects only the failures that happen inside it. Anything hoisted above it for convenience is a permanent single point of failure with a reassuring amount of resilience code sitting just below it.
  • Does any health check assert that data arrived? Process liveness, port binding, and HTTP 200 all answer a question nobody was asking. If the only thing that would notice a dead input is a human reading a boot log, the input is unmonitored.
  • Which .all() or .any() over a collection quietly couples independent things? Then decide whether the coupling is deliberate, as ours turned out to be. Knowing which is which before the incident matters more than the audit itself.
  • Which "it looks full" signals are relative to the last write rather than to now? Queue depth and stream length keep their last healthy value forever after writes stop; so does file size.

And the search heuristic that would have saved us the most time: when a symptom has no cause at its own timestamp, stop scanning minutes around it. Find the longest window, timeout, or TTL in the system, and search back by that. The gap between cause and symptom is usually one of your own constants, and here it was sitting in the source as WINDOW_S = 93_600.

Top comments (0)