Learn AI Create the Future — with Pranay
Main site

Incident Response for ML Systems

Debugging a latency spike

A latency spike is usually a small share of requests taking far longer than the rest, hidden by an average that looks fine — finding which stage they get stuck in is the whole job.

Read these first

On this page 9
  1. The short answer
  2. The analogy you have already lived
  3. Why the average lies to you
  4. How it works
  5. Where the time actually goes
  6. Where you have already felt this
  7. The honest part
  8. Remember this
  9. What to learn next

One lesson, three depths. Pick the one that fits you today — you can switch any time.

Beginner — No maths. Plain English.

The short answer

A latency spike is a small share of requests taking far longer than the rest, hidden by a fine-looking average.

The analogy you have already lived

Think of a barbershop with one chair. Most haircuts take ten minutes. Once in a while somebody wants a full shave and a colour, and that takes forty.

Ask "how long does a haircut take" and you might hear "about eleven minutes on average." That hides the truth. Most people wait ten. One unlucky person in the queue behind the long job waits closer to forty. A latency spike is that one person, multiplied across thousands of requests.

Why the average lies to you

An average blends every request into one number. A handful of very slow requests barely move it. Those same requests can be the entire reason users are complaining.

This is why serving systems talk in percentiles, not averages. "p99" means: sort every request's time, fastest to slowest, and look at the one at position 99 out of 100. It answers "how bad is it for the unluckiest 1%?" — a question an average cannot answer.

How it works

1,000 requests, sorted fastest to slowest

fastest  ......................................  slowest
   |          |                    |         |
  p50        p95                  p99       max
 (500th)    (950th)              (990th)  (1000th)

p50 = 20ms    "half of everyone waits under this"
p95 = 40ms    "19 in 20 wait under this"
p99 = 900ms   "1 in 100 waits nearly a full second"

A p50 of 20ms and a p99 of 900ms describe the same service. Both are true. Only one of them describes what your unluckiest users experience.

Where the time actually goes

A single prediction is rarely one operation. It is a chain: read the request, build its features, ask the model, package the answer, send it back. A spike almost always lives in one link of that chain, not spread evenly across all of them.

Finding the slow link is the entire debugging job. "The service is slow" is not a diagnosis. "Feature building takes 30ms on 5% of requests, everything else takes under 1ms" is one.

Where you have already felt this

A food delivery app that is instant nine times out of ten. Once in a while it spins for half a minute, usually because one restaurant's system is slow to confirm. Everyone else's order was never affected.

The honest part

Chasing a tail latency spike is genuinely harder than fixing a service that is uniformly slow. The slow requests are a minority, and they may not repeat the same way twice. A fix that helps the average can leave the tail untouched. Measure the tail specifically — do not infer it from the average.

Remember this

  • Look at percentiles (p50, p95, p99), never only the average — the average hides the unluckiest requests.
  • A spike lives in one stage of the request most of the time. Find which one before trying to fix it.
  • A service can look fine on average and still be badly broken for 1 in 100 users.

What to learn next

Developer — Code and libraries.

Setup

None. Pure Python standard library — time.perf_counter() for timing, statistics for the mean.

Timing every stage, of every request

latency_probe.py
import statistics
import time

N_REQUESTS = 300
SLOW_EVERY = 20  # every 20th request hits a deliberately heavy path


def build_features(i: int) -> float:
    t0 = time.perf_counter()
    if i % SLOW_EVERY == 0:
        # A stand-in for a cold cache or a slow upstream lookup.
        sum(range(2_000_000))
    else:
        sum(range(1_000))
    return time.perf_counter() - t0


def model_predict(i: int) -> float:
    t0 = time.perf_counter()
    sum(x * x for x in range(500))
    return time.perf_counter() - t0


def serialize(i: int) -> float:
    t0 = time.perf_counter()
    str({"score": 0.42, "id": i})
    return time.perf_counter() - t0


records = []
for i in range(N_REQUESTS):
    req_start = time.perf_counter()
    t_features = build_features(i)
    t_model = model_predict(i)
    t_serialize = serialize(i)
    total = time.perf_counter() - req_start
    records.append({"i": i, "features_ms": t_features * 1000, "model_ms": t_model * 1000,
                     "serialize_ms": t_serialize * 1000, "total_ms": total * 1000})


def pct(data: list[float], p: float) -> float:
    data = sorted(data)
    k = (len(data) - 1) * p
    f, c = int(k), min(int(k) + 1, len(data) - 1)
    return data[f] if f == c else data[f] + (data[c] - data[f]) * (k - f)


totals = [r["total_ms"] for r in records]
print(f"{N_REQUESTS} requests, {N_REQUESTS // SLOW_EVERY} of them on the slow path\n")
print(f"mean:  {statistics.mean(totals):7.3f} ms")
print(f"p50:   {pct(totals, 0.50):7.3f} ms")
print(f"p95:   {pct(totals, 0.95):7.3f} ms")
print(f"p99:   {pct(totals, 0.99):7.3f} ms")
print(f"max:   {max(totals):7.3f} ms")

# Where did the slowest 5% of requests spend their time?
slow = sorted(records, key=lambda r: r["total_ms"], reverse=True)[: N_REQUESTS // 20]
print(f"\nSlowest 5% of requests ({len(slow)} of them), average time per stage:")
print(f"  build_features: {statistics.mean(r['features_ms'] for r in slow):7.3f} ms")
print(f"  model_predict:  {statistics.mean(r['model_ms'] for r in slow):7.3f} ms")
print(f"  serialize:      {statistics.mean(r['serialize_ms'] for r in slow):7.3f} ms")
Output
300 requests, 15 of them on the slow path

mean:    1.414 ms
p50:     0.022 ms
p95:     1.361 ms
p99:    28.120 ms
max:    31.400 ms

Slowest 5% of requests (15 of them), average time per stage:
  build_features:  27.798 ms
  model_predict:    0.021 ms
  serialize:        0.006 ms

These exact milliseconds are real, measured on one laptop, running this exact code — they are not invented, and they will differ on your machine and on every rerun. What will not differ is the shape: p50 near zero, p99 more than a thousand times larger, and almost every millisecond of the slow requests sitting in build_features. That shape is the real finding, not the specific numbers.

Line-by-line walkthrough

SLOW_EVERY = 20 makes 1 in 20 requests take a much heavier path inside build_features — a stand-in for a cache miss, a slow upstream call, or a database query that only sometimes needs to happen.

pct implements linear-interpolation percentiles by hand, so the lesson has no dependency beyond the standard library. numpy.percentile or statistics.quantiles compute the same thing in real code.

The last block does more than print an overall p99 — it isolates the slowest 5% of requests specifically and asks where their time went. That per-stage breakdown, not the overall percentile, is what points at build_features as the culprit.

Common mistakes

Debugging with the mean. The mean above, 1.4ms, looks completely healthy. It is the p99 that reveals the problem — a mean can rise by a fraction of a millisecond while the tail rises by a factor of a thousand.

Optimising the fast path. model_predict and serialize are already under a hundredth of a millisecond. Speeding up code that is not the bottleneck wastes effort and moves nothing.

Reproducing the spike with a small sample. With SLOW_EVERY = 20, a batch of 10 requests might contain zero slow ones by chance, and look perfectly healthy. Percentiles need enough requests to be meaningful — hundreds, not a handful.

No per-stage timing at all. Without splitting build_features, model_predict, and serialize apart, "the request took 28ms" is the whole finding, and points nowhere. Instrument each stage before an incident, not during one.

Try it yourself

Change SLOW_EVERY to 5 and rerun. Watch p50 start to rise too, not only p99 — that is the line between "a rare tail problem" and "a problem affecting a meaningful share of everyone," and it changes how urgently you would treat it.

What to learn next

Researcher — Mathematics and papers.

Why percentiles, formally

For a latency distribution with cumulative distribution function $F$, the $p$-th percentile is $F^{-1}(p)$: the value below which a fraction $p$ of observations fall. The mean $\mathbb{E}[X]$ and $F^{-1}(0.99)$ are different functionals of the same distribution, and for a right-skewed distribution — the common shape for latency, since a request cannot be faster than zero but can be arbitrarily slow — they diverge sharply. This is why two systems with equal means can have wildly different p99s, exactly as the output above shows.

Queueing theory and the tail

Little's law, $L = \lambda W$, relates the mean number of requests in a system ($L$), the arrival rate ($\lambda$), and the mean time in system ($W$), and holds for any stable queue regardless of the arrival or service time distribution. Its practical consequence: as utilisation $\rho \to 1$, expected queueing delay grows as $\rho / (1-\rho)$, so a service running comfortably on average utilisation can still show catastrophic tail latency at moderate load, because the tail is dominated by queueing variance, not by the mean service time. Model serving's researcher section covers this in more depth, including how tail latency compounds across a fan-out of parallel backend calls (Dean and Barroso, The Tail at Scale, CACM 2013).

Diagnosing where the tail comes from

Three distinct causes produce a similar-looking p99 spike, and the fix differs for each:

  • A rare heavy code path — as simulated above. Fixed by caching, precomputing, or making the heavy path itself faster.
  • Queueing under load — no single request is slow; the system is saturated and everything waits. Fixed by more capacity or admission control, not by profiling any one request.
  • A resource contention stall — garbage collection pauses, lock contention, a noisy neighbour on shared hardware. Fixed by isolating the resource, not by touching the request-handling code at all.

Distinguishing them needs different evidence: per-stage timing (as above) for the first, concurrent request-count-over-time for the second, and host-level metrics (GC pause logs, CPU steal time) for the third. Profiling one request in isolation, which is what the code above does, cannot detect the second cause — it needs load, not a single trace, to appear.

Continuous profiling

For production systems where the slow path is not known in advance, always-on statistical profilers (Google-Wide Profiling, Ren et al., 2010; open-source equivalents like py-spy and pyroscope) sample running processes at low overhead and attribute latency to code paths without per-request instrumentation. This scales to systems where hand-instrumenting every stage, as this lesson does for teaching clarity, would be impractical to maintain.

What to learn next