28Observability and Incident Response

On 22 August 2013 the system that disseminates consolidated quotes for Nasdaq-listed stocks began to fail at 11:48 in the morning, with intermittent outages on some of its channels. At 12:03 it stopped disseminating quotes altogether; a regulatory halt stopped trading in those stocks on every venue; the technical fault was fixed by 12:24, and quoting and trading resumed at 15:25. A firm’s monitoring that morning could look perfect: every process up, every queue empty, every heartbeat on time — because nothing was arriving. This chapter builds the monitoring that would have noticed: signals about what users of the platform receive rather than about the processes that serve them, objectives with error budgets, alerts that page only when a person should act, and the incident practice that follows the page.

28.1 Metrics, logs and traces

The chapter’s chain is the platform’s own: capture (chapter 2), the tick store, the position service (chapter 17) and real-time risk (chapter 18). firm.observe gives each a metric registry, structured log records and spans in the OpenTelemetry sense, carried from one service to the next. A traced message shows where its time goes (Figure 28.1): a fraction of a millisecond in capture, storage and positions, then the wait in the risk service’s queue — 50 milliseconds on a normal day, a minute when the risk service falls behind.

class Tracer:
    def __init__(self, prefix: str = ""):
        self.spans: list[Span] = []
        self._ids = itertools.count(1)
        self.prefix = prefix

    def start(self, name: str, service: str, ts: float, parent: Span | None = None,
              **attrs) -> Span:
        n = next(self._ids)
        trace = parent.trace_id if parent else f"{self.prefix}t{n:06d}"  # a root: new trace
        parent_id = parent.span_id if parent else None
        s = Span(trace, f"{self.prefix}s{n:06d}", parent_id, name, service, ts, None, attrs)
        self.spans.append(s)
        return s

    def finish(self, span: Span, ts: float) -> None:
        span.end = ts

    def trace(self, trace_id: str) -> list[Span]:
        mine = (s for s in self.spans if s.trace_id == trace_id)
        return sorted(mine, key=lambda s: s.start)

Each of the three answers a different question. Metrics say that something is wrong, cheaply, for everything, all the time. Logs say what happened in one service. Traces say where the time went across services, for the sampled units of work. Most trading firms have the first two and not the third, and learn where a message spent its minute only by reading the logs of four services side by side, with four clocks.

28.2 Service levels and error budgets

The indicator is chosen from the user’s side. A heartbeat from the risk service says the process is alive; the age of its data says whether it is doing its job. On the hook’s morning every heartbeat was on time and every age grew by one second per second. An SLO differs from Book 14’s service-level agreement in whom it binds: an agreement is a promise to a customer with penalties, an objective is the firm’s own target, set tighter than any promise it makes.

A 99.9% objective on 30 trading days of 23 400 seconds allows 702 bad seconds a month. The chapter’s quiet days — the chain’s normal latency of tens of milliseconds, plus pauses (a burst, a collection, a slow disk) that arrive 0.8 times an hour and during which the age grows one second a second — spend 115 of them, 16% of the budget, in 18 pauses of more than five seconds (Figure 28.2).

28.3 Alerting that people act on

A page wakes a person. It should mean that a person must act now, and it should come early enough for the action to matter. Static thresholds on the data’s age trade the two against each other; a rule on the error budget does not have to.

def _window_share(bad: np.ndarray, w: int) -> np.ndarray:
    c = np.concatenate(([0], np.cumsum(bad)))
    t = np.arange(1, len(bad) + 1)
    lo = np.maximum(0, t - w)
    return (c[t] - c[lo]) / w           # share of bad seconds; the missing past counts good


def burn_rate_pages(bad, target: float, rules, min_gap_s: float = 3600) -> list[int]:
    """Multi-window burn-rate alerting: page when, for some rule (long, short, rate), the
    bad share over both the last `long` and `short` seconds exceeds rate x (1 - target)."""
    b = np.asarray(bad, dtype=float)
    fire = np.zeros(len(b), dtype=bool)
    for long_s, short_s, rate in rules:
        lim = rate * (1.0 - target)
        long_ok = _window_share(b, int(long_s)) > lim
        both = long_ok & (_window_share(b, int(short_s)) > lim)
        fire |= both
    return _pages(fire, min_gap_s)

Three incidents are replayed on a quiet day at the hook’s clock times: a feed stall from 12:03 lasting 21 minutes; intermittent stalls of 20 seconds every minute from 11:48 for a quarter of an hour; and a slow consumer from 14:00, a risk service whose lag grows by 0.05 seconds each second. Five rules watch them (Table 28.1).

Time to restore is measured on the service a user receives, from the incident’s start; Book 14’s mean time to repair is a property of a component such as a circuit, averaged over its failures, from failure to repair.

The static thresholds show the trade-off (Table 28.1). At five seconds they detect everything at once and page 18 times a month on pauses that heal by themselves; within a few weeks nobody answers them. At thirty or sixty seconds the false pages disappear, but the intermittent stalls — the 11:48 phase of the hook — never reach the threshold, and a slow consumer takes ten or twenty minutes to be noticed. The burn-rate rules page 56 seconds into the stall, three minutes into the intermittent stalls and two and a half into the slow consumer (Figure 28.3), with one page a month on quiet days: the 56-second pause, which does spend a real share of the budget and deserves a look.

28.4 On call and incident command

In a trading firm the first minutes of an incident are about exposure, not diagnosis: is the firm trading on stale data, and should strategies stop? The runbook for a data-age page therefore starts with the kill switches of Book 13 and the risk limits of Book 11, then the diagnosis, and the incident commander’s first question to the trading desk is what the firm holds. Only one group changes the system during an incident, so that fixes do not collide; one person communicates, so that the desk, risk and compliance hear the same thing.

28.5 An incident replayed, and the review that follows

The replayed stall’s review writes itself from Table 28.2. The data stopped at 12:03; the burn-rate page came at 12:03:56; the feed returned at 12:24 and the risk service’s data was fresh again the same second. The questions it asks are not who failed but what the system let happen: why the firm’s dashboards showed green (they measured processes, not data); what the strategies did with stale prices for the first minute (the kill switch’s trigger was on process health, not data age); why the intermittent phase from 11:48 went unnoticed (thresholds above its twenty seconds). Its actions are changes: an SLI on data age for every consumer, burn-rate paging, a kill switch on stale data, and the replay itself kept as a test (chapter 27) so that the next change to the alerting is checked against it. An incident that becomes an operational loss event (Book 6, chapter 28) enters the firm’s loss data as well; the review is what makes the loss data useful.

28.6 Tutorial: three hours of silence

28.7 Build: observability

28.8 Exercises

28.9 Problem: Three Hours of Silence

28.10 Interview questions