Skip to content

The ACPI probes ask off the boot processor from a held thread - #1187

Merged
Japabu merged 4 commits into
mainfrom
flaky-tests
Nov 5, 2026
Merged

Japabu merged 4 commits into
mainfrom
flaky-tests

Conversation

@Japabu

@Japabu Japabu commented Nov 5, 2026 •

Copy link
Copy Markdown
Collaborator

Problem

acpi_mediated_access reddened intermittently with acpi: 64 threads in a row started on the boot processor: three nightly reds between 2026-10-21 and 11-03 (39566825102 tcg, 40847028162 and 41618038084 kvm), and the first guest-rows run of main at 15c26bf on the quiet runner (42008942191). The probe spawned a thread again and again until one read itself off the boot processor; where a spawn lands is the scheduler's, and on a two-CPU guest it can land every one on the boot processor. acpi_release, the T14 acpi_server_death job, used the same loop and fell back to claiming from the boot processor, which that row's judge refuses; and a thread that read itself off the boot processor could still be preempted onto it before the kernel took its request.

Change

Both probes ask from one thread held to the machine's last CPU with core_affinity (tests/guest/rust-tests/src/off_the_boot_processor.rs). A mask moves the thread as it is set and keeps it off every other CPU, which affinity_pins holds, so the asker is fixed before the request and stays fixed. The 64-try loops and the fallback are gone.

The harness now requires each of the three crossed calls (0x51..0x53) asked from that CPU (cpu{cpus-1}), where it required one of them asked from any CPU but the boot processor.

Records: issues/no-t14-row-arranges-an-acpi-disable-asked-off-the-boot-processor.md loses the enable's window and the fallback (its exit loses that clause; the disable's asker and the lock-spin answer stay owed), and the ACPI track loses the matching caveat.

Nightly 41427513540 reddened the same row a second way, ten lines for five calls. On that tree the acpicase boot carried a console port, and the merged capture held each call's line off the port and again off the UART. acpicase's probe boots have had no console port since 79473b7, so the UART is their one console and nothing here addresses that mode.

Evidence

All guest runs on the guest runner (guest-rows.yml), x86-64 KVM:

run head filter result
42008942191 main 15c26bf acpi_mediated_access … red: 64 threads in a row started on the boot processor
42010705757 this branch, 0383550 acpi_ acpi_mediated_access green, the three calls asked from cpu1, x2APIC [1, 1, 1]; acpi_lock_given_back_on_one_cpu, acpi_supply_outlives_holder, acpi_holder_is_refused_a_held_functions_configuration green; acpi_press_is_one_sci STALL, see below
42010736954 mutation: held to CPU 0 acpi_mediated_access red as predicted: firmware call 0x51 was asked from cpu0, where the probe held its asker to cpu1

Logs: https://github.com/ToyOSOrg/evidence/tree/cae8728ee085cd0e7555b49c065fe21dc4f27226

acpi_press_is_one_sci stalls in 3 of 3 runs: 42010705757 and 42016111039 at 0383550, and 42025888487 on main at b27dd3e. Every time, the console ends at the kernel's Boot: complete and carries nothing past the UART's hand-over to its driver, so no line of any userland process appears. It is main's, not this branch's: the press arm makes no firmware call, and the silence starts before the probe could speak. Recorded with the runs in issues/acpi-press-is-one-sci-boots-to-a-console-that-carries-no-line-past-the-hand-over.md. The 11-03 nightly, before #1175 made the UART a driver's, passed the row. Evidence: https://github.com/ToyOSOrg/evidence/tree/dd2322e70ef113d1da8d5418647bbb8fa22e52c5/r3

Review r1's other records:

  • issues/sixty-four-spawns-in-a-row-landed-on-the-spawners-cpu.md: the sighting the pin hides. It carries the four runs, the CpuHandles::place rule they contradict, the three candidate causes and owner kernel::sched. It becomes a defect with severity hang if the cause is a doorbell left unserviced.
  • issues/a-red-run-keeps-no-serial-for-a-boot-whose-uart-is-qemus-stdio.md: a boot whose 16550 is QEMU's stdio writes no uart-*.log, so the red run's serial artifact held only another lane's passing boot.
  • The harness's crossed bytes now note that they mirror the probe's CROSSED.

Host checks: cargo run -- --ci host on this tree, exit 1. Its only red step is the build system's buildlock fairness test and the Directory not empty that test leaves for the next one. Both are flakes in build/, which this branch does not touch, and #1186 fixes them. Every guest-crate clippy and test step is green.

Metal: the T14 booted the acpicase image staged at 0383550 (rc=0, boot verdict passed), and --metal-readback judged it PASS acpi_server_death. The job claimed from x2APIC id 7, the kernel wrote ACPI_ENABLE on cpu0 asked from cpu7, and the disable, which nothing arranges (see the record), was asked from cpu3. Evidence: https://github.com/ToyOSOrg/evidence/tree/b8532182b82f83b367675bca20de5273ccaa6d5b/r2. Supported targets are unchanged: the QEMU rows on q35 x86-64, acpi_server_death on the T14.

Record-only commit f529b66: issues/the-nightly-is-frozen-so-nothing-runs-the-guest-matrix.md now carries portability-linux's dependency on pulling a moving debian:sid tag. All six of its nightly reds from 10-24 to 10-31 were toomanyrequests pulls. Resumption owes an image pinned by digest from a mirror the build controls.

🤖 Generated with Claude Code

acpi_mediated asked its three crossed firmware calls, and acpi_release its
claim, from a thread it spawned again until one read itself off the boot
processor, 64 at most. Where the spawns went was the scheduler's, and on a
two-CPU guest it put all 64 on the boot processor: three nightly reds from
2026-10-21 to 11-03 (runs 39566825102 tcg, 40847028162 and 41618038084 kvm)
and the first guest-rows run at 15c26bf (42008942191), each `acpi: 64
threads in a row started on the boot processor`. acpi_release fell back
to claiming from the boot processor, which the T14's acpi_server_death
judge then refused; and a thread that read itself off the boot processor
could still be preempted onto it before the kernel took its request.

Both now ask from one thread held to the machine's last CPU with
core_affinity (tests/guest/rust-tests/src/off_the_boot_processor.rs). A
mask moves the thread as it is set and keeps it off every other CPU, which
affinity_pins holds, so the asker is fixed before the request and stays so.
The harness now requires each of the three crossed calls asked from that
CPU, where it required one of them asked from any CPU but the boot
processor.

Nightly 41427513540 reddened the same row another way, ten lines for five
calls: on that tree the boot carried a console port, and the merged capture
held each call's line once off the port and once off the UART after the
UART had said the log was carried elsewhere. acpicase's probe boots have
had no console port since 79473b7, so the UART is their one console.

The records lose what the pin closes: the window and the 64-try fallback
in issues/no-t14-row-arranges-an-acpi-disable-asked-off-the-boot-processor.md,
and the matching caveat in the ACPI track.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
… the internet

Six nightlies from 2026-10-24 to 10-31 failed portability-linux before its
first step, the pull of public.ecr.aws/docker/library/debian:sid refused
`toomanyrequests`. A verdict that rests on the public internet is one root
CLAUDE.md rules out; the nightly is frozen, so the record that owns its
resumption now carries this too.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
@Japabu

Japabu commented Nov 5, 2026

Copy link
Copy Markdown
Collaborator Author

Review r1 of #1187 at 0383550 (and the record-only f529b66)

Architecture. Pinning is legitimate test control. The probes test whether SMI_CMD crosses to the boot processor, not where the scheduler places a thread. An affinity mask is the explicit, supported way to choose that CPU, and the previous record's own exit asked for this pin. The 64-try loop made the row an accidental placement test, and its fallback in acpi_release produced a boot that the T14 judge refuses. Net change: +55/−128.

Does core_affinity work as used? Yes.

  • set_for_current goes through the ToyOS fork already pinned for affinity_pins to sys_thread_set_affinity (proc.rs:246). For the calling thread, set_affinity → realign → KernelHw::kick on its own CPU sets need_resched (hw.rs:37–42). The move is therefore taken before the syscall returns to ask, not at some later tick.
  • affinity_pins covers this: its first x2apic_id() after pin(on) must match every read after a sleep.
  • The kernel's cpuN is the CpuId index, which is what cpu_count() - 1 and the harness's cpus - 1 name.
  • Both arms ran: in 42010705757, acpi_mediated_access (2 CPUs) read asked from cpu1 ×3 with x2APIC [1,1,1], and acpi_lock_given_back_on_one_cpu (1 CPU, held = 0) read [0,0,0].
  • The mutation 42010736954 (head edd0c3e) failed as predicted at 0x51.

Is 64 spawns in a row on cpu0 expected placement? Not by the documented rule. This is the one required finding.

Required

  1. The placement anomaly the reds exposed is not recorded. The pin removes the only signal of it. issues/ should get it as a sighting: issues/placement-has-no-migration-cost-or-wake-affinity.md covers something else, and nothing else covers it.
    • The rule. CpuHandles::place (kernel/pure/sched/cpu.rs:2867) orders candidates by (load, !sleeping_unrung, busy_siblings, homed, away, idle_exit) from a rotating start (driver.rs:382). On a 2-CPU guest, the probe's main thread runs on cpu0 and calls cpu0 home.
    • What it predicts. With equal published load, an idle cpu1 wins on sleeping_unrung, or else on homed. Ties alternate with the rotating start, so 64 consecutive landings on cpu0 cannot be chance: the odds are 2⁻⁶⁴.
    • What it implies. Something systematic happened in each case: cpu1's published load stayed higher for 15 ms, cpu1 was judged not answering (a standing doorbell edge older than STALE_PASS_NS), or the new thread was moved to cpu0 before its first instruction. None of these is established, and the second would be a real kernel defect.
    • The observations. I confirmed all four reds carry the message: nightly 39566825102 (tcg), 40847028162 and 41618038084 (kvm), plus guest-rows 42008942191. In 42008942191 all 64 spawns ran within about 15 ms (log lines 472–497).
    • What is needed. Either explain it from the code or file the sighting with those runs, the rule it contradicts and an owner. Fixing it is out of scope here. The phase rule forbids hiding a race, and the cheapest compliant step is a short record.
  2. The acpi_press_is_one_sci STALL in 42010705757 is still unattributed. That row runs the changed acpi_mediated binary (tests/toyos.rs:3105), so this branch is not unrelated by construction. The PR body correctly does not claim it is. Before landing, read the console that 42016111039 (queued, head 0383550) captures. If the stall is independent, say why and record it as a sighting. If it reproduces, investigate. A green rerun alone does not attribute it.

Suggestions

  • The job's serial artifact kept another lane's file in 42010705757. That is an evidence-collection defect in guest-rows, and it is worth a short record so the next STALL is not unreadable as well.
  • tests/toyos.rs:2997 repeats CROSSED as ["0x51", "0x52", "0x53"]. It is acceptable across the crate boundary, but a one-line note that it mirrors the probe's CROSSED would keep the two in step.

Records.

  • The window and the fallback are gone from no-t14-row-arranges-... together with the matching exit clause. The new "unbuilt" proposal is consistent with current_mask, since a spawned process starts with its spawner's mask.
  • The ACPI track's caveat is deleted correctly, and no stale reference to STARTS, claim_off_the_boot_processor or the 64-thread fallback remains.
  • f529b66 is accurate: nightly.yml:119 names debian:sid, and job 124496246843 shows toomanyrequests.
  • I did not review the metal acpi_server_death claim in the PR body, which was excluded from this review.

SEND BACK

… whose serial nobody keeps

Review r1 of #1187: the pin removes the only signal of a placement that
contradicts CpuHandles::place, so the four runs that showed it, the rule and
the candidate causes are a sighting with an owner. And guest-rows
42010705757's serial artifact held another lane's passing boot while the
stalled stdio-UART boot left no file at all.

The harness's crossed bytes say they are the probe's CROSSED.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Japabu added a commit that referenced this pull request Nov 5, 2026
…'s hand-over, on main too

The STALL review r1 of #1187 asked to attribute: 3 of 3 runs, two at
0383550 and one at main b27dd3e, each silent after the kernel's
Boot: complete. The press arm makes no firmware call and the stall is before
any userland line, so it is not this branch's; recorded with its runs and the
neighbouring boot whose UART stopped mid-line.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
…'s hand-over, on main too

The STALL review r1 of #1187 asked to attribute: 3 of 3 runs, two at
0383550 and one at main b27dd3e, each silent after the kernel's
Boot: complete. The press arm makes no firmware call and the stall is before
any userland line, so it is not this branch's; recorded with its runs and the
neighbouring boot whose UART stopped mid-line.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
@Japabu

Japabu commented Nov 5, 2026

Copy link
Copy Markdown
Collaborator Author

Orchestrator verification of the round after review (0383550..2060374). It changes no code:

  • Three new issue records, a nightly-record addition, and one comment line in tests/toyos.rs.
  • Required finding 1 is resolved: the placement anomaly is recorded as a sighting with its four runs, the rule it contradicts, the candidate causes and an owner.
  • Required finding 2 is resolved: the acpi_press_is_one_sci stall reproduces on main b27dd3e (42025888487), so it is independent of this PR. It is recorded, with the next diagnostic step.
  • The T14 acpicase boot judged PASS (acpi_server_death), and the guest evidence at 0383550 applies unchanged.

@Japabu
Japabu marked this pull request as ready for review November 5, 2026 12:52
@Japabu
Japabu added this pull request to the merge queue Nov 5, 2026
Merged via the queue into main with commit e162a44 Nov 5, 2026
10 checks passed
@Japabu
Japabu deleted the flaky-tests branch November 5, 2026 13:12
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant