[Japabu]

Problem

osbench round 2 (#989) showed a whole-machine stop on the T14 (LENOVO 20W0003AMZ, i5-1135G7, BIOS N34ET71W 1.71). Every CPU stopped for 4.1 to 4.6 ms, every 2.2165 to 2.248 s. Across three boots at 588c821ee the per-CPU MSR_SMI_COUNT rose 27 or 28 times per 60 s, matching the 27 late wakes in each boot.

The cause was already measured, with controls, on 2026-10-02 (#681, comment 5966817345) and is recorded in issues/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md. The scout booted the same image twice:

• Legacy mode, nothing written: SCI_EN stayed clear and the count rose by 14 in an idle 30 s and by 13 in a busy 30 s.
• After ACPI_ENABLE: the count stayed at 4818 on every CPU for 61 s.

Linux runs with SCI_EN set and read 0 SMIs in 120 s (perf stat -e msr/smi/, #681). The kernel enables ACPI mode only for the holder of the acpi claim, which is /system/bin/acpiserver. That is the owner's stage-1 ruling, unchanged here.

tests/images/benchcase.toml and tests/images/latencycase.toml did not start acpiserver. Every boot of either image stayed in the firmware's legacy mode: every round-2 log says the firmware handed over in legacy mode and none has an ACPI_ENABLE line. Shipped images (images/system.toml, console.toml) and testcases.toml all start acpiserver. So the bench, and cyclictest's latency, were measuring firmware time that no shipped ToyOS or the bench's Linux pays.

Supporting detail: in ACPI mode acpiserver takes embedded-controller query 0x4f 13 or 14 times per 30 s and 27 times per 60 s on the T14. That is the same rate as the SMIs, which points to the EC event that SMM serves in legacy mode. This is an inference; nothing here reads it inside SMM.

Change

• benchcase.toml and latencycase.toml start acpiserver before test-runner, with the same row images/system.toml uses. The supervisor spawns [boot] start in order, and the claim is minted at spawn, so ACPI_ENABLE lands before the first job. On the T14 the write itself held cpu0 2,243,230 ns (benchcase) and 2,186,279 ns (latencycase), and SCI_EN read set 16,980 and 14,550 ns after it. ACPI stage 1: the machine in ACPI mode for a userland server's claim; its SCI, power button and EC events served #713's 14,868 ns is that second figure. The 2026-10-02 scout's 2,129,279 ns ran from its write to SCI_EN reading set, so it includes the write's hold.
• The osbench and latency_wake judges call a new in_acpi_mode_before_any_job. It refuses a boot that was not in ACPI mode before its first ===TEST_START, or that logged legacy mode again. A firmware that hands over in ACPI mode passes. This keeps a later image edit from quietly bringing the firmware back into the numbers.
• The issue gains one paragraph with the round-2 reading and why those images were exposed.

No kernel, firmware-policy or security change. The AMD bench also hands over in legacy mode (SMI_CMD 0xb0) and its osbench image now also runs acpiserver. Its SMI cost cannot be read there, because it has no SMI counter.

Checks

• cargo run -- --ci host at 27acd19a6 plus this diff: exit 0, 87 steps green. Rerun at the round-1 head a7e96bfa4 (Markdown-only change): exit 0, 87 steps green.
• Negative control for the guard: I ran the osbench judge on a copy of round-2 readback metal-r2b-t14-1 (built from 588c821ee, legacy mode). At 588c821ee it passed (1 passed). With this change it fails with FAIL osbench: the machine was not in ACPI mode before the first job (exit 1).
• T14 metal at e6d6170d8 (run by the orchestrator; the round-1 commit changes only an issue file):
  • benchcase, osbench judge exit 0. ACPI_ENABLE at 12.013 s, the first job at 12.018 s. Every CPU's tail counter read smi=0 over both tail.wake.periodic.60s and tail.diag.periodic.30s. Both runs had late_over_1ms=0, max 37,249 ns and 36,627 ns. Round 2's three boots are the control: same suite, same machine, no acpiserver, 27 late wakes of 4.1 to 4.6 ms per 60 s.
  • latencycase, latency_wake and tlb_shootdown_cost judges exit 0. cyclictest: p99 16 µs, max 1,874 µs. Its SMI count moved 4819 to 4821 over its 2 s. One of those is the acpiserver firmware call 0xf5 logged at 12.151 s (cpu0 held 297,820 ns). The other is not attributed, because later calls of the same byte are not logged one by one.
• AMD bench: no boot. Existing AMD readbacks with acpiserver all log acpi: ACPI mode: ACPI_ENABLE 0xa0 written to SMI_CMD 0xb0 before their first ===TEST_START and never legacy mode again. For example: bench/metal-std-amd/testcases (3a5fc40), crypto-sec/metal-r2/amd/cryptoctcase (9022dcc) and crypto-perf/readback-probe-amd/cryptocase (fb93764). So the guard passes the AMD osbench row.
• Evidence: https://github.com/ToyOSOrg/evidence/tree/655ce68f3ac475ed317f10a522a932b478b61128/smi

Risks

• acpiserver now runs during the bench. It serves an SCI about every 2.2 s and reads the battery every 10 s, as shipped images and Linux do. Its namespace init runs AML that may write SMI_CMD early in the boot. Those are SMIs ToyOS asks for and counts as firmware calls.
• latency.p99_us, tlb.latencycase.p50_ns and tlb.latencycase.p99_ns were recorded from legacy-mode boots.
• The TLB bench is not guarded, on purpose. It runs in the kernel before the supervisor exists: 11.701 s, against ACPI_ENABLE at 12.075 s in the latencycase boot. So it always measures legacy mode, in every image, and an ACPI-mode guard on its row would pass a reading taken in legacy mode. Its 256 shootdowns take well under a millisecond, so an SMI lands in one with a probability of about 1 in 4,000 (inference). A single hit moves the max, not p99 (one sample in 256).
• cyclictest now starts while acpiserver initialises its namespace (12.08 to 12.16 s). Its worst wake (1,874 µs at about 12.10 s) falls in that window; the cause is not identified.
• tests/images/metalcase.toml also starts no acpiserver. None of its rows is a timing row, so it is left as it is.

🤖 Generated with Claude Code

https://claude.ai/code/session_01PXEk8BBMDT8tXu4AnENB9Q

[Japabu]

Review of #1009, round 1 (head e6d6170d8, base 27acd19a6)

Architecture

The fix is right. The acpi claim is the only thing that takes the machine out of legacy mode, and its holder is acpiserver, as the owner ruled for stage 1. Shipped images (images/system.toml, console.toml) and testcases.toml start it. Linux, the comparison, also runs with SCI_EN set. So a bench image that leaves the firmware in legacy mode was measuring a state no shipped ToyOS is in. The approved design says the kernel enables ACPI mode for the claim holder only, so the cure belongs in the image, not in the kernel. The row added is the same row system.toml uses.

I checked the ordering claim against the code. system/supervisor/src/main.rs start() mints each devices claim before it spawns the process. The mint (kernel/src/arch/x86_64/acpi_mode.rs enter) parks the minting task until SCI_EN reads set and only then logs acpi: ACPI mode: ACPI_ENABLE .... [boot] start is spawned in order. So the enable happens before test-runner exists. The judge checks this order anyway.

Judge versus making it unrepresentable. An image row cannot establish the fact that matters. The claim can be refused, SCI_EN can time out, or acpiserver can die, and each of these leaves the machine in legacy mode and the boot still running. Each case is logged by name. Reading the boot's own log is the cheapest check that sees the actual property. A build rule such as "every timing image declares acpiserver" would be a new custom gate, would duplicate the judge, and would still miss all three runtime failures. The judge is the right place. Its coverage is incomplete, though (see below).

metalcase.toml. It needs nothing. Its rows judge no timing. The only numbers its boots record are the per-boot boot.* readings, which are compared with that machine's own record as the 2x bug guard, under the same firmware mode every time. Nothing compares them with Linux.

Perturbation. An SCI about every 2.2 s, with an EC query, and a battery read every 10 s are what Linux also services in ACPI mode, so this is the like-for-like comparison. Their cost is a process's microseconds of CPU, set against a 4.5 ms stop of every CPU. osbench tail's roster names the process behind any late wake, so if acpiserver ever shows up there it will be visible rather than hidden.

Size. +57/-6 across two test images, one judge helper and one issue paragraph. No production code changes.

Findings

BLOCKER tests/toyos.rs:957-970: tlb_shootdown_cost is unguarded. It is a timing row on the same latencycase image and records tlb.latencycase.p50_ns and p99_ns. A 4.5 ms whole-machine SMI that lands in a shootdown window goes straight into p99. Only latency_wake calls in_acpi_mode_before_any_job. A run of tlb_shootdown_cost alone (the handoff stages it as its own word) would therefore accept a legacy-mode boot. That is exactly the regression the guard exists to catch: "keeps a later image edit from quietly bringing the firmware back into the numbers". Fix: call the helper in this judge too. Then correct the issue paragraph's "Both rows' judges" and the PR text so they cover the image's two timing rows, and note that the recorded TLB numbers also came from legacy-mode boots.

BLOCKER (evidence): the host run, the negative control and the staging logs live only in the evidence commit 655ce68, which is not pushed. The PR cites them but links nothing. I read the local logs:

• host.log ends 87 step(s), all green, exit 0, at 27acd19a6.
• host.diff differs from the PR diff only in the issue line until #<PR> versus before 2026-10-22, so reusing the host run is valid.
• negctl-judge.log fails osbench with the new message, exit 1, on metal-r2b-t14-1.

These claims hold, but they have to be published at a full hash. The pending metal runs must also be recorded before landing:

• T14 benchcase: ACPI_ENABLE before the first ===TEST_START, the tail's smi= equal to the firmware calls, and no ~4.5 ms late wakes. This boot is also the positive control showing the guard passes a good boot.
• T14 latencycase with latency_wake tlb_shootdown_cost.
• The osbench row also declares the AMD bench. Nothing in the tree records that machine reaching ACPI mode under acpiserver, and the guard now fails the row there if it does not. The cheapest check is to grep an existing AMD testcases readback for acpi: ACPI mode: ACPI_ENABLE. Otherwise one AMD benchcase boot is needed.

BLOCKER issues/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md:84-91: the paragraph needs two changes.

• Its last sentence, "Both rows' judges now refuse a boot not in ACPI mode before its first job", restates test code that the code already states. It is also incomplete (the TLB row) and will go stale. Delete it.
• "the 30 s diary run read 14 of each" names a run that nothing in the tree or the PR identifies. Give its revision and boot, or drop the clause.

The remainder is accurate against the PR's figures: 27 or 28 per 60 s, 27 late wakes of 4.1 to 4.6 ms spaced 2.2165 to 2.248 s, legacy mode in each log. The by-design statement matches acpi_mode.rs's module contract.

SUGGESTION tests/toyos.rs:5885-5893: the counters row already reads acpi: ACPI mode: ACPI_ENABLE and refuses acpi: legacy mode again inline. Calling the new helper there would keep one spelling of "this boot was in ACPI mode". Optional.

SUGGESTION (PR description, the orchestrator's to fix): "the ACPI_ENABLE write (about 2 ms on cpu0)". The issue records 2,129,279 ns for the scout's raw write but 14,868 ns through the claim (#713). Either cite the claim figure or drop the number.

Not a finding:

• The helper finds the kernel needles in log(), not kernel(). It needs one text in which to compare positions against ===TEST_START. If logkeeper reordered the merge, the result could only be a false refusal, never a false pass.
• At the stop, smi_cmd refuses ACPI_DISABLE, so a clean boot never logs legacy mode again. The counters row already depends on the same fact on the T14.

SEND BACK

[Japabu]

Round 1 response (head a7e96bfa4)

BLOCKER tlb_shootdown_cost unguarded: refuted, with a note added. The TLB bench is a boot parameter. It runs in the kernel on the BSP before the supervisor spawns anything. In the latencycase boot at e6d6170d8 it logs tlb: bench ... at 11.701 s, while acpi: ACPI mode: ACPI_ENABLE follows at 12.075 s once the supervisor spawns acpiserver. So no image can put that bench in ACPI mode. in_acpi_mode_before_any_job on its row would pass a reading taken in legacy mode, which is a false assurance. The PR now says that its recorded numbers come from legacy mode, that this holds by construction, and how much an SMI can move them: about 1 in 4,000 per boot (inference), and one sample in 256 moves the max, not p99.

BLOCKER evidence: the T14 metal results (osbench, latency_wake, tlb_shootdown_cost, all judges exit 0 at e6d6170d8) and the AMD readbacks are now in the PR body. The publication push was denied by the session's permission policy. Per the orchestrator, it stays local (655ce68) pending the owner, and the PR says so.

BLOCKER issue paragraph: the "Both rows' judges..." sentence is gone. The diary clause now names each round-2 boot's 30 s tail.diag run at 588c821ee; all three read late_over_1ms=14 and smi=14. One sentence records the fixed T14 reading.

SUGGESTION counters row helper: declined. It would add the first-job ordering condition to the testcases boot's judge, and its metal evidence would then need re-judging for a dedupe of three lines.

SUGGESTION "about 2 ms": corrected with the measured figures. The write itself held cpu0 2.24 ms and 2.19 ms in the two T14 boots, and SCI_EN read set 17 and 15 µs after it. #713's 14,868 ns is the second figure, not the write's cost.

• cargo run -- --ci host at a7e96bfa4: exit 0, 87 steps green.

[Japabu]

Review of #1009, round 2 (head a7e96bfa4; only the issue file changed since e6d6170d8)

Round 1 blockers

1. tlb_shootdown_cost unguarded: refuted, and I accept the refutation.

• kernel/src/main.rs:538-547 runs arch::tlb::bench() on the BSP after smp::set_ready() and before scheduler::enter_idle_loop(). At that point no process exists, so no claim can have enabled ACPI mode.
• The latencycase readback agrees: tlb: bench ... p99=2417ns max=32397ns at 11.701 s, then ACPI_ENABLE at 12.075 s. in_acpi_mode_before_any_job would pass because the enable precedes the first ===TEST_START, so on this row it would vouch for a legacy-mode reading. I was wrong to ask for it.
• "Legacy mode by construction", stated in the PR, is the right resolution:
  • The bench needs "nothing else running", so it cannot run after userland exists.
  • Making the kernel wait for a userland claim before benchmarking would add machinery for one actuator.
  • The row records p50 and p99 only. Moving p99 takes at least three of the 256 samples, and the 256 shootdowns take about 0.4 ms against a 2.2 s SMI period. Moving p99 is effectively impossible, and the max that one hit could move is not recorded.
• No change to the row or the bench is needed.

2. Evidence: resolved for review purposes. The PR body now gives the T14 results for all three rows at e6d6170d8 and the AMD readbacks. I checked the latencycase readback myself:

• ACPI_ENABLE ... the write held cpu0 2186279ns ... SCI_EN set 14550ns after at 12.075 s;
• ===TEST_START test_rs_cyclictest=== at 12.080 s;
• cyclictest at p99=16us ... max=1874us, with SMI counts 4819 to 4821 on every CPU;
• the 0xf5 call at 12.151 s that held cpu0 297,820 ns.

These match the PR. Publishing the evidence commit at a full hash is still owed before landing. That decision belongs to the orchestrator and the owner, not to this code.

3. Issue paragraph: resolved. The judge sentence is gone. The diary clause names each round-2 boot's 30 s tail.diag run. The new sentence matches the benchcase figures in the PR: smi=0 and a 37,249 ns max.

Round 1 suggestion on the ACPI_ENABLE cost: the author is right

smi_cmd::Written's Display prints the write held cpu{on} {held}ns. enter() starts SCI_EN set {} after from written = clock::now(), which is taken after smi_cmd::write returns. #713's line predates the held field and reads ..., SCI_EN set 14868ns after, so 14,868 ns is the time from write to SCI_EN, not the write's cost. The write held cpu0 2.19 ms here (2.24 ms on the bench boot). My round 1 suggestion was wrong, and the PR's corrected text is accurate.

New: cyclictest's 1,874 µs worst wake inside acpiserver's startup

Do not make the row wait for acpiserver to settle.

• The judged number is latency.p99_us, and it is 16 µs. One wake cannot move it: that takes 100 of the 10,000.
• Every shipped boot runs this same startup, so the window is a property of ToyOS, not noise from the image.
• Waiting on an event would remove from the only latency instrument we have the one real-time wake that was 1.9 ms late, while leaving the cause unexplained.

The readback narrows the cause without settling it. The 0xf5 SMI is too short at 298 µs. Between 12.08 and 12.155 s, acpiserver makes 42,906 firmware-memory reads plus 385 AML SystemMemory reads, each a kernel access. The second SMI has no attribution.

BLOCKER (no silent debt): a real-time-band wake 1.87 ms late with no identified cause is now recorded only in the PR's Risks section, and a PR body is not a durable record.

• Record it in issues/ with the boot (e6d6170d8, T14 latencycase), its figures, the startup window, the unattributed second SMI, an owner and an exit.
• The firmware-call issue fits if the cause turns out to be an SMI, but nothing shows that yet. A new finding is the honest home.
• Investigating it is not this PR's job. The cheapest next step is to map cyclictest's worst-wake clock onto the log's and read the firmware-call count and nanoseconds at the stop.

Suggestion

issues/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md:90-91: "one boot read no SMI on any CPU over either run" should name the osbench boot and its revision (e6d6170d8). The latencycase boot of the same round read two SMIs, so "one boot" invites a misreading. Optional.

SEND BACK. The only remaining blocker is the issues/ record of the 1,874 µs wake, which is a Markdown-only change.

[Japabu]

Round 2 response (head 05e1bedbb)

• New finding issues/cyclictests-worst-t14-wake-may-fall-in-acpiservers-startup.md, owned by the latency track. It records:
  • the boot: e6d6170d8, T14 latencycase;
  • cyclictest's figures (max 1,874 µs at 638,179,441 ns nanos_since_boot; run from 12.082 s to 14.103 s);
  • the startup window: ACPI_ENABLE at 12.075 s, namespace initialised at 12.160 s, power sources at 12.171 s. The log puts the end at 12.160 s, not 12.155 s;
  • 42,906 firmware-memory reads and 385 AML SystemMemory reads;
  • the logged 0xf5 call (297,820 ns) and the second, unattributed SMI.
  • The placement near 12.10 s is labelled an inference: the clocks are not aligned.
  • Next step: align the stamp, then read the kernel's firmware-call count and time at the stop.
  • Exit: the cause is named; if it is the startup, the owner decides whether timing rows wait for it.
• The SMI issue now names "one osbench boot at e6d6170d8".
• cargo run -- --ci host at 05e1bedbb: exit 0, 87 steps green.