Split off-CPU intervals into sleeping and run-queue time - #3

Why

A blocked interval runs from switch-out to switch-in, so it holds two different waits: the thread's sleep until its wakeup, and then its wait on a run queue until it gets a CPU. PR #2 recorded why each interval began and left this split as future work, with capture proto field 21 and profile entry fields 20–23 reserved for it. This PR fills them in:

sleeping = wakeup − switch_out
runqueue = switch_in − wakeup

How it is measured

The scheduler already keeps each task's total run-queue wait in task_struct.sched_info.run_delay, the second field of /proc/<pid>/schedstat. The switch-out hook saves it and the switch-in hook reads it again; the difference is that interval's run-queue time.

• The accounting runs whenever the kernel has CONFIG_SCHED_INFO, whether or not delay accounting or schedstats are switched on at runtime. This was checked in the kernel source for v6.13 and master:
  • it starts at enqueue_task (the same activation that precedes sched_wakeup), or at sched_info_depart for a task that leaves the CPU still runnable;
  • it adds the wait to the counter in prepare_task_switch, before our switch-in hook;
  • migrations and EEVDF delayed dequeue are accounted for.
• It costs two field reads in hooks that run anyway. A sched_wakeup hook would fire for every wakeup on the host; it is left for a future waker-attribution source, and it would have to be sched_wakeup, not sched_waking, which can fire before the switch-out.
• A pending signal on 5.18–6.12 makes __schedule keep a sleeping prev_state without dequeuing the task. sched_info counts that interval as run-queue time throughout, which is what actually happened.

What changes

Configuration and capture

• A new timeSplit block beside sampling: source: schedInfo (the default) or off. It is resolved, echoed by the native side, written into the manifest, captureStart and analysisInputs, and compared structurally, like sampling. It is a separate block because it changes what is measured, not which intervals are kept.
  • schedInfo fails at prepare on a kernel whose BTF lacks sched_info.run_delay, and the error names timeSplit.source: off. There is no silent fallback.
  • The flat native option is time-split=schedInfo|off.
• The BPF program reads the fields through local CO-RE flavours guarded by bpf_core_field_exists, so it still loads on a kernel without them.
• Observations carry runqueue_nanos (field 21), and the control schema moves to version 4. The kernel drops a reading only when the counter went backwards, and counts it in runqueueInversions. The ring record grows from 128 to 136 bytes.
• The agent rejects a row that carries a reading under off.

The split rule, applied by the consumers from the raw value:

• blocked: the run-queue part is the tail [end − runqueue, end], and the rest is sleeping.
• runnable and preempted: run-queue time throughout.
• Unsplit, never guessed or clamped:
  • intervals from a version 2 or 3 capture or a capture with off;
  • intervals whose reading the kernel dropped;
  • blocked intervals whose reading exceeds their duration.
• Each part is clipped to the analysis window separately, so sleeping + runqueue + unsplit equals each interval's clipped duration exactly.

Correlator

• The report's offCpuReasons.matched.<reason> gains sleepingNanos, runqueueNanos and unsplitNanos. A new offCpuReasons.timeSplit gives the source, whether the split is available, the rule, unsplit intervals by cause, and runqueueInversions.
• The stack profile fills entry fields 20–23 and adds unsplit_nanos and estimated_unsplit_nanos (24–25) plus provenance time_split_json. The change is additive and the profile schema stays 1.
  • The estimated parts are floored cumulatively, so they add up exactly to estimated_nanos.
  • A profile without the split, including one written by PR Classify off-CPU intervals by switch-out reason and add a stack profile #2, reads as all unsplit, so merge just sums.
• stacks --time total|sleeping|runqueue|split:
  • split keeps the whole time and ends each line in a [sleeping], [runqueue] or [unsplit] frame, so one flame graph shows both waits.
  • Modes other than total refuse a profile without the split.
  • --summary adds time and unsplitNanos.
• export adds the six split columns.
• The default collapsed files, the audit files and the synthetic JFR are unchanged.

Docs: the README ("Why the thread left the CPU", the agent options, the overhead table, "Slice and filter"), OFFLINE.md (a new "Sleeping and run-queue time" section, the profile, retention), the AGENTS.md contract, and the agent and native READMEs.

A finding worth knowing

A runnable or preempted interval's reading can exceed its duration by a few microseconds, because rq_clock can be stale when a running task leaves the CPU (sched_yield, for example, updates it before calling schedule()). In the proof this happened to about 3 % of such intervals, by at most 26 µs; no blocked interval overshot. The first version dropped these readings in the kernel (82 of 6,830). Now the kernel passes the raw value through, and the rule treats runnable and preempted intervals as run-queue time regardless.

Verification

Gate: the kernel proof. run-offcpu-reason-proof.sh is extended and passes on the 16-CPU 7.1.5 host, with task_delayacct=0 and sched_schedstats=0:

• For each sleeper, the recorded run-queue parts add up to the growth of its /proc/<pid>/task/<tid>/schedstat run delay; for the uncontended sleeper they match to the nanosecond (251,114 ns).
• A nice-19 sleeper pinned beside three nice-0 spinners waits 1.42 ms for a CPU after each 1 ms sleep, against 136 ns uncontended.
• Runnable and preempted spinners are run-queue time for 99.96 % of their duration.
• There are no inversions, no blocked overshoots, and no readings in a phase with the split off.

Overhead. A pipe ping-pong in the target, pinned to one CPU, with admission set to zero so that only the hooks run: schedInfo against off measured +18 ns and −17 ns per round trip in two runs, on about 3,000–3,400 ns with the hooks attached. That is within noise.

Tests

• ./gradlew spotlessCheck :jonoffcpu-agent:check :jonoffcpu-correlator:check, cargo fmt --check, and the native unit tests pass (including struct layout, timeSplit parsing and record encoding).
• New correlator tests cover:
  • the split rule: every reason, clip windows before, across and after the wakeup, and missing or oversized readings;
  • a version 4 capture end to end, with report numbers checked, --time slices that add up to the total, a canonical profile and exact estimated parts;
  • merging with a version 3 profile;
  • off rows with readings rejected;
  • schema/timeSplit mismatches rejected.
• run-packaged-agent-smoke.py --libc musl passes on x86-64 with new assertions:
  • the resolved timeSplit is {"source":"schedInfo"};
  • all 1,515 matched blocked intervals are split (33.02 s sleeping, 0.49 ms run queue, none unsplit);
  • --time split renders back to the total.
• Collector smoke, sched-exit, target-exit and T07/T08 pass.
  • The sequence-boundary proof failed once (15 of 16 expected is_switch=false callbacks) and passed twice on rerun; that check is untouched by this change.
  • T09 and T14 fail as before for their known unrelated reasons.

Pulsar broker capture (version 2), main against this branch on the same machine:

• The collapsed stacks and the matches file are byte-identical.
• The profile still renders the collapsed file, and --time runqueue is refused with a clear message.
• Correlation time is unchanged (main 89 s and 90 s, branch 87 s and 91 s).
• Peak retention goes from 272 to 284 MB: 8 bytes per row, plus the wider profile counters.
• The synthetic JFR has the same events and converts to the same 19,026 collapsed lines. Only the byte order of the JMC writer's constant pool shifts.

Compatibility

• New default: a configuration without timeSplit resolves to schedInfo. On a kernel without CONFIG_SCHED_INFO, a configuration that worked before now fails with a message naming timeSplit.source: off. Mainstream distribution kernels enable it through TASK_DELAY_ACCT or SCHEDSTATS.
• A version 3 correlator refuses version 4 captures with its schema-version error.
• The source column slot grows from 51 to 59 bytes.