The host's load decides no verdict: every wait on a guest reads the guest's own clock, and a wait on another CPU is a bound on a dead one by Japabu · Pull Request #658 · ToyOSOrg/ToyOS

Japabu · 2026-10-01T03:21:39Z

The host's load no longer decides a guest test's verdict for the ten reds it decided. Every wait the harness puts on a guest reads that guest's own clock: the wall clock with the host's steal taken out. The kernel's waits on another CPU's progress are bounds on a dead CPU, not on one the hypervisor has not scheduled yet. The ten rows #654 disabled for these reds go, along with their three issues.

Triage

red	seen on	which	here
update_boots_the_new_kernel, update_falls_back_from_a_dying_kernel, update_floor_is_the_images_own, update_refusals_boot_the_other_slot	#648 at load 84; the first also on #642	host speed: 15 s of wall-clock silence across a firmware reset	fixed: the guest's clock
guest_dies_with_its_harness	#648	host speed: the owner's boot cut at an unscaled 20 s of wall clock while its loader printed	fixed: the guest's clock
syscall_window_nmi_controls	#648	host speed: a 10 s spinner against a million-syscall trigger (it made 950000), and three 100 ms waits on the victim	fixed: the spinner runs until the boot is ended; the victim waits are bounded by DEAF_CPU
virt_smp	#636	host speed: an AP had 100 ms to echo	fixed: AP_START is DEAF_CPU's 5 s
loader_watchdog_arms	#650 (libc only, load 66-74)	host speed, most likely: the boot ceiling, 132 s of wall clock, expired at "BdsDxe: starting Boot0001"; 50-odd passes of 6-34 s in the kept logs	the guest's clock; a stall would still red on it
metal_sim_window_drag, usb_boot_stick_pulled	#650 (libc only, load 66-87, the run reported 1.01x)	host speed: serial-tail boots cut at 21 and 22 s of wall clock with the loader still printing	the guest's clock
redirty_mid_flush	#642	main: the guest went silent after its spawn (stays disabled in #654)	the 74-minute guard is fixed here. It was 120 s × 12 wide × a host_scale of 3.1. It is now 120 s × the host's speed, read on the guest's clock. A stopped guest wants no CPU, so its clock runs at the wall's rate
process_stats, lan_dhcp_lease, root_candidate_malformed, iommu_virtio_platform	#640, #648; #638; #638; #650 and three more branches	main defects	stay disabled in #654
blockd_serves_partitions	#650 (libc only)	main: the bench passed and its process exited, and no ===TEST_END=== came; either test-runner's wait missed the exit or logd stopped forwarding (#655's poller shape is the logd reading; blockd finished, so #643 is not on the path). Stays disabled in #654	its 59-minute guard is fixed here. A chatty idle guest runs to the backstop, which is now the bench's own 600 s on a clock that an idle guest's runs at the wall's rate. Ending it within seconds needs the kernel to say which parks carry a deadline (`issues/diagnostics/an-idle-guest-and-a-hung-one-print-the-same-sched-line.md`)

Decisions

The guest's clock (tests/common/steal.rs). A wait on a guest is a hang detector, and a hang is a guest that does not progress while it has the host. The clock reads QEMU's process accounting: run and runnable time from proc_pid_rusage on macOS, and each thread's schedstat on Linux. For each span:

If the threads wanted less than one thread's worth of CPU, the span counts in full, minus the moments they waited.
If they wanted more, the span counts in the share the host served.

A guest that wants nothing gets the wall's time, so an idle guest and a stopped one are judged on time however loaded the host is. Only a starved guest's clock slows. On a quiet host the clock is the wall, and every ceiling is the number it was before. The independent oracle is steal time as hypervisors account it to a vCPU: Linux's /proc/stat steal column and KVM's steal-time MSR are the same subtraction.

Every wait on a guest reads it:

the boot wait, run_test's ceiling, drain_serial/drain_until, wait_for_console, Liveness, await_guest/await_reset
the screendump waits and await_exit
the update tests' await_machine
the QMP event waits (QmpShutdown, QmpResets, QmpHold, now bounded on the clock with a 200 ms read poll)
the segment's frame wait
the tests' own deadline loops

WIDTH, set_width and round_trip are deleted. The width was a stand-in for contention, and contention is now the clock's to take out. Keeping both double-counts it, which is how a stopped redirty_mid_flush was waited on for 4474 s. host_scale now times boots on the guest's clock, so it measures the host's speed and not its load. The boot ceiling is the 20 s a phase of one guest already gave it.

The run reports its load. #650 called its ceilings "1.01x" at load average 66-87. Its gauge was the fastest boot, which shows the host's speed at its quietest moment and never its load. Every guest's clock now adds its spans to a run-wide tally, and the summary prints host: the guests had N% of the … their waits read across. On Linux, a kernel without schedstat (CONFIG_SCHED_INFO) is refused by name: without that file a starved guest would read as one that wanted nothing.

AP_START is now DEAF_CPU's 5 s, up from 100 ms. The degraded answer on expiry is booting one CPU short for good. A vCPU whose host has not scheduled it is slow, not dead, and a live CPU is already held to DEAF_CPU's span elsewhere in this kernel. Independent oracle: Linux waits 5000 ms for the same echo on arm64 (arch/arm64/kernel/smp.c, __cpu_up) and 10 s in its generic bring-up (kernel/cpu.c, cpuhp_wait_for_sync_state). Cost on metal: a CPU that never answers costs 5 s of boot once, because the loop stops at the first one. The smp-skip-ap boots now wait that 5 s.

The NMI storm.

The spinner never ends by itself. The storm fires on a syscall count, and only the harness, reading the report, knows when the storm is over.
HOLD_ACK_NS and HELD_DELIVERY_NS are DEAF_CPU's 5 s, up from 100 ms.
hold::TURNS is now 2^31, so the hold outlasts that wait at the 3 ns-a-turn estimate its own assertion states.

The redlisted syscall_window_nmi uses the same storm, and its own issue (the sprayed ratio) is unchanged.

-icount is not taken.

It is TCG's alone. The aarch64 guests here run on HVF and CI runs KVM, so it would hide the kernel's exposure to steal on TCG and remove it nowhere.
QEMU refuses MTTCG with it ("No MTTCG when icount is enabled", accel/tcg/tcg-all.c, v11.1.1). Every guest's vCPUs would share one thread in round-robin, switched on a TCG_KICK_PERIOD of 100 ms of virtual time (accel/tcg/tcg-accel-ops-rr.c).
AArch64's core::hint::spin_loop is ISB SY, which does not yield before that kick, so each cross-CPU spin would pay up to 100 ms.

The cost in suite time is unmeasured. An optional job pair below measures it.

Gates

cargo run -- --ci host at 1478bd4: EXIT=0, "56 step(s), all green". The head, f1ad5d1, adds one issue file after it.
- An earlier run at 330c76a was EXIT=1, with clippy's needless_borrow at tests/common/power.rs:777 its one red step. 262dd97 fixed it, and the gate there was EXIT=0, 56 green.
cargo test --test toyos-checks -- steal_clock: EXIT=0.
cargo run -- --build-only: EXIT=0, at 330c76a.
cargo run -- --kernel-feature boot-actuators --build-only: EXIT=0. This is the kernel that compiles nmi_gate, with TURNS = 2^31 and its assertion.
nmi_window_spin built for x86_64-unknown-toyos with the guest toolchain and profile the harness uses: EXIT=0, no warnings.
Redlist: sixteen reds on main, each disabled with the issue that owns it #654's own host CI passed (run 36811706825).

Negative controls and the oracle

Host: served returning the wall span (mut-served-is-wall.patch) built and ran: EXIT=101, "light demand lost the moments it waited: … gave 1s, not 800ms". Losing the runnable time (mut-no-runnable.patch) built and ran: EXIT=101, "28 spinners on 14 cores ran 2.55s and waited 0ns".
Guest: the whole change reverted onto this head for kernel/ and tests/, with this branch's redlist kept so the tests run (negctl-revert-the-change.patch; its tree builds at 1478bd4, cargo test --test toyos-build --no-run EXIT=0, and so does the -icount measurement's). It is requested under the same load as the green arm. Main's own record already holds four sightings: 648 (update ×4, guest_dies, nmi_controls), 642r2 (update_boots), and 636r2 (virt_smp).
Measured on this host at load average 126: a process whose 28 threads ran 1.60 s and waited 7.57 s in 317 ms of wall clock was given 55 ms by the clock (steal_clock check output).

Unsure

Wall-clock bounds left on purpose:
- QMP's own reply and connect bounds (20 s, 10 s). They are QEMU's monitor, not a guest.
- The 2 s drain after a dying guest's panic line.
- Tests' fixed pacing sleeps.
- wallclock.rs's host-time reads, which are the subject of those tests.
- The orphan test's 300 s wait on its owner process, whose own boot now ends on the guest's clock.
The kernel's other guest-time bounds on another CPU are not touched. DEAF_CPU itself has panicked a TCG guest whose vCPU the host starved for 5 s (issues/kernel/a-shootdown-panicked-on-a-cpu-the-host-starved.md). That issue owns the question.
On Linux, a thread that exits between two readings takes its share out of the sum. That span then reads as no demand, which errs toward the wall.
The clock does not see memory-bandwidth or cache contention. A guest slowed by that and not by waiting runs on the wall's time.
Every QEMU ceiling is at most three times what its test takes; wedges end in seconds; two LAN boots ride the talking boot #638 (wt/toyos-tight) also deletes WIDTH, and it rewrites ceiling_verdict, the boot ceiling and several waits converted here. Whichever lands second has a real merge.

The long tests, toward ten minutes

Quiet-host whole runs: 642 (725.6 s), 638L (612.9 s), 641f-r3 (339.6 s). Each figure is that run's time.

test	s
readdir_bound	207 / 166 / 169 (KVM nightly: 16)
update_boots_the_new_kernel	114 / 137 / 81
update_refusals_boot_the_other_slot	109 / 158 / 61
usb_reset_records_the_phase_it_cut	91 / 111 / 74
usb_reset_hands_devices_back	80 / 151 / 54
spawn_cwd	100 / 100 / 33
blockd_lends_within_its_bound	73 / 84 / 69
blockd_survives_its_death	69 / 91 / 60
toolkit_iced	130 (642 only)
update_falls_back_from_a_dying_kernel	56 / 98 / 47

#638 already cuts readdir_bound's /home arm, which was most of its time.

Guest runs owed

None has run on this head yet. The request is /Users/jan/.claude/jobs/2280e09e/tmp/scratchpad/orch/loadfree/jobs.txt:

The ten reds: update_ (all of them), guest_dies_with_its_harness, syscall_window_nmi_controls, virt_smp, loader_watchdog_arms, metal_sim_window_drag and usb_boot_stick_pulled, plus failed_ap_leaves_no_hole for the AP_START change. Each under a host build as a load generator.
The negative control under the same load.
The whole suite, under load and quiet.
Optionally, a back-to-back std_ pair with and without -icount.

🤖 Generated with Claude Code

https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L

The orchestrator stops re-running reds on a quiet host. Every red below is on main's code, so each is disabled now, and its issue says what it is and what ends it. Defects already on main: - process_stats: a connection park charged 0 ns to ipc and to pipe, at process_stats.rs:280 on wt/toyos-loaderlines 6e0d7da (fastest boot 480 ms) and at :263 on wt/toyos-proclife1 60ec86d. Neither branch touches the test or the charge. The existing issue takes both sightings and becomes expected-red. - lan_dhcp_lease: the test awaits the lease and asserts netd's ready line after it, but the capture ends at test-runner's ===READY===, which can come first (wt/toyos-tight 59940c4, ceilings at 1.00x). - root_candidate_malformed: wait_for_ready reads a 16550 ready marker off QEMU's log file while the loader is still writing the line, and the test got "Slot A: REFUSED, its root is" (same run). - redirty_mid_flush: the guest went silent after spawning its child (wt/toyos-proclife 6e9d6a4). The branch's own kernel change is two retired-syscall lines; the test passed at the branch's previous head and in every other kept whole-suite log. Verdicts the host's speed decided: - update_boots_the_new_kernel, update_falls_back_from_a_dying_kernel, update_floor_is_the_images_own, update_refusals_boot_the_other_slot: 15 s of silence across the firmware reset reads as a stall at load average 84, on #648's run and again on #642's. - guest_dies_with_its_harness: the owner's boot is judged at an unscaled 20 s on the host's clock. - syscall_window_nmi_controls: the spinner stops after ten seconds of the guest's clock and the storm waits for a million syscalls; starved, it made 950000. - virt_smp: an AP has 100 ms to echo, and a starved vCPU did not. src/redlist.rs's whole-name test probed `<row>_controls` against None; with syscall_window_nmi and syscall_window_nmi_controls both disabled that probe finds the second row, so it now asserts only that the probe does not find the row it extends. The old assertion reds on this table (checked: EXIT=101), the new one passes. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L

…uest's own clock, and the kernel's waits on another CPU are bounds on a dead one Seven reds were the host's speed, not the guest's behaviour. Each timing assumption is removed where it lives. The harness. Every wait on a guest measured the host's wall clock, so a TCG guest whose QEMU sat runnable and unserved read as one that stopped (the update tests' 15 s of silence across a firmware reset; the owner's boot in guest_dies_with_its_harness killed at 20 s with its loader still printing). The opposite error had the same cause: `budget` multiplied a ceiling by the phase width and by a fastest-boot `host_scale` taken early in a loaded run, so redirty_mid_flush's stopped guest was waited on for 4474 s against its 120 s budget. - tests/common/steal.rs is a guest's own clock: the wall clock less the host's steal, read from QEMU's process accounting (macOS proc_pid_rusage's run and runnable times; Linux's per-thread schedstat). Demand under one thread's worth loses the moments it waited; demand over it has the share the host served. A guest that wants nothing, idle or stopped, has the wall's time, so a stopped guest is called stopped on time however loaded the host is. - Every wait on a guest reads it: the boot wait, run_test's ceiling, the drains, Liveness, the screendump waits, await_exit, the update tests' wait, the QMP event waits (now bounded on the clock with a 200 ms read poll), the segment's frame wait, and the tests' own deadline loops. - WIDTH, set_width and round_trip go: sharing the host is the clock's to take out, and the width was a stand-in for it. The boot ceiling is the twenty seconds a phase of one guest gave it. `host_scale` reads boots on the guest's clock, so it measures the host's speed and not its load. The kernel. `time::AP_START` gave an AP 100 ms to echo, and a vCPU its host had not scheduled for that long booted the machine one CPU short (virt_smp, cpu7 of 8). It is now DEAF_CPU's span, the bound this kernel already holds a live CPU to; Linux waits 5 s for the same echo on arm64 (`__cpu_up`) and 10 s in its generic bring-up (`cpuhp_wait_for_sync_state`). The NMI storm. syscall_window_nmi_controls' spinner stopped after ten seconds of the guest's clock while the storm waits for a million syscalls on one CPU; starved, it made 950000 and the storm never fired. The spinner now spins until the harness ends its boot, and the storm's three waits on its victim (`HOLD_ACK_NS` twice, `HELD_DELIVERY_NS`) are DEAF_CPU's span rather than 100 ms; the hold's budget of turns grows to 2^31 to outlast it at the 3 ns-a-turn estimate its assertion states. The seven rows #654 disabled for these, and their three issues, go: update_boots_the_new_kernel, update_falls_back_from_a_dying_kernel, update_floor_is_the_images_own, update_refusals_boot_the_other_slot, guest_dies_with_its_harness, syscall_window_nmi_controls, virt_smp. -icount is not taken: it is TCG's alone, so the HVF and KVM guests keep the kernel's exposure to steal and only TCG's is masked; QEMU refuses MTTCG with it ("No MTTCG when icount is enabled", accel/tcg/tcg-all.c), and round-robin switches vCPUs on a 100 ms kick of the virtual clock (TCG_KICK_PERIOD), which ISB-based spin loops on AArch64 do not yield before. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L

…only branch's run Both went red in 650-libcllvm-whole.log on wt/toyos-libcllvm, whose diff is userland/libc alone, at load average 66-74. - iommu_virtio_platform is a defect on main. It reads netd's claim line and netd's feature negotiation off a boot log that ends at test-runner's ===READY===, and netd starts before test-runner but speaks after it. The same race reds in two wordings on 634r2, 637r2 and 641f-r3, each on a branch that does not touch it. #639 carries a fix (d773a43). - loader_watchdog_arms timed out its boot at 132 s of wall clock, which is 10 s x 12 wide x host_scale. The console stood at "BdsDxe: starting Boot0001". Its 50-odd other runs in the kept logs passed in 6-34 s. It goes under the harness-wait issue, which now carries this sighting and 650's two update STALLs. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L

The redlist branch added iommu_virtio_platform, which stays disabled here, and loader_watchdog_arms under the harness-wait issue, which this branch closes. Its row goes with the issue. The issue's modified side carried 650's sightings: two update STALLs and loader_watchdog_arms' 132 s boot timeout at "BdsDxe: starting Boot0001", all on wall-clock ceilings this branch puts on the guest's own clock. They are recorded here and in the pull request rather than in a file this merge deletes. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L

…d borrow Clippy's needless_borrow, red in the host gate's clippy step at 330c76a: the guest is already a reference there. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L

650-libcllvm-whole.log, wt/toyos-libcllvm, whose diff is userland/libc alone; load average 66-87, with the run reporting ceilings at 1.01x. - metal_sim_window_drag and usb_boot_stick_pulled timed out their boots at 21 and 22 s in the serial tail, the 20 s a phase of one guest gets. Each had the loader still printing its segments. They go under the harness-wait issue, which now also says why the run's 1.01x could not see the load. - blockd_serves_partitions: the bench passed and its process exited at 35.978 s, then no ===TEST_END=== came for 3559 s, while the kernel kept logging with every CPU idle. Either test-runner's wait on the job missed the exit's post, or logd stopped forwarding. The new issue says which evidence the next sighting needs, and names #655's poller shape as the logd reading. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L

The redlist branch added blockd_serves_partitions, which stays disabled here. It also put metal_sim_window_drag and usb_boot_stick_pulled under the harness-wait issue, which this branch closes, so their rows go with it. The issue's modified side carried 650's serial-tail sightings: two boots cut at 21 and 22 s of wall clock with the loader still printing, and a run that called its ceilings 1.01x at load average 66-87. Both are what the guest's clock and the end of the width take out. They are recorded here and in the pull request rather than in a file this merge deletes. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L

…without schedstat is refused #650's run called its ceilings "1.01x" at a load average of 66-87. Its gauge is the fastest boot, taken at the run's quietest moment, so it sees the host's speed and never its load. Every guest's clock now adds its read spans to a run-wide tally, and the summary says what share of its waits' wall clock the guests had. That is the load, measured where it fell. On Linux the clock reads each thread's /proc schedstat. A kernel built without CONFIG_SCHED_INFO has no such file, so a starved guest would read as one that wanted nothing. demand() now refuses such a kernel by name. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L

blockd_serves_partitions' guest printed "ready=0 ... parked=4" every ten seconds for an hour. The coordinator asked that such a guest be ended within seconds. The line cannot carry that verdict: a guest waiting out a timer prints the same line. The issue records what would carry it, a count of the parks with a deadline, and what it would end early. Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com> Claude-Session: https://claude.ai/code/session_016t9wjdQkB8SH7bmfUoiy6L

Japabu · 2026-10-01T10:50:36Z

Closed as superseded by #670 (landed): its re-cut on the 21-test harness. Under a load average of ~98 main's own wall-clock harness passed 21/21 (the negative control on #670), so the guest-time clock had nothing left to fix and was dropped; the AP_START 5 s kernel fix landed alone in #670.

Japabu and others added 8 commits October 1, 2026 04:19

Japabu mentioned this pull request Oct 1, 2026

The guest suite keeps the 21 tests only a booted machine answers; the rest are metal, host or tracked #660

Merged

Japabu marked this pull request as ready for review October 1, 2026 03:58

This was referenced Oct 1, 2026

Redlist: sixteen reds on main, each disabled with the issue that owns it #654

Closed

The boot CPU waits for an AP's echo as long as a dead CPU is: 5 s, not 100 ms #670

Merged

Japabu closed this Oct 1, 2026

Navigation Menu

Repository navigation

The host's load decides no verdict: every wait on a guest reads the guest's own clock, and a wait on another CPU is a bound on a dead one - #658

The host's load decides no verdict: every wait on a guest reads the guest's own clock, and a wait on another CPU is a bound on a dead one#658
Japabu wants to merge 9 commits into
mainfrom
wt/toyos-loadfree

Japabu commented Oct 1, 2026 •

edited

Loading

Uh oh!

Japabu commented Oct 1, 2026

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

1 participant

Conversation

Japabu commented Oct 1, 2026 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Triage

Decisions

Gates

Negative controls and the oracle

Unsure

The long tests, toward ten minutes

Guest runs owed

Uh oh!

Japabu commented Oct 1, 2026

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

1 participant

Japabu commented Oct 1, 2026 •

edited

Loading