Keyboard shortcuts

Press ← or → to navigate between chapters

Press S or / to search in the book

Press ? to show this help

Press Esc to hide this help

Observability Inside the Hot Path

Before you start — this chapter leans on a handful of primer ideas:

  • Cache lines and false sharing — why counters get padded to 64/128 bytes and never shared between threads: ch00a
  • rdtsc / cycle stamps — the ~2ns timestamps the whole design is built around: ch00e
  • HdrHistogram — where all the recorded samples end up: ch00e
  • Syscalls and their cost — why even getpid or a pipe write is banned from the hot loop: ch00b
  • Jitter suspects — the tail-spike mechanisms this instrumentation exists to catch: ch00e

Read those first — 20 minutes there saves an hour here.

Measurement costs latency, and the paths most worth measuring are the ones with the least latency to spare. Done naively, the instrumentation becomes the jitter you’re hunting. Done well, the hot path stays observed in production — during the incident, not just in the lab — for a cost you can state and defend.

Budget it like everything else

You already accept this cost in web systems: the Datadog or New Relic agent runs in production, and you know it isn’t free. The only difference here is that the overhead gets a stated number and an owner.

Rule of thumb worth adopting and quoting: observability spends ≤1% of the path budget. A 5µs tick-to-trade path (ch00f’s wire-in → order-out scoreboard number) affords ~50ns of instrumentation — roughly a dozen rdtsc stamps and counter bumps, and nothing else. The exact number matters less than the discipline it enforces: instrumentation is a line item in the latency budget with an owner, not a free action. Every technique below exists to fit under it.

Corollary: the instrumentation must be always on. This is the Sentry principle — you don’t install error tracking after the outage. A measurement path that’s compiled out in production has two failure modes — it perturbs the system when you finally enable it, and it’s off during the incident you needed it for. The perturbation is physical, not superstition: compiling the stamps back in shifts every instruction address after them, which reshuffles cache and branch-predictor layout — timings move even in code you didn’t touch. It’s a Heisenbug factory: the act of looking changes the thing observed. Pay the 1% permanently; design so 1% is enough.

Cheap counters: per-thread, padded, aggregated off-path

This section is statsd done right: each worker bumps counters nobody else touches, and a scraper sums them once a second. The anti-pattern is every worker incrementing one shared row — the hot-row contention you’d never design into Postgres.

The wrong way: a shared AtomicU64 incremented by several threads — the cache line ping-pongs between cores and every increment pays a cross-core transfer (the microbenchmarks chapter’s table, ch10; ch00a for the mechanism). The mutex-guarded metrics struct is the same mistake with extra steps.

The right way: each thread owns its counters on cache lines nobody else writes; a cold aggregator thread reads them at 1Hz. Writes are plain-ish stores to an L1-resident line (~1ns); the reader’s once-a-second reads cost the hot thread at most one line transfer per second. The accounting behind that claim, in two sentences: when the aggregator reads your line, your core keeps a copy but gives up exclusive ownership, so your next write has to fetch the line back before it can proceed. That fetch-back is the entire cost — and it happens once per aggregator read, i.e. once per second.

 hot thread 1        hot thread 2        hot thread 3
┌─────────────┐     ┌─────────────┐     ┌─────────────┐   one padded counter
│ counters #1 │     │ counters #2 │     │ counters #3 │   block per thread —
│ (own lines, │     │ (own lines, │     │ (own lines, │   sole writer, cheap
│ sole writer)│     │ sole writer)│     │ sole writer)│   stores
└──────┬──────┘     └──────┬──────┘     └──────┬──────┘
       │                   │                   │
       └───────────────────┼───────────────────┘
                           │  1Hz reads (cold thread)
                   ┌───────▼───────┐       ┌─────────────────┐
                   │  aggregator   │──────►│ /metrics scrape │
                   │ (sums blocks) │       │  (Prometheus)   │
                   └───────────────┘       └─────────────────┘

One wrinkle in the padding: Intel’s adjacent-line prefetcher pulls cache lines in pairs, so “your own line” really means “your own 128-byte pair” — hence the align(128) below rather than 64.

#![allow(unused)]
fn main() {
use std::sync::atomic::{AtomicU64, Ordering::Relaxed};

/// One cache line (2 on Intel to defeat the adjacent-line prefetcher pair).
#[repr(align(128))]
pub struct StageCounters {
    pub events: AtomicU64,
    pub bytes: AtomicU64,
    pub queue_full: AtomicU64,
    pub max_cycles_seen: AtomicU64, // reset by aggregator
}

impl StageCounters {
    #[inline(always)]
    pub fn bump(&self, bytes: u64) {
        // Sole writer -> no RMW contention; Relaxed is correct: these are
        // statistics, not synchronization.
        self.events.fetch_add(1, Relaxed);
        self.bytes.fetch_add(bytes, Relaxed);
    }
}
}

Because each counter block has exactly one writer, fetch_add(Relaxed) never contends; on x86 you could even use plain load+store, but the uncontended RMW is ~20 cycles and saves you an argument with Miri, Rust’s undefined-behaviour checker. The aggregator sums per-thread blocks and that is what your Prometheus endpoint serves — the scrape never touches hot-thread state directly, and there is no lock anywhere a hot thread can see.

Ring-buffer event logging

Counters tell you rates; incidents need events: “what were the last 10,000 things this thread did, with timestamps.” The tool is a fixed-size ring of fixed-size binary records, written by the hot thread, drained (or deliberately not drained — see tail capture) by a cold thread.

This is the pattern the event-sourcing chapter (ch13) will formalize. The two-sentence sketch: instead of storing current state, you store an append-only log of small immutable facts (“what happened”), and any state you want is rebuilt by replaying the log. Here the “domain” is the pipeline itself: the hot path appends facts, and consumers rebuild any view they want — histograms, dashboards — off-path. Same log discipline, same replayability, same single-writer append — if you can defend this ring in an interview, that chapter’s event store will feel familiar, and connecting the two unprompted is worth doing.

#![allow(unused)]
fn main() {
/// 32-byte POD record ("plain old data": fixed-size bytes, no pointers, no heap).
/// No strings, no Debug formatting — ever.
#[derive(Clone, Copy)]
#[repr(C)]
pub struct Event {
    pub tsc: u64,       // raw cycles; convert off-path
    pub kind: u16,      // enum discriminant
    pub stage: u16,     // pipeline stage id
    pub a: u32,         // e.g. symbol id
    pub b: u64,         // e.g. order id / seq
    pub c: u64,         // payload (price, size, latency, ...)
}

pub struct EventRing {
    buf: Box<[Event]>,        // power-of-two length
    mask: usize,
    head: std::sync::atomic::AtomicU64, // writer-owned; reader loads
}

impl EventRing {
    #[inline(always)]
    pub fn push(&self, ev: Event) {
        use std::sync::atomic::Ordering::*;
        let h = self.head.load(Relaxed);
        // SAFETY: single writer; slot ownership by index math.
        unsafe {
            let slot = self.buf.as_ptr().add((h as usize) & self.mask) as *mut Event;
            slot.write(ev);
        }
        self.head.store(h + 1, Release); // publish: Release orders the slot
        // write first, so any reader that sees the new head value is
        // guaranteed to also see the slot's bytes
    }
}
}

Cost of push: an rdtsc (if stamping), a few stores to a line that’s usually L1-resident, one release store. ~5–15ns. The drain thread walks head snapshots, converts cycles→ns, feeds HdrHistograms, writes to disk — all at its leisure, on a non-isolated core.

Overwrite policy is a choice: a drained ring must handle wrap (drop + count ring_dropped — never block the writer); an undrained “flight recorder” ring is supposed to overwrite (below).

Sampling and late materialization

Two multipliers that stretch the 1% budget: sampling and late materialization.

Sampling (1-in-N). Anything expensive to capture — full order-book snapshots, deep stamp sets, payload copies — gets recorded for only a fraction of events: if seq & 1023 == 0 { capture_expensive() }, where the bit-mask just means “every 1024th event.” The guard branch is ~free because the CPU’s branch predictor guesses the skip in advance and is right 99.9% of the time.

Won’t sampling miss the tail event? No — because you always record the cheap latency stamp for every event, and only sample the expensive context around it.

Better yet, bias the sampling: capture the expensive context conditionally on the observed latency exceeding a threshold. Now the expensive data exists for exactly the events you’ll end up investigating.

Late materialization — the same instinct as storing user_id, not the user’s full name, in every log row. The hot path logs ids, not strings: symbol id, not "AAPL"; enum discriminant, not a message; raw cycles, not formatted time. The drain thread joins ids against tables and formats. format! is a heap allocation plus a traversal — 100ns–1µs — and every one of them in a hot path is someone’s future p99.9 spike. Format off-path, always.

Same idea at stage boundaries: the hot thread’s whole timing duty is ring.push(Event{ tsc: rdtsc(), stage: STAGE_DECISION, .. }). Histogram math, percentiles, cycle conversion: all cold.

What NOT to do in a hot path

Each of these has appeared in a real trading system’s hot path, and each is a tail event generator:

  • syslog / any logging framework call: formatting + locks + possibly a syscall (and a blocking write if the disk hiccups). ms-scale worst case.
  • format! / to_string: allocation + formatting. Even “just for the error path” — error paths during a burst are exactly when you can’t afford it.
  • Mutex-guarded metrics (Mutex<HashMap<String, f64>> is the classic): the failure mode is priority inversion — the hot thread hits the lock at the exact moment the scrape thread holds it, and the scrape thread, being low-priority, has been descheduled by the kernel mid-critical-section. Your fastest thread is now waiting on the slowest thread’s nap: a 1Hz scrape holding the lock for 100µs turns into hot-thread stalls.
  • Prometheus client structs with internal locks / registry lookups per event: metric lookup by string name per increment is a hash + lock. Resolve handles at startup; better, keep the whole scrape surface on the aggregator only.
  • Unbounded anything: a Vec of events that grows until the reallocation lands on your worst burst.
  • Innocent syscalls: getpid, write(2) to a pipe “just for a heartbeat” — syscalls are 100ns+ and a scheduling opportunity: crossing into the kernel is exactly where the scheduler is allowed to take your core away, so a “harmless” heartbeat write can return milliseconds later. The bpftrace syscall check (the profiling chapter, ch09) should stay empty.

Watchdogs: heartbeat and deadline monitoring

Latency observability tells you how fast you were; a watchdog tells you that you’ve stopped — and in trading, a stalled system with live orders is the emergency.

  • Heartbeat: each hot thread stores last_seen = rdtsc() into its padded counter block every loop iteration (a store it already pays). A cold monitor thread checks each block at ~1ms: now - last_seen > threshold → alert / cancel orders / trip the kill switch. Cost to the hot path: one store. Value: a stall detector with millisecond reaction, immune to the stalled thread’s own inability to report.
  • Deadline monitor: for event-driven stages, the watchdog checks progress against input: producer seq is advancing while consumer seq isn’t → the stage is wedged even though its thread might be spinning “alive.” This is exactly Kafka consumer-lag alerting: the consumer process is up, but its offset has stopped moving while the topic’s head keeps advancing. Compare sequence numbers, not just heartbeats.
  • Escalation is domain logic: a wedged market-data thread means your book is stale — the correct automated response (pull quotes) belongs to the watchdog, not to a human reading a dashboard 45 seconds later.

Always-on tail capture: the flight recorder

The p99.99 event will not happen while you’re watching. The trick that catches it is Sentry’s breadcrumbs / session replay, applied to nanoseconds: always be recording the recent past over itself, and when something goes wrong, freeze the recording. The pattern:

  • Keep a pre-crisis ring: the last N events (say 64k), always being overwritten, never drained — an aircraft flight recorder.
  • On a trigger — watchdog trip, latency threshold breach, crash handler, SIGTERM — freeze and dump the ring: you now hold the complete, timestamped, per-stage event sequence for the milliseconds leading into the incident.
  • Triggered from the latency path itself: consumer observes end-to-end cycles > threshold → snapshot the ring alongside. You get causality (“the 40µs outlier was preceded by 900 queue_full events in stage 2”), not just a number.
  • Cost: the ring writes you were already making. The freeze/dump is off-path and rare.

This closes the loop with the profiling chapter (ch09): perf and ftrace reconstruct the system’s view of an incident; the flight recorder holds the application’s view; the rdtsc stamps let you join the two timelines.

Plain-English recap

  • The 1% budget is the APM-agent overhead you already accept — made explicit. You run the Datadog agent in production knowing it costs something; here the cost is a stated line item (~50ns on a 5µs path) with an owner, and every technique exists to fit under it.
  • Always-on is the Sentry principle. You don’t install error tracking after the outage. Instrumentation that gets compiled in “when needed” is off during the incident and perturbs the system when enabled — so it’s on permanently and its cost is part of every number you quote.
  • Per-thread counters + cold aggregator is statsd done right. Each worker bumps its own local counters; a scraper sums them once a second. The anti-pattern — every worker incrementing one shared row — is exactly the hot-row contention you’d never design into Postgres, yet Mutex<HashMap> metrics do it in memory.
  • The event ring is event sourcing (ch13) applied to telemetry. Small immutable facts appended by one writer, projections (histograms, dashboards) built downstream at leisure — a double-entry ledger for the pipeline itself.
  • Late materialization is storing user_id, not the user’s name, in every log row. The hot path logs ids and raw cycle counts; the drain thread does the joins and formatting — the same reason you don’t denormalize and stringify at write time in a high-volume table.
  • Watchdogs are liveness probes plus consumer-lag alerts. The heartbeat store is a k8s liveness check at 1000× the resolution; the deadline monitor (producer seq advancing, consumer seq stuck) is exactly Kafka consumer-lag alerting — a thread can be “alive” and still wedged.
  • The flight recorder is Sentry breadcrumbs / session replay. The last 64k events are always being recorded over themselves; the error (latency breach, watchdog trip) freezes and dumps them, so you get the milliseconds leading into the incident, not just the incident.

Interviewer will ask

Q: How much latency does your instrumentation add, and how do you know? A: It’s budgeted: ≤1% of the path — for a 5µs path, ~50ns, which buys a handful of rdtsc stamps, per-thread counter bumps, and one ring push. And it’s measured like any other change: A/B replay with instrumentation compiled in vs stubbed, comparing full histograms — the stubbed build exists only in the lab harness, to price the stamps; production never runs that way. It’s always on, so production numbers include its cost.

Q: Why not a shared atomic counter for a metric several threads bump? A: Contended atomic RMW makes the cache line ping-pong — each increment pays a cross-core transfer, ~100+ cycles, and it scales negatively with threads. Per-thread counters on padded (128B on Intel) lines are ~1ns sole-writer increments; a 1Hz aggregator sums them. Same totals, none of the coherence tax.

Q: Your logging is a binary ring. What happens when it fills? A: Policy is explicit per ring. Drained telemetry rings drop-and-count on overrun — the writer never blocks, and ring_dropped > 0 is itself an alert that the drain is undersized. Flight-recorder rings are the opposite: designed to overwrite forever and only read after a trigger freezes them.

Q: How do you log “what happened” without strings in the hot path? A: Late materialization: fixed-size POD records — tsc, enum discriminants, symbol/order ids, raw values. The cold drain joins ids to names and formats. Formatting is allocation plus traversal, 100ns to 1µs; ids are stores. Same reason the wire protocols we parse are binary.

Q: How would you detect that a hot thread has stalled, within a millisecond, without adding a syscall to its loop? A: Heartbeat store: the thread writes rdtsc to its own padded slot each iteration — a store it can afford — and a cold watchdog polls all slots at 1kHz comparing against now. Plus deadline monitoring on queue sequence numbers to catch a thread that’s spinning but not progressing. The watchdog owns the escalation — pull quotes first, page humans second.

Q: Prometheus in a trading system — where does it fit? A: At the edge only. Hot threads write per-thread counters and rings; an aggregator thread materializes those into Prometheus metrics and serves the scrape. The scrape path and any locks it needs exist only on the aggregator. The hot path neither knows nor cares that Prometheus exists.

Q: You see a 40µs outlier in the histogram. What’s your next artifact? A: The flight-recorder dump keyed to it: the consumer that observed the breach froze the last-64k-event ring, so I have the timestamped per-stage sequence leading into the spike — queue depths, stage deltas, event kinds. I correlate its tsc range with sched/ftrace data to decide app-cause vs system-cause. Histograms locate that something happened; the ring says what.

Further reading

  • Gil Tene, “How NOT to Measure Latency” — the service-time/response-time framing that motivates always-on production measurement.
  • Brendan Gregg, Systems Performance (2nd ed.) — observability-tool overhead and the “observer effect” discussions.
  • The LMAX Disruptor technical paper (Thompson et al.) — the single-writer principle and mechanical sympathy behind the ring design.
  • HdrHistogram docs — interval histograms and the recorder/double-buffer pattern for lock-free histogram handoff to a reader thread.
  • Martin Fowler’s write-ups on Event Sourcing and the LMAX architecture — the architectural pattern this chapter’s telemetry design mirrors.

Where this goes next: Chapter 12 welds the measurement chapters (ch07–ch11) into one runnable lab — a TSC-stamped three-stage pipeline you deliberately break four ways and watch each break appear in the histograms.