x86: a dispatched thread with a published wake returns the CPU without consuming it, 5-6 times per specimen

[ryanbreen]

Split out of the #764 round-2 review
(docs/planning/green-program/sockets/764-RCA-2026-09-03.md), which measured
but did not explain a sub-mechanism inside #766's dispatch-latency mechanism:
a thread that has already been woken and dispatched sometimes returns the CPU
without consuming its own wake, several times in a row, before a later
dispatch finally does. This is not the #766 round-robin wait itself -- it is
extra turns inside that wait that #766's "one round robin after a tail
re-enqueue" model does not predict.

The two specimens

repro-boot-057 (docs/planning/green-program/sockets/serials/764-rca/repro-boot-057/serial_kernel.txt):
the reader (thread 30) is woken at line 2291 (unblock(30): Added to per_cpu_queues[0]). It is then restored -- a full dispatch, not merely
enqueued -- six times before it observes the wake:

2313, 2349, 2407, 2490, 2558, 2620  <- "Restored kernel context for thread 30: RIP=0x80002f7912 RSP=0xffffc90000282978"
2622  <- "TCP_BLOCK: Thread 30 woken from recv blocking"

Five of those six restores (2313/2349/2407/2490/2558) are immediately
followed by a CR3 switch and a "Saved kernel context for blocked thread 30"
at an identical RIP/RSP, with zero intervening log lines -- e.g. 2313 (restore)
/ 2314 (CR3) / 2315 (save). Only the sixth (2620) reaches the wake check at
2622 and makes progress.

Re-derived in this slot:

grep -n 'unblock(30)' repro-boot-057/serial_kernel.txt
  -> 2123, 2291
grep -n 'Restored kernel context for thread 30' repro-boot-057/serial_kernel.txt
  -> 2203(pre-wake), 2313, 2349, 2407, 2490, 2558, 2620
grep -n 'woken from recv blocking' repro-boot-057/serial_kernel.txt
  -> 2622

707/boot01 (docs/planning/green-program/sockets/serials/707-2026-09-02/x86-battery-r2/boot01/serial_kernel.txt,
the issue's own #764 specimen): the reader (also thread 30) is woken at
2303, then restored seven times before it observes the wake:

2363, 2489, 2545, 2656, 2705, 2749, 2755  <- restores
2757  <- "TCP_BLOCK: Thread 30 woken from recv blocking"

Six of those seven restores are wasted; the seventh (2755) reaches the check
at 2757 and the read completes.

Re-derived in this slot:

grep -n 'unblock(30)' boot01/serial_kernel.txt
  -> 2210, 2303
grep -n 'Restored kernel context for thread 30' boot01/serial_kernel.txt
  -> 2287(pre-wake), 2363, 2489, 2545, 2656, 2705, 2749, 2755
grep -n 'woken from recv blocking' boot01/serial_kernel.txt
  -> 2757

The 707-battery turn census

docs/planning/green-program/sockets/serials/764-rca/summarize.py, run over
all 25 boots of 707-2026-09-02/x86-battery-r2/, counts a thread's restores
between its wake and the line where its sys_read wait loop observes it
(resumes column). 24 of 25 boots have a countable value (boot14 has no
accept-block line for the port and is excluded):

turns	boots	data_latency_ms
1	20	318 - 1480
2	1	2258
3	1	2768
4	1	3155
7	1	4740 -- the battery's exit 13

Re-derived in this slot:

python3 docs/planning/green-program/sockets/serials/764-rca/summarize.py \
        docs/planning/green-program/sockets/serials/707-2026-09-02/x86-battery-r2/boot* \
  | awk -F'\t' 'NR>1 && $NF!="" {print $NF}' | sort | uniq -c
  -> 20 x "1", 1 x "2", 1 x "3", 1 x "4", 1 x "7"

data_latency_ms tracks this turn count, not queue length or a uniform
per-pass cost -- 39 of 46 boots in the separate 76-boot battery's census
consume the wake on turn one, as expected if a dispatched reader normally
exits its wait loop immediately. The multi-turn boots are the outliers this
issue is about.

Why this isn't already explained

A dispatch of the reader is a full context-switch cycle: a restore
(kernel/src/interrupts/context_switch.rs:962), set_running()
(kernel/src/task/scheduler.rs:2103), and a fresh quantum
(kernel/src/interrupts/context_switch.rs:436). sys_read's wait loop
breaks the moment thread.state != Blocked
(kernel/src/syscall/handlers.rs:1403-1410):

crate::task::scheduler::yield_current();
crate::arch_halt_with_interrupts();

let still_blocked = crate::task::scheduler::with_scheduler(|sched| {
    if let Some(thread) = sched.current_thread_mut() {
        thread.state == crate::task::thread::ThreadState::Blocked
    } else {
        false
    }
})
.unwrap_or(false);

if !still_blocked {
    // ... consumes the wake

So once unblock() has run (set_ready() at scheduler.rs:2897, the
Added to per_cpu_queues log at :2951), a subsequent restore of the same
thread should read Blocked as false and take the !still_blocked arm on
its very first dispatch. It does not, five and six times respectively on the
two specimens above -- and a restore followed immediately by a save at the
same RIP/RSP looks identical in the serial log whether still_blocked ran
and (correctly or incorrectly) read Blocked, or the thread executed no
instruction from still_blocked at all before yielding again. The serials
alone cannot distinguish those two cases.

Candidate reading

Not concluded, just the shape worth checking: set_ready() at
scheduler.rs:2897 and set_running() at scheduler.rs:2103 are two
separate writes to thread state, on two different sides of a dispatch. If
there is a window in which a thread is dispatched (restored, set_running()
called) but its state field has not yet settled to a value distinguishable
from Blocked at the point still_blocked reads it -- or conversely, if
still_blocked can read a state that flips back to Blocked between the
read and the yield_current()/halt on some other iteration -- either would
produce exactly this shape: N restores that make no progress, then one that
does.

Proposed experiment (per CLAUDE.md: tracing framework, not log lines)

A trace_count! (or trace_event!) on the still_blocked == true branch of
the loop at handlers.rs:1403-1410, read back through the lock-free tracing
framework (kernel/src/tracing/, trace_dump() / trace_dump_counters()
via GDB or /proc/trace/*) rather than through a log line, so the hot
context-switch/syscall-wait path is not disturbed. If the counter increments
on the wasted restores, still_blocked is reading Blocked correctly on
each of them, and the question becomes why the scheduler keeps
re-dispatching a thread whose own wait loop has no work to do until turn N;
if it does not increment on some of the wasted restores, the thread is
failing to reach or execute that check at all on those restores, which
points at the dispatch path instead.

Related

• loopback_wake_test_child reader_exit_13: data-path wake latency exceeds DATA_WAKE_BOUND_MS #764 -- the specimen this was found investigating (repro-boot-057, and
  the issue's own 707/boot01 specimen); re-attributed to the scheduler row
  as one presentation of x86: a timer wake dispatches only after a full round robin - measured sleep overrun p90 2592 ms, max 10318 ms over 324 trials #766's dispatch-latency mechanism, but the wasted
  turns inside that wait are a distinct, unexplained sub-mechanism.
• x86: a timer wake dispatches only after a full round robin - measured sleep overrun p90 2592 ms, max 10318 ms over 324 trials #766 -- the round-robin dispatch-latency mechanism this issue's wasted
  turns are inside: x86: a timer wake dispatches only after a full round robin - measured sleep overrun p90 2592 ms, max 10318 ms over 324 trials #766 predicts one round robin (one turn) after a tail
  re-enqueue (scheduler.rs:3731); the two specimens above take six and
  seven turns respectively, which x86: a timer wake dispatches only after a full round robin - measured sleep overrun p90 2592 ms, max 10318 ms over 324 trials #766's stated mechanism does not predict.

[ryanbreen]

Experiment: 60-boot recv-wait counter battery — underpowered, undecided

Branch exp/772-wasted-turns @ 36f0e8fc (instrument 8699af30 + measure
c4e1e88a + this report 36f0e8fc, on top of main 4103571a). Two lock-free
counters (RECV_WAIT_STILL_BLOCKED_TRUE / _FALSE,
kernel/src/tracing/providers/counters.rs) at the still_blocked check in
the recv wait loop (kernel/src/syscall/handlers.rs:1403-1430) distinguish
reading (a) (TRUE increments once per wasted turn before FALSE fires —
unblock()'s set_ready() not yet visible when the loop re-checks) from
reading (b) (the thread is dispatched but the loop body doesn't run to
completion on a wasted turn, so neither branch increments). Full writeup:
docs/planning/green-program/sockets/772-EXPERIMENT-2026-09-03.md.

Measurements

60 boots (docker/qemu/run-x86-gate.sh 4 full, beast breenix-x86 KVM,
same host/driver as the #764 battery below). case is whether the data
recv() entered the wait loop at all (block) or returned without doing
so (no-block, 58/60 boots below); turns is the number of Restored kernel context for thread <tid> lines between unblock() and woken
(- for the 58 no-block boots, where the loop did not run). Full
per-boot serials committed at
docs/planning/green-program/sockets/serials/772-exp/README.md.

boot	case	turns	TRUE	FALSE	lat_ms
01	no-block	-	0	0	1872
02	no-block	-	0	0	1227
03	no-block	-	0	0	3498
04	no-block	-	0	0	1999
05	no-block	-	0	0	1053
06	no-block	-	0	0	2097
07	no-block	-	0	0	1128
08	no-block	-	0	0	1559
09	no-block	-	0	0	2573
10	no-block	-	0	0	2102
11	no-block	-	0	0	1918
12	no-block	-	0	0	805
13	no-block	-	0	0	1302
14	no-block	-	0	0	1236
15	no-block	-	0	0	2386
16	no-block	-	0	0	1347
17	no-block	-	0	0	1272
18	no-block	-	0	0	1591
19	no-block	-	0	0	530
20	no-block	-	0	0	4063
21	no-block	-	0	0	2498
22	no-block	-	0	0	1368
23	no-block	-	0	0	1211
24	no-block	-	0	0	818
25	no-block	-	0	0	1737
26	no-block	-	0	0	1485
27	block	1	0	1	299
28	no-block	-	0	0	1525
29	no-block	-	0	0	2023
30	no-block	-	0	0	1187
31	no-block	-	0	0	6452
32	no-block	-	0	0	1935
33	no-block	-	0	0	2056
34	no-block	-	0	0	1150
35	no-block	-	0	0	1117
36	no-block	-	0	0	1132
37	no-block	-	0	0	3846
38	no-block	-	0	0	2380
39	no-block	-	0	0	3614
40	no-block	-	0	0	1101
41	no-block	-	0	0	1451
42	no-block	-	0	0	4511
43	no-block	-	0	0	1497
44	no-block	-	0	0	1461
45	block	1	0	1	752
46	no-block	-	0	0	1294
47	no-block	-	0	0	1182
48	no-block	-	0	0	1240
49	no-block	-	0	0	2015
50	no-block	-	0	0	1304
51	no-block	-	0	0	1361
52	no-block	-	0	0	696
53	no-block	-	0	0	2203
54	no-block	-	0	0	2666
55	no-block	-	0	0	2787
56	no-block	-	0	0	2553
57	no-block	-	0	0	2078
58	no-block	-	0	0	2124
59	no-block	-	0	0	1734
60	no-block	-	0	0	1586

58/60 boots: no_block_case=true (data already buffered, loop never
ran) → TRUE=0, FALSE=0 correctly, since the branch pair can't fire if the
loop body doesn't execute. 2/60 boots (boot_27, boot_45) blocked and
consumed the wake on the first dispatch (turns=1), both showing
TRUE=0, FALSE=1 — exactly what readings (a) and (b) predict identically
for a 1-turn call, so this confirms the instrument fires where the source
says it fires and reports what it says it reports, without distinguishing
either reading. 0/60 boots produced a turns>=2 specimen — the actual
#772 phenomenon (a reader dispatched twice or more before consuming its
wake) does not occur in this battery.

Population check against #764's battery

#764's own battery (serials/764-rca/battery.tsv, 76 boots, same host and
driver) blocked in 46/76 (61%) boots and had turns>=2 in 7/46 (15%) of
those. This battery blocked in only 2/60 (3.3%) and had 0 turns>=2
specimens — a ~20x drop, not noise.

This is an observer effect of the in-band counter readback, not a host
or profile difference. reader_child's counter bracket
(read_recv_wait_counters(), 3 syscalls: open/read/close of
/proc/trace/counters) now runs between accept() returning and the
blocking read() starting — work #764's reader never had (in #764's
own specimens acc == pre exactly; in this battery pre - acc is never
zero: min 100ms, median 1290ms, max 6515ms across all 60 boots). Measured
directly: w0_to_pre==0 (reader already blocked before the peer's write —
the precondition for blocking at all) drops from 55/76 (72%) in #764's
battery to 2/60 (3.3%) here, tracking the block-rate collapse almost
exactly. The bracket's own added latency is large enough, most of the time,
for the peer's write to land before the reader ever reaches the real
blocking read.

Worth noting: the phenomenon is present in this battery's own serials,
just outside the bracket's scope. reader_child's second blocking call (the
EOF-wait read(), unperturbed by any counter bracket) goes through the
identical wait-loop code and produced 6/59 turns>=2 specimens across the
same 60 boots, including a 5-turn specimen in boot_45
(serial_kernel.txt:2648-2897) matching #772's shape exactly — restore → CR3 switch → save five times at identical RIP=0x8000326f72 RSP=0xffffc90000e19958, zero intervening kernel-log lines each time. No
counter delta brackets that window, so it can't decide (a) vs (b) either,
but it confirms the phenomenon recurs on this host/profile at a rate (~10%)
matching #764's (~15%), and shows the corrected experiment doesn't need
the data read specifically to find specimens.

Corrected measure step

Move the counter read out-of-band: drop the in-band bracket and either
(1) attach GDB post-test and run call trace_dump_counters(), or (2) read
/proc/trace/counters once at process exit, after the pass/fail verdict is
already decided. Either way the reader's own path gets no added syscalls
before the blocking call. Loop the next battery until ≥3 boots produce
turns>=2, not a fixed boot count — both #764's rate (7/76 ≈ 9%) and
this experiment's own EOF-read rate (6/59 ≈ 10%) suggest a few dozen boots
under the corrected measurement should be enough.

Reading: undecided

The two 1-turn specimens confirm the counters measure what they claim, but
a 1-turn call is exactly the case where readings (a) and (b) predict the
same values — there are no wasted turns to tell apart. With 0/60 turns>=2
specimens, this battery has no evidence for or against either reading on
the actual multi-turn phenomenon. The next battery (corrected, out-of-band,
looped to ≥3 specimens) is what would decide it: a turns=6 specimen
showing TRUE=5, FALSE=1 is reading (a); one showing TRUE=0, FALSE=1 (or
any total well under 6) is reading (b).

_{claim-lint: scripts/claim-lint.py --files docs/planning/green-program/sockets/772-EXPERIMENT-2026-09-03.md → exit 0}

[ryanbreen]

Round 2: reading (b) decided — 7/7 usable specimens show the wasted turn skips the counter check

Branch exp/772-wasted-turns @ 0ba65fe7 (rework ffa42938 moved the
read_recv_wait_counters() bracket out-of-band — one read before accept(),
one at process exit, after both the data-read and EOF-wait verdicts — then
measure 8e53590d), on top of main 4103571a. Full writeup:
docs/planning/green-program/sockets/772-EXPERIMENT-R2-2026-09-03.md.

Round 1 diagnosed its own in-band bracket as an observer effect (median
1290ms gap between accept() and the blocking read, block rate collapsed
46/76 → 2/60). This round's out-of-band bracket removes that gap directly
from this battery's own serials (pre - acc is 0 in 107/120 boots, 89.2%)
and block rate partially recovered to 23/120 (19.2%) — still well under
#764's 46/76 (60.5%), reported as a second, unexplained finding, not
chased further in this measure slot.

The task's stop condition (3 DATA-read turns>=2 specimens) was not met

120 boots hit the hard cap with only 2 DATA-read turns>=2 specimens
(boot_011, boot_088), not 3. But round 1 already established the DATA
read and the EOF-wait read share byte-identical wait-loop code
(kernel/src/syscall/handlers.rs:1403-1430), and this round's bracket spans
the whole reader process — so each of this battery's 11 turns>=2 episodes
(data or EOF) carries a counter reading for the same question. That gives
7 boots with a usable delta out of those 11 (the other 4 lost their
EXIT marker to the EOF_WAKE_BOUND_MS/exit-15 path below).

Per-specimen table (11/11 turns>=2 boots this battery produced, opened directly against their own serial + census)

Reading (a) predicts TRUE = turns − 1 (summed across a boot's episodes),
FALSE = 1 per resolved episode. Reading (b) predicts TRUE = 0 regardless
of turns, FALSE = 1 per resolved episode.

boot	data turns	eof turns	TRUE Δ	FALSE Δ	reading (a) predicts TRUE	note
boot_011	3	1	0	2	2	both episodes' counters — DATA specimen, refutes (a) alone
boot_019	1	3	0	2	2	DATA specimen (1 turn) + EOF 3-turn episode
boot_093	1	2	0	2	1
boot_120	1	2	0	2	1
boot_013	– (no-block)	2	0	1	1	data read returned without blocking
boot_016	– (no-block)	2	0	1	1	data read returned without blocking
boot_036	– (no-block)	2	0	1	1	data read returned without blocking
boot_088	2	1	null	null	2	DATA specimen, eof_wait_ms=7689 > EOF_WAKE_BOUND_MS → exit(15) fires before the EXIT marker prints
boot_009	– (no-block)	5	null	null	4	eof_wait_ms=6338 > bound → exit(15), no EXIT marker
boot_099	– (no-block)	3	null	null	2	eof_wait_ms=5493 > bound → exit(15), no EXIT marker
boot_112	1	5	null	null	4	eof_wait_ms=4196 > bound → exit(15), no EXIT marker

7/7 usable-delta boots show TRUE Δ = 0 where reading (a) predicts 1 or
2 in every case. FALSE Δ matches the resolved-episode count exactly in all
110 boots with a usable delta (0 mismatches), confirming the instrument
fires where the source says it fires. The 4 boots without a usable delta all
share one mechanism, independently confirmed in loopback_wake_test.rs: the
EXIT counter read sits after the EOF-wait verdict, and all 4 exceed
EOF_WAKE_BOUND_MS (4000ms) and take the exit(15) arm upstream of it —
this is a disclosed sampling bias (boots with the most wasted turns are the
ones most likely to lose their counter reading), not evidence either way.

Reading: decided — (b)

Reading (a) — RECV_WAIT_STILL_BLOCKED_TRUE increments once per wasted turn
because unblock()'s set_ready() isn't yet visible when the loop
re-checks — is refuted: boot_011 alone (3 turns, TRUE Δ = 0 for the
whole boot) rules it out, and 7/7 usable specimens agree. Reading (b) — the
thread is dispatched (a fresh quantum runs, context_switch.rs's dispatch
path fires) but the wait loop's body
(kernel/src/syscall/handlers.rs:1399-1424) does not reach the
still_blocked check/trace_count! call before being switched out again —
is what the data shows everywhere it could be checked. yield_current()
(kernel/src/task/scheduler.rs:4957) only sets need_resched; the actual
context switch happens at the next interrupt return, not synchronously. A
thread resuming from its arch_halt_with_interrupts() HLT still has to run
the with_scheduler closure and comparison before either trace_count! call
executes — if another interrupt (ordinarily the next 1kHz timer tick) drives
a fresh reschedule before that happens, the thread is dispatched and
re-suspended without ever reaching the check, so neither counter moves. That
is consistent, unanimous, and mechanistic — not just an absence of contrary
evidence.

Confidence: high on the counter evidence itself (7/7 unanimous, 0/110
FALSE-vs-episode-count mismatches, both DATA specimens independently
re-verified against raw serial_kernel.txt/serial_user.txt/census.json
line-by-line in this comment and in the linked report). A fix for the wasted
dispatch would touch the recv wait loop
(kernel/src/syscall/handlers.rs:1379-1430) and very likely the
dispatch/reschedule path it depends on (yield_current() and schedule()
in kernel/src/task/scheduler.rs, and the interrupt-return dispatch in
kernel/src/interrupts/context_switch.rs) — both Tier-1/Tier-2 files under
this repo's prohibited-modifications list, out of scope for this experiment
lane.

_{claim-lint: scripts/claim-lint.py --files docs/planning/green-program/sockets/772-EXPERIMENT-R2-2026-09-03.md → exit 0}

[ryanbreen]

Round 3 review correction — two false statements in the round-2 report, one test perturbation removed

Independent review of the round-2 battery (report comment
#5531930545,
0ba65fe7) found the reading (b) verdict itself holds — it is not in
question — but the test that produced round 2's block-rate number was still
perturbing the phenomenon under study, and two published statements in the
writeup are false. Corrected in three commits on exp/772-wasted-turns @
481c60d2:

1. The test perturbation: the START counter read still ran before accept()

userspace/programs/src/loopback_wake_test.rs restored to origin/main
bytes exactly (git diff origin/main -- userspace/programs/src/loopback_wake_test.rs
→ empty). Coordinator ruling R105: a counter baseline taken inside the
measured process before the measured call is in-band wherever it sits —
moving the bracket from inside the blocking call (round 1) to before
accept() (round 2) relocated the perturbation to the one place it does
the most damage, instead of removing it. No counter readback lands in the
gate binary. The branch's diff against origin/main outside docs/ is now
exactly kernel/src/syscall/handlers.rs and
kernel/src/tracing/providers/counters.rs — the kernel counters stay as
permanent tracing-framework instrumentation.

2. False claim: "the bracket is ruled out … as the cause of the 19.2% block rate"

The report (772-EXPERIMENT-R2-2026-09-03.md:88,101-107 at 0ba65fe7)
called the block-rate gap (60.5% → 19.2%) an "open, unexplained finding"
after ruling the bracket out via pre - acc == 0 in 107/120 boots. That
measurement is real but blind by construction: round 1's bracket sat
between accept() and pre; round 2's bracket sits before accept(),
in a span pre - acc cannot see.

Re-derived directly from this branch's committed serials (acc - w0, the
reader's accept()-return stamp minus the peer's pre-write stamp):

battery	reader work before accept()	acc - w0 p25/p50/p75	boots with acc <= w0
round 1 (60 boots)	none	-63 / -53 / -1 ms	49/60 (81.7%)
round 2 (120 boots)	procfs read + println!	+79 / +129.5 / +159 ms	29/120 (24.2%)

Conditioned within round 2's own 120 boots: acc <= w0 → 23/29 blocked
(79.3%); acc > w0 → 0/91 blocked (0.0%) — blocking is impossible by
construction once the peer's write lands before accept() returns. The
START bracket moved 76% of boots into the peer-wins bucket. That is the
whole of the gap. (Cost is more than three syscalls: /proc/trace/counters
generation also triggers two blocking serial_println!s and a ~90-counter
heap String render — boot_001/serial_user.txt:676-677 vs :724.)

The doc's Verdict section and Section 2 are corrected in place.

3. False claim: "10/10" boots missing the EXIT marker are exit-15

772-EXPERIMENT-R2-2026-09-03.md:203 said the 10 boots lacking
RECV_WAIT_COUNTERS_EXIT are loopback_wake_test_child exit-15 boots.
9/10 are; boot_032 is exit-13:

boot_032/serial_kernel.txt:3264
[DEBUG] kernel::task::process_task: Process 19 'loopback_wake_test_child_19' (thread 30) exited with code 13

boot_032 is a data-side bound failure (data_latency_ms=7153, this
battery's max; w0_to_pre=7136) — exactly the phenomenon under study —
that also loses the EXIT marker. Section 3's sampling-bias disclosure was
written as EOF-only; widened to cover both sides. boot_032 contributes no
turn evidence (its read did not block, per Section 2's acc > w0 bucket),
so reading (b) is unaffected.

What did not change

Reading (b) — the thread is dispatched but the wait loop's body doesn't
reach the still_blocked check before being switched out again — stands.
Nothing in this correction touches the counter-delta evidence (7/7
turns>=2 boots at TRUE Δ = 0, 110/110 FALSE Δ == resolved-episode
count) that decided it.

Also taken from the same review pass, non-blocking: Section 7's
per-signature table undercounted loopback_wake_test_child FAILs (8 vs.
the true 10 — the gate names only the first non-allowlisted process per
boot); and round 1's "median 1290 ms" is a v[n//2] nearest-rank figure
(true median 1286.5 ms), relabeled p50 in both round-1 and round-2 docs.

_{claim-lint: scripts/claim-lint.py --files docs/planning/green-program/sockets/772-EXPERIMENT-R2-2026-09-03.md docs/planning/green-program/sockets/772-EXPERIMENT-2026-09-03.md → exit 0
claim-lint: scripts/claim-lint.py (default, changed hunks) → exit 0}