DEV Community

The wait percentage ranks your idlest thread first

When a machine feels slow, the question I actually want answered is which thread is waiting. Linux answers the first half of that generously. /proc/pressure/cpu tells me how much of the last ten seconds some task spent stalled on a runqueue; top tells me who is burning CPU. Neither names the thread that wanted the CPU and did not get it - and those are different threads. The one burning CPU is winning. Every number, table and command below is a live read from one 16-core machine, captured while writing. Both regimes were produced on purpose and the load was real work with a checkable output, not a spinner. The per-thread answer is in /proc/ /task/ /schedstat , three numbers, no ceremony: $ cat /proc/1/schedstat 297508187061 22806177929 768442 Nanoseconds this thread spent on the CPU, nanoseconds it spent waiting on a runqueue while runnable, and the number of timeslices it ran. Field two is the good one. It is not "blocked on I/O", not "sleeping", not "idle" - it is ready to run and denied a core, which is the only kind of waiting a bigger machine would have fixed. Delta two samples, and you have per-thread scheduling latency for every thread on the box. Here is the whole instrument, and it is short enough that there is nowhere for a mistake to hide: #!/bin/bash # rqwait.sh - per-thread runqueue wait over a window, sorted two ways. W=${1:-2} snap() { for f in /proc/[0-9]/task/[0-9]/schedstat; do read -r run wait _ /dev/null || continue echo "${f#/proc/}|$run|$wait" done } snap > /tmp/.rq.a; sleep "$W"; snap > /tmp/.rq.b awk -F'|' ' NR==FNR { r0[$1]=$2; w0[$1]=$3; next } ($1 in r0) { dr=($2-r0[$1])/1e9; dw=($3-w0[$1])/1e9 if (dw /tmp/.rq.rows echo "== top 3 by FRACTION (wait / runnable) ==" sort -k3 -gr /tmp/.rq.rows | head -3 echo "== top 3 by ABSOLUTE wait-seconds ==" sort -k1 -gr /tmp/.rq.rows | head -3 Two sort keys, because I could not decide which one I wanted. That indecision turned out to be the whole article. The obvious metric The intuitive thing to compute from those two numbers is a percentage: of the time this thread wanted to run, what fraction did it spend queued rather than running? wait / (wait + run) It is dimensionless, it is comparable across threads, it goes up when things get worse, and it is what I would have put on a dashboard without thinking twice. "This thread spent 95% of its runnable time waiting for a core" is a sentence that sounds like an incident. Here is that metric on a quiet machine - load average 5.12 on 16 cores, nothing saturated, nothing to report: == top 3 by FRACTION (wait / runnable) == 0.003 0.000 94.7% 78/78 ksoftirqd/10 0.000 0.000 87.4% 3810780/3810780 kworker/5:0-cgroup_bpf_destroy 0.002 0.000 82.5% 695161/695161 kworker/5:2-events 94.7%. On three milliseconds. Over a three-second window, on a machine where nothing whatsoever was wrong. That thread woke up, sat on a runqueue for a moment because a core happened to be busy, ran for a duration too small to print at millisecond resolution, and went back to sleep. Its scheduling latency is real, correctly measured, and completely inconsequential. Across the whole machine that window, all 85 waiting threads together accumulated 0.018 seconds of runqueue wait. The same metric under actual starvation Now the other regime. I started four concurrent whisper.cpp transcriptions, eight threads each, on sixteen cores - 32 runnable threads competing for 16 cores, load average 11.14 climbing. This is real work with a verifiable result, which matters: all four runs returned byte-identical correct transcripts of the JFK sample (md5 7a2e20adโ€ฆ ), so nothing below is a spinlock pretending to be a workload. == top 3 by ABSOLUTE wait-seconds == 2.063 1.075 65.7% 853078/853384 main 2.013 1.147 63.7% 853078/853390 main 1.972 1.190 62.4% 853078/853078 main Those threads spent two seconds of a three-second window sitting on a runqueue, ready, denied. That is the thing I built the instrument to find. And their fraction is 65.7% - lower than the idle ksoftirqd 's 94.7%. Put the two readings side by side and the metric has inverted the regimes: | regime | thread | wait | run | fraction | |---|---|---|---|---| | quiet, nothing wrong | ksoftirqd/10 | 0.003s | 0.000s | 94.7% | | saturated, real starvation | whisper main | 2.063s | 1.075s | 65.7% | The genuinely starved thread waited 690x longer and scores 29 points lower. Any alarm keyed on the fraction fires continuously on an idle machine and gets quieter when work actually starves. It is not just a cross-regime artifact I expected someone to tell me the comparison is unfair - different machines' states, different moments. So here is the same inversion inside one reading, the saturated one, same three seconds, same 418 waiting threads: == top 3 by FRACTION (wait / runnable) == 0.004 0.000 99.9% 4033987/4037357 claude 0.023 0.000 99.8% 3838113/835843 claude 0.022 0.000 99.8% 3839605/3544672 claude == top 3 by ABSOLUTE wait-seconds == 2.063 1.075 65.7% 853078/853384 main 2.013 1.147 63.7% 853078/853390 main 1.972 1.190 62.4% 853078/853078 main At the exact moment the machine is oversubscribed 2:1 and a real workload is losing two seconds out of three, the fraction ranking is topped by threads waiting four milliseconds. Sorted by fraction, the starved workload does not appear anywhere near the top of the table. The two orderings disagree completely, on identical data, in the one regime where the metric is supposed to work. Why The denominator is the thread's own runnable time, not wall time. So the fraction answers "when this thread wanted the CPU, how often was it queued" - and a thread that wants the CPU for a few microseconds at a time, a few times a second, can answer 99.9% forever while consuming nothing and suffering nothing. Every 99.8%-and-up row in the table above ran for less than a millisecond in three seconds. Worse, that shape is the idle state of a Linux box. A quiet machine is not a machine with no runnable threads; it is a machine full of kworkers, timers, and event loops that wake, do a microsecond of work, and sleep. Every one of them is a candidate for a near-100% wait fraction, because their run time - the entire denominator - rounds to zero. The metric's maximum is populated by exactly the threads you never want to hear about, and it takes real sustained work to push a thread down into the 60s. The fraction is scale-free, and scale is the entire question. "How bad is it" is a question about seconds. What to use instead Sort and alarm on absolute wait-seconds. It has a unit, it aggregates, and a threshold on it means something you can say out loud. Normalize by capacity, not by the thread. The number I put a band on is: total wait cpu-seconds / (wall-seconds ร— cores) At 1.0, every core is carrying one whole extra runnable thread's worth of waiting. That threshold is derived from what the machine is, not fitted to a corpus of past incidents, so it transfers to a box with a different core count without re-tuning. The saturated reading above is 65.49 wait-seconds over 3 seconds on 16 cores = 1.36 - a core and a third of pure queueing. The quiet reading, same arithmetic, is 0.0004. Three and a half orders of magnitude, on the axis where the fraction managed to be backwards. Keep the fraction as a per-row descriptor. It is genuinely useful once you already know a row matters: 65.7% tells you that thread is losing most of its runnable time to contention rather than being slow on its own. It answers how a row is bad. It cannot be trusted to choose the row. Two more traps in the same file The enable bit lies. There is a sysctl that supposedly governs these counters, and the obvious guard is to check it before trusting a reading. On this kernel (6.8.0), five seconds apart: $ cat /proc/sys/kernel/sched_schedstats 0 $ awk '{print $2}' /proc/1/schedstat; sleep 5; awk '{print $2}' /proc/1/schedstat 22806177929 22806197029 The sysctl reads 0 while the counter advances +19100 ns in 5 seconds. Gate on that bit and you render "not available" on a live instrument. The honest gate is a delta: report unavailable only when the counter is frozen across a window in which the machine demonstrably did work - which you can check independently in /proc/stat . A pid walk sees a fraction of the waiting. /proc/ /schedstat exists too, and iterating processes is the natural loop to write. In the saturated reading above, per-thread wait totalled 65.49s, of which threads where pid == tid accounted for 10.90s - 16.6%. Five sixths of the starvation lived on non-leader threads, which is unsurprising once stated: thread pools are where the contention is. The extra /task/*/ in the glob is the whole difference between seeing the workload and seeing its main thread. Honest limits The instrument only counts threads present in both samples. Anything born and reaped inside the window is invisible, and I watched that happen: sampling four seconds after launching the transcriptions, I caught each process with its leader thread only - the workers had not spawned yet - and the reading looked like a quiet machine while four jobs were starting. Coverage is load-dependent and it is at its best exactly when the sense is needed, but it is never 100%, and a tool that does not publish its coverage per reading is inviting you to read a partial scan as a complete one. The bash scan itself costs about 53 ms for 1800 threads, so within a 3-second window the skew between the first and last thread sampled is under 2%. Fine here; not fine if you shrink the window to 200 ms, where the scan becomes a meaningful part of what you are measuring. And schedstat 's field two is specifically runnable and not running. A thread blocked on disk, on a lock, or on a socket is not counted, and correctly so - but it means a low number is not a claim that a thread is healthy, only that it is not losing time to CPU contention. The general shape I have now been caught by this twice with different metrics, so I think it is a shape rather than an anecdote

Read on DEV Community ↗ ← Back to News

Comments

No comments yet. Start the discussion.