7b2d4037a4
`make ramroot` wiped the objects on the way in, and nothing wiped on the way out. So a plain `make` afterwards kept every RAMDISK_ROOT object and linked the 24 MB ramdisk back into a kernel that no longer used it: 25 MB where a clean build is 836 KB. It still booted -- from the ramdisk -- and the only outward symptom was stage2 having thirty times as much to load through PIO, one sector at a time. That is the "booting got slower" report this came from. A stamp file records which setting the objects were built with, and the tree is dropped when it changes in either direction. qemu-kvm is opt-in and the default stays TCG, because the suite's timings were established there. Measured with the guest timing itself, `ls /bin | wc -l` goes 2.9s -> 1.1s. Boot does not improve and gets slightly worse: every PIO port access in stage2 is a VM exit under KVM. Retracts a claim from earlier today. The "2.2x speedup" attributed to the region-based allocator was a measurement artifact -- the probe sent a command, slept a fixed 50s on the host, then read /proc/uptime, so it timed the sleep rather than the command, through a guest clock that drifts under load. Bracketing the command inside one guest command line shows no measurable difference. The e820 change is still correct; it is simply not a performance change. Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
109 lines
5.1 KiB
Markdown
109 lines
5.1 KiB
Markdown
---
|
|
name: schos-bootcheck-trust
|
|
description: bootcheck silently stopped running and five of seven modes asserted nothing; how to tell a real pass from a script that died
|
|
metadata:
|
|
node_type: memory
|
|
originSessionId: 9d8a2aef-bcf0-47a0-96c6-f706efab4a95
|
|
modified: 2026-08-09T20:44:14.569Z
|
|
---
|
|
|
|
**A green run is only green if you counted the checks.** On 2026-08-09 the
|
|
bootcheck suite was reported passing seven times when it had not executed at
|
|
all, and separately when five of its seven modes asserted nothing whatsoever.
|
|
|
|
**Why:** `bootcheck.ps1` had `[string]$Qemu = (Find-Qemu)` as a param default.
|
|
PowerShell binds parameter defaults *before* any function in the script body is
|
|
defined, so it died on its first line with "Find-Qemu is not recognized" —
|
|
text containing neither `FAIL` nor `Exception`, which were the two words being
|
|
grepped for. Empty output was read as success. Resolve after the param block:
|
|
`if (-not $Qemu) { $Qemu = Find-Qemu }`.
|
|
|
|
**And:** an earlier index-based edit (`s[:a] + inner + s[c:]`) that removed the
|
|
obsolete `-SchFS` block also deleted the `Expect` blocks for `-Tty`, `-Usb`,
|
|
`-Sock`, `-Ps` and `-Evdev`. Those modes still booted, still printed, and still
|
|
exited 0 — asserting nothing. It happened before `git init`, so no commit ever
|
|
had them; they were reconstructed from failure text quoted earlier in the
|
|
transcript.
|
|
|
|
**How to check a run is real:**
|
|
|
|
```sh
|
|
grep -c '\[ok\]' # must be non-zero, and roughly what you expect
|
|
grep -c 'boot check passed'
|
|
```
|
|
|
|
Counting `FAIL` alone cannot distinguish "passed" from "never ran". Expected
|
|
counts as of 2026-08-09: base 23, Tty 47, Ps 28, Sock 60, Fb 32, Usb 27,
|
|
Evdev 25 — Tty and Sock include `[ok]` lines printed by the guest programs
|
|
themselves.
|
|
|
|
**Never pipe a long bootcheck through `head`.** It closes the pipe, kills the
|
|
script partway, and looks like a hang. Redirect to a file and grep the file.
|
|
|
|
**Why:** the general lesson is that absence of failure output is not evidence
|
|
of success. Both of these produced clean-looking runs while testing nothing.
|
|
|
|
**How to apply:** after any change to the harness itself, verify the check
|
|
count, not just the absence of FAIL.
|
|
|
|
## The extended suite was timing-fragile — fixed 2026-08-09
|
|
|
|
`yes writes through a pipe` failed repeatedly on `-Fb -Tty -Usb -Sock -Evdev
|
|
-Ps` while `y`/`y` were plainly correct in the transcript. Three harness bugs,
|
|
all fixed in commit 4e0478c and its follow-up:
|
|
|
|
1. **`Wait-Prompt` waited a fixed 20 s.** Measured from inside the guest, a cold
|
|
`ls /bin | wc -l` takes **23 s** here (**51 s** before the e820 work), so the
|
|
wall was always crossed. Now 60 s.
|
|
2. **It matched the prompt anywhere in the transcript.** Between sending a
|
|
command and the guest echoing it, the log still ends with the *previous*
|
|
prompt — so it could return before the command started. Now anchored to text
|
|
produced after the command was sent.
|
|
3. **On timeout it slept 2 s and typed anyway**, landing the next command in a
|
|
busy shell and interleaving the transcript, so the check that failed was a
|
|
*later* unrelated one. Now waits for output to stop growing.
|
|
|
|
The run also names any command that produced no prompt, because after one
|
|
overrun every later check is reading a possibly-interleaved transcript.
|
|
|
|
**Still treat a lone FAIL here as suspect until you have read the transcript.**
|
|
|
|
**Leaked QEMU made this worse and is now fixed** (commit 4e0478c): the
|
|
`finally` cannot run when the *script* is killed, so QEMU outlived it and, under
|
|
TCG, taxed every later run. Each run now records its pid and reaps the previous
|
|
one's orphan.
|
|
|
|
## Measuring anything about guest speed
|
|
|
|
Do not use host wall clock, and do not compare runs made minutes apart. Three
|
|
confounds each produced a confident wrong answer in one session:
|
|
|
|
1. **Stray QEMU** pinning a core (see above).
|
|
2. **`build/schfs.img` ages** — it accumulates writes across boots. Delete and
|
|
`make build/schfs.img` before every timed boot.
|
|
3. **Ordering / host drift** — alternate the variants and run each twice.
|
|
|
|
Time it from inside — **and bracket the command in a single guest command line**:
|
|
|
|
```sh
|
|
cat /proc/uptime; ls /bin | wc -l; cat /proc/uptime
|
|
```
|
|
|
|
Sending the command, sleeping a fixed interval on the host, then asking for
|
|
uptime **measures the host's sleep, not the command**. That produced a confident
|
|
and completely fictional "2.2x speedup" for the e820 work: the two readings were
|
|
50 s apart because the host slept 50 s, and the arm that looked faster only had
|
|
a guest clock lagging under load. One command line, two readings, no host timing
|
|
in the loop.
|
|
|
|
4. **The guest clock drifts under TCG.** Missed timer ticks mean `/proc/uptime`
|
|
undercounts during heavy load, so it is trustworthy for bracketing a short
|
|
command and not for comparing long intervals across runs.
|
|
|
|
Baselines, measured correctly 2026-08-09 with an 836 KB kernel:
|
|
`ls /bin | wc -l` **2.9 s TCG / 1.1 s KVM**; boot to `schinit: ready` ~3.7 s TCG.
|
|
`make qemu-kvm` is the opt-in KVM target. **KVM does not speed up boot** and
|
|
slightly slows it: stage2 loads the kernel by PIO one sector at a time, and each
|
|
port access is a VM exit.
|
|
|
|
See [[schunix-verify-by-driving-shell]].
|