Observing the Queue

On the second on-sale night the ticket emails started running late again, and this time the dashboard said so at 4 minutes. The render had left the request, the outbox and the stream were doing their jobs, and worker-01 was completing 2 jobs a second against the 5 a second that 3,000 orders in 10 minutes bring. The wound was the same and the cause was different: not work in the wrong process, but not enough of the right one, and nobody watching the number that would have said so.

A queue has three numbers that matter: how many jobs are waiting, how old the oldest one is, and how fast they are being completed. The second one is the alert, because depth means nothing without knowing whether it is draining, and throughput means nothing without knowing what is arriving. This topic is the three metrics, how the worker reads them from the stream, what each one's shape means, and the arithmetic that says how many workers the night needed before the night.

Depth, Age, Throughput

Depth is the entries the group has not finished. XLEN is not it, because acknowledged entries stay on the log until trimmed; XINFO GROUPS jobs is, reporting for the workers group the number of entries not yet delivered as lag and the number delivered and not acknowledged as pending, and depth is their sum. Age is the property that makes the stream better than most queues at this: every entry id begins with the millisecond it was added, so the age of the oldest unfinished job is the current time minus the timestamp in its id, with no clock stored anywhere else. The oldest unfinished entry is the older of two: the head of XPENDING, and the first entry past the group's last-delivered id, which XRANGE returns in one call. Throughput is a counter the loop increments at every XACK, labelled by kind, and the dashboard shows its rate per second.

The worker's exporter computes the three every 15 seconds and the dashboard draws them as the three lines above. On the night, depth rose in a straight line toward 12,000 while throughput sat flat at 5 a second, and those two shapes together are a sentence: the work is arriving faster than one worker completes it, and it will keep doing so until the arrivals stop. Depth on its own could not say that. Age said it at 21:04.

Age Is the Alert

A depth of 12,000 at 5,000 completions a second is a backlog of 2.4 seconds, which no buyer will ever notice. The same 12,000 at 5 a second is 40 minutes. Depth cannot tell those two nights apart, and an alert on depth either fires on the healthy night or sleeps through the bad one, depending on where the threshold was set. Age is the division already done: it is the time the oldest job has waited, which is exactly what the buyer is experiencing, and it grows only when arrivals outrun completions for long enough to matter.

Stagedoor's alert is one rule: the oldest unfinished render_tickets job is older than 60 seconds for 1 minute. It is written the way Topic 69 of Chapter 13 writes every alert, on the symptom the buyer would report, in the unit the buyer would use. On the second on-sale night it fired 4 minutes after the on-sale opened, when the oldest render had waited a minute. Marek started two more workers from the same image, and the age line turned down at 21:06 instead of climbing to 40 minutes. The buyers who bought in the first 6 minutes waited a few minutes for their tickets. Nobody waited 40.

jobs_depth{kind="render_tickets"}                300      # lag + pending, by kind
jobs_oldest_age_seconds{kind="render_tickets"}    61       # now - timestamp of the oldest unfinished id
jobs_completed_total{kind="render_tickets"}       200      # a counter; the dashboard draws its rate: 2/s
jobs_dead_length                                   0        # XLEN jobs:dead

# the alert: on age, per kind, never on depth
alert: JobsBacklogAge
  expr: jobs_oldest_age_seconds > 60
  for:  1m
  page: "{{ $labels.kind }} oldest job {{ $value }}s old: add workers or find the slow dependency"

Four gauges and counters, each labelled by the job kind, and one alert rule on the age gauge that pages when any kind's oldest job has waited more than a minute, sustained for a minute so that a single slow render does not page. The message names the kind and the age and says what to do first, because the person paged at 21:04 has 6 minutes before the buyers start writing in, and should not spend them deciding what the number means.

Reading the Shapes

The three lines have a small vocabulary of shapes, and each one is a diagnosis. Depth rising with throughput flat is the night above: the workers are saturated, or a dependency has slowed every job by the same amount, which on Stagedoor's worker is the renderer's seat-map read queued behind organizer reports on the replica of Topic 36 of Chapter 6. Throughput at zero is workers that are dead, or a reclaim loop that is dead while the workers hold entries they will never finish. Depth flat and high with throughput normal is a poison job blocking one consumer's batch of 10: everything moves except the entries stuck behind it, and Topic 46's delivery counter has not yet reached its limit. The length of jobs:dead rising is a code bug on a class of jobs, and it is a page even at 1.

Per-Kind Metrics

One stream carries every kind, and an aggregate over all of them is a number that lies by averaging. On the second night the aggregate throughput of 5 a second looked like a worker doing its job, because update_sales_counter and record_analytics were completing in 20 milliseconds each and made up most of the acks; render_tickets was completing 2 a second against 5 arriving, and it was the 40 minutes, under one label. The exporter computes depth and age per kind by walking the undelivered tail with XRANGE in pages of 1,000 and the pending list with XPENDING, counting each by its kind field and keeping the oldest id per kind, which at 12,000 entries costs 12 round trips every 15 seconds and nothing else. Throughput is per kind for free, because the counter's label is set by the loop that already knows what it just ran.

The labels are what make the alert message say render_tickets and not "the queue." They are also what make the dashboard answer the question a paged engineer asks first: which one. Topic 69 of Chapter 13 has the general rule, that a metric is labelled by the dimension along which the answer differs, and for a queue that dimension is the kind.

Capacity

The number of workers is arithmetic, and the night's arithmetic was available in August. 3,000 orders in 10 minutes is 5 renders a second arriving. The rate that matters for capacity is that average and not the 100 checkouts a second the API answers in the opening seconds, because the stream absorbs the peak, which is most of why the render is a job at all; the worker count follows the average for as long as the queue's age stays inside what a buyer will accept. A render is 4 seconds of CPU, a worker has 8 render threads, so one worker completes 2 renders a second, and 3,000 renders through one worker is 25 minutes, of which the last buyer waits for all but the first 10. Three workers complete 6 a second, ahead of the 5 arriving, and the whole burst is done inside the 10 minutes it takes to arrive, with the queue never older than a few seconds. Two workers complete 4 a second and fall behind by 1 a second, which after 10 minutes is a 600-job backlog and a 2.5-minute wait for the last buyer; acceptable, and one worker's failure away from the night above.

The inputs are the render's P95 from the trace of the next section, the burst from the organizer's event size and the on-sale pattern, and the threads per worker from the free-threaded build of Topic 04 of Chapter 1. Topic 67 of Chapter 12 is where the arithmetic is checked against a real run, with 3,000 synthetic orders in 10 minutes against three workers and the age line watched. One worker was deployed for the second night because one had always been enough, which is the argument the arithmetic exists to replace.

The Job's Own Trace

Every entry carries the request's trace id from Topic 21 of Chapter 4, and the worker starts a span under it when the handler begins. The buyer's checkout trace therefore continues into the worker: the 90 milliseconds of the handler, the 100 milliseconds in the outbox, then a span named queue.wait from the entry id's timestamp to the moment the handler started, then render_tickets for 4 seconds, then a second job's send_tickets with the mail provider's 300 milliseconds inside it. On an ordinary night the whole trace is 5 seconds wide and the wait is a sliver. On the second on-sale night the wait span for an order placed at 21:03 was 3 minutes wide, and a 3-minute span in a trace is unmistakable in a way that a log line saying "email sent" at 21:07 is not.

The queue-wait span is the one that costs nothing to add and answers the question support will ask: where did the wait go. It went in the queue, not in the render and not at the mail provider, which is what Topic 70 of Chapter 13 shows as one wide bar with two narrow ones after it. Without the trace id in the entry, the same night is a log search across two hosts joined by an order id, and the answer takes an hour to assemble instead of a click.