The endpoint that was slow for one customer

A support ticket reporting an endpoint as unusably slow, against a dashboard showing a p95 of two hundred and twenty milliseconds. Both were correct: the aggregate describes the population and the ticket describes a customer whose data is an outlier by two orders of magnitude.

The symptom

GET /api/v2/orders, one week, all consumers:

  p50   42ms
  p95  220ms
  p99  410ms

and the ticket: "this takes four seconds every time".

reproduced with their credentials: 4.1 seconds,
consistently, on every request.

they are 2% of traffic. the aggregate p95 does not move
when they are excluded.

Two per cent of requests at four seconds contributes almost nothing to a p95 computed across everybody, which is arithmetic rather than a measurement failure. The metric is answering a question about the population and the ticket is asking about one member of it.

Why it happens

A percentile across consumers is a weighted average of populations that may have nothing in common. A small consumer with a pathological data shape is invisible in it by construction, and the smaller they are the more invisible they get.

The fix

One label

$histogram->observe($durationSeconds, [
    'route'    => $request->route()->getName(),
    'method'   => $request->method(),
    'consumer' => $request->user()?->apiKeyId ?? 'anonymous',
]);

the same week, labelled:

  integrator-a   p50 40ms    p95 190ms
  integrator-b   p50 44ms    p95 210ms
  integrator-c   p50 41ms    p95 205ms
  integrator-d   p50 1,880ms p95 6,400ms

four named consumers is a bounded label set. the same
label on user id would be unbounded, and an unbounded
label on a histogram is how a metrics store falls over.

What was different about their data

$ ./bin/consumer-shape integrator-d
  orders                 204,882
  median lines per order       4
  max lines per order        188
  orders in the last 30 days  41

$ ./bin/consumer-shape integrator-a
  orders                     412
  median lines per order       3
  orders in the last 30 days  88

# 500× the rows, 2× the recent activity. they are an
# eight-year-old account and everybody else is recent.

The plan, which was a different plan

-- for a typical customer
EXPLAIN ANALYZE SELECT * FROM orders
WHERE customer_id = 412 ORDER BY placed_at DESC LIMIT 50;

-> Index lookup on orders using idx_customer_placed
     (actual time=0.1..0.4 rows=412 loops=1)

-- for integrator-d
-> Sort: orders.placed_at DESC  (actual time=3,880..3,910)
     -> Table scan on orders
          (actual time=0.2..2,104 rows=2,104,882 loops=1)

The optimiser estimates that two hundred thousand of two million rows is most of the table and chooses a scan, which is a defensible decision at that selectivity. One query with two plans is invisible in any aggregate measurement and is the reason a per-consumer view was needed to find it at all.

Fixing it without pessimising everybody

  a histogram on customer_id
    improved the estimate and did not change the
    decision — the estimate was roughly right.

  FORCE INDEX
    works, and freezes a decision that will be wrong
    for somebody else in two years.

  a covering index
    (customer_id, placed_at, id, status, total_minor)
    so the scan never happens because the index
    answers the query.
    → 4.1s → 38ms for integrator-d, unchanged for
      everybody else.
    → +1.8 GB, and +0.4ms per insert.

chosen: the covering index, with the arithmetic
written down.

The index costs sixteen seconds a day of write time across forty thousand inserts to save one consumer four seconds twice a day, which is closer than it looks and favours the index because the write cost is spread and the read cost is a person waiting. A partial index would be clearly right and MySQL does not have them.

The alerting change that came out of it

- alert: ConsumerLatencyRegression
  expr: |
    histogram_quantile(0.95,
      sum by (le, consumer) (rate(http_duration_seconds_bucket[10m])))
    > 2 *
    histogram_quantile(0.95,
      sum by (le) (rate(http_duration_seconds_bucket[10m])))
  for: 15m
  annotations:
    summary: "{{ $labels.consumer }} p95 is 2× the aggregate"

Alerting on a consumer being twice the aggregate rather than on an absolute threshold is what makes this work across endpoints with different baselines. It fired once more in September, on a consumer who had started requesting three includes on a two-hundred-item page — which was a conversation rather than an index.

Verifying it worked

$ ./bin/latency --by-consumer --since=7d
  integrator-a   p95 188ms
  integrator-b   p95 205ms
  integrator-c   p95 201ms
  integrator-d   p95 240ms      # was 6,400ms

$ ./bin/insert-latency --table=orders --since=7d
  p50 1.8ms   # was 1.4ms

$ mysql -e "SELECT index_name, ROUND(stat_value*@@innodb_page_size/1024/1024/1024,1)
            FROM mysql.innodb_index_stats
            WHERE table_name='orders' AND stat_name='size'"
  idx_customer_placed_covering   1.8

Reporting the insert latency alongside the improvement is the honest accounting — the index made writes measurably slower and that number belongs next to the four seconds it saved. Nobody would have measured it if the decision had not required the arithmetic.

What this costs

A metric with a label that must stay bounded, and there is nothing enforcing that. Four named integrators is safe; the same label applied to an authenticated user id would be tens of thousands of time series and would take the metrics store down — which is a mistake somebody will make by copying this line.

The index is also 1.8 GB and 0.4 milliseconds per insert, paid by everybody, for one consumer. That is defensible now and the defence depends on there being one such consumer — a second one with a different access pattern gets a second index, and at some point the answer is that their data belongs somewhere shaped for it.