Four readings, and only one of them moved with the load

The median went from twenty-one milliseconds to a hundred and twenty-two between an arrival rate of ten a second and one of forty-eight. Something ran out. You have four readings available on a service you can see all of: processor share, memory, connections held open, and worker slots occupied.

Three of the four will move. Commit to which one explains the latency before you take any of them.

Predict

One worker, two milliseconds of processor time and eighteen of waiting per request. At an arrival rate near capacity the median is roughly six times the declared cost. Which reading will explain it?

Choose one answer

Processor share, pinned or close to it — six times the latency means the machine is out of cyclesMemory, climbing as the queue holds more connectionsWorker slots, full from well below capacity onwards — and the latency is the queue standing behind the full slotConnections held open, rising past what the listening socket will take

Lock in answer

Taking all four

Two terminals. In the first, offer load long enough to read something:

docker compose up -d service
docker compose run --rm load --rate 48 --seconds 60

In the second, while that is running:

# processor share and memory, from outside the process
docker stats --no-stream $(docker compose ps -q service)

# connections held and worker slots, from inside it
curl -s http://localhost:18081/stats

The second command is the one worth noticing. accepted minus completed is the number of connections the service is holding — in service or queued — and in_service is how many worker slots are occupied right now. Neither of those is visible from outside the process, which is the whole point of the admin port existing on a second socket.

{"accepted": 289, "refused": 0, "completed": 283, "abandoned": 0,
 "in_service": 1, "queued_max": 18, "queued": 5,
 "config": {"workers": 1, "spin_ms": 2.0, "wait_ms": 18.0, "limit": 0}}

Taken at three arrival rates across one sweep, on one laptop:

offered	median, milliseconds	processor, share of one core	resident memory, MiB	connections held	worker slots	deepest queue
10	21.2	2.5%	13.9	0, peak 1	1 of 1	2
30	41.1	4.6%	13.9	2, peak 4	1 of 1	7
48	122.4	10.1%	13.9	6, peak 11	1 of 1	18

Reading the table honestly

Memory did not move. Not by a tenth of a mebibyte across a fivefold change in load. Rule it out and stop looking at it; it is on the dashboard because it is cheap to collect, not because it is informative here.

Processor share moved, and it moved less than the latency did. A factor of four against a factor of nearly six, finishing at about a tenth of one core. There are nine tenths of a core idle at the moment the service is taking six times as long as its work costs. This is the exact situation track one named: the processor graph has thirty, or in this case ninety, per cent of its height unused and that is not headroom.

It also moved for an uninteresting reason. Each request costs two milliseconds of processor time and the service completes about forty-six a second, so it needs roughly ninety-two milliseconds of processor per second — a tenth of a core, which is what the reading says. The processor figure here is a restatement of the throughput. It carries no information the completions column did not.

Worker slots were full from thirty arrivals a second onwards. One of one, every time it was sampled, at two thirds of capacity and above. The reading saturated and then went quiet, which is the signature worth learning: a saturated resource stops being an interesting graph at exactly the moment it starts being the answer.

Connections held rose fastest of the four, and it is not a cause. Zero, two, six, with peaks of one, four and eleven. Little's law explains the whole column: forty-six and a half completions a second times a hundred and twenty-two milliseconds in flight is about five and seven tenths requests in flight, and the median reading at that rate is six. This column is the latency, converted into a count. Which makes it the most useful of the four to alert on and the most misleading to call a bottleneck.

So: three readings moved, one of them is full, and the full one is the answer. The latency is that full slot's queue, and queue depth times service time gives it back: about five waiting, twenty-one milliseconds each, a hundred and five milliseconds of wait on top of twenty-one of work.

What people actually reach for, and what each one misses

Processor and memory from outside the process. docker stats here, kubectl top pod on a cluster, and both read the same cgroup accounting underneath. They are correct and they answer the wrong question most of the time, for the reason above.

The one outside reading that is genuinely decisive is throttling rather than utilisation. Under cgroup v2, /sys/fs/cgroup/cpu.stat reports nr_throttled and throttled_usec: the number of periods in which the container was given no more processor time and the total time it spent stopped. A container being throttled shows a low utilisation figure, because it is not allowed to run — so the utilisation graph looks comfortable precisely when the limit is biting hardest. If I could export one processor metric from a containerised service it would be this one and not utilisation.

The accept queue, from the kernel. ss -ltn on the listening socket shows Recv-Q as the number of connections completed by the kernel and not yet accepted by the process, and Send-Q as the configured backlog. A standing non-zero Recv-Q means the process is not calling accept fast enough, which is a different failure from the one in this lab — here the door accepts immediately and queues internally, so the kernel queue stays empty and all the depth is inside the process where ss cannot see it. Worth knowing because the reverse case exists: a service whose accept loop is blocked shows an empty internal queue and a full kernel one.

Worker slots and internal queue depth, from inside the process. This is the reading that mattered and the one most services do not export. What exists: Puma's Puma.stats returns backlog and running per worker; gunicorn with --statsd-host emits gunicorn.workers and request duration but not queue depth; Hikari's connection pool exports hikaricp_connections_pending, which is the same measurement for a database pool; Postgres answers it with a count over pg_stat_activity against max_connections.

If you are adding one metric to a service that currently has none, add the in-flight count — a gauge incremented when a request enters the handler and decremented when it leaves. It costs two lines, it is the only one of the four that tracks the latency, and dividing it by your measured service time gives you the wait without a histogram.

Tracing, when you cannot reason about which resource. A span per stage tells you where the time went inside one request, which is lesson four of track one's subject rather than this one's. It will not tell you that a worker pool is full, because queueing time before the handler starts is usually outside the span. Instrumenting the queue wait specifically — the gap between accept and handler-start — is the fix, and almost nobody does it.

Check

A colleague reports that their service's processor utilisation sits at fifteen per cent while its latency has tripled, and concludes the service is not processor-bound. Under what circumstance are they wrong, and what would you ask them to read?

Choose one answer

Wrong if the container has a processor limit and is being throttled — ask for nr_throttled and throttled_usec from cgroup cpu.stat, because a throttled container reports low utilisation precisely because it is not being allowed to runWrong whenever the figure is an average over a window — ask for the hundredth-percentile utilisation insteadThey are not wrong — fifteen per cent rules out a processor bottleneck, so the cause must be a pool or a dependencyWrong if the service is multi-threaded, because the figure is per core rather than per process

Check answer

Where these four readings stop being enough

Every number in the table assumes the service and the load generator are the only things on the machine that want this core. On a laptop that is close enough to true to reason from, and it is the condition the table quietly rests on.

The crossing to watch for: once another process on the box wants the same core the service does, the processor reading becomes a measurement of the pair and the latency grows for a reason none of the four readings name. The symptom is specific and recognisable — the median rises while worker slots are not full and the queue is shallow, which is impossible if the service is the only thing running. A build, an indexer, an antivirus scan, or another container on the same node will all do it.

At that point the readings you need move up a level: the throttling counters above, the host's own run queue length, and in a cluster the sum of every pod's requested processor share against the node's capacity. The four readings in this lesson describe a service alone on a machine. The next lesson breaks that on purpose, by giving the service enough workers to want a core of its own.

Worth remembering

• A reading that rises tells you about load. A reading that is full tells you about a bottleneck, and only the second is actionable.
• Across a fivefold rise in arrival rate the memory reading did not move, the processor reading rose by about a factor of four to roughly a tenth of one core, and the worker-slot reading saturated at two thirds of capacity and stayed there.
• The processor figure here is a restatement of the throughput — requests a second times the processor cost of one request — and carries nothing the completions column did not.
• Connections held open is the latency converted into a count by Little's law, which makes it excellent to alert on and wrong to call a cause.
• The latency was the queue behind the full worker slot: about five requests waiting at twenty-one milliseconds each, on top of twenty-one milliseconds of work.
• A throttled container reports low processor utilisation because it is not being allowed to run, so utilisation is only trustworthy when read beside the limit — the cgroup throttling counters are the reading that separates the two cases.
• Worker-slot and internal queue-depth readings are the ones that mattered and the ones most services never export; an in-flight gauge is two lines and is the single highest-value metric to add.
• A median that rises while worker slots are not full and the queue is shallow means something outside the service is competing for the machine.