From fb4479c710b544502af4b65d616e210d56e4c1e1 Mon Sep 17 00:00:00 2001 From: japabu Date: Fri, 9 Oct 2026 15:18:58 +0200 Subject: [PATCH 1/5] The stop takes the console's wire from klogd for good and holds it to the machine's end A stop could power the machine off or reset it with its last records on no console. Measured on 8-CPU virt guests under HVF with a probe on the stop's two drains: drain_for_the_stop held the wire and let it go to klogd, queued behind it; klogd's turn was posted and klogd was not dispatched. The last word's drain_inline then found the wire free with a ticket outstanding (ticket=197 now=196) and declined, and flush_final spun on try_wire until its count ran out (2.95 s and 4.16 s in two reds), with the stop's thread parking nowhere from there to the power-off and running with preemption off from xhci::seal_shut on. SYSTEM_OFF followed, and on virt no black-box page said what was lost. Now the stop asks klogd for the wire (log::handoff), and klogd lets it go between two writes, never takes it again, and posts that it has. The stop parks on that post, so its own CPU is free to run klogd, bounded by LET_GO, DEAF_CPU's span; it then holds the wire through power::shutdown and power::reboot, which drain under it (StopWire). A take past the bound alerts; no take by it alerts with the holder's name and writes every record over it through the registers. klogd logs that it let the wire go, so a console says why its backlog arrives at the last word. flush_final, and its spin on a count, is gone. The hand-off's two SeqCst fences are loom's (console_handoff). The staged holder is two actuators, wire-held-across-the-stop and wire-kept-through-the-stop, judged on one-CPU q35 at the power-off and on virt at the reboot; with the stop's path as main has it, all four stall waiting for the last word. Closes issues/the-power-offs-last-drain-gives-up-on-a-wire-whose-holder-cannot-run.md. Files issues/a-woken-klogd-can-wait-seconds-on-an-idle-cpu-under-hvf.md, the dispatch delay the probe found under it, which this does not fix. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_017cSFvbD35xJ2kGANVdm23C --- ...-under-host-load-can-go-silent-for-15-s.md | 20 ++ ...n-reach-the-console-after-the-last-word.md | 2 +- ...n-wait-seconds-on-an-idle-cpu-under-hvf.md | 54 +++++ ...t-is-a-count-its-comment-calls-a-second.md | 10 +- ...-give-back-line-is-in-no-black-box-tail.md | 2 +- ...es-up-on-a-wire-whose-holder-cannot-run.md | 62 ----- kernel/loom/src/lib.rs | 5 + kernel/loom/tests/console_handoff.rs | 40 ++++ kernel/src/actuator.rs | 9 + kernel/src/drivers/serial.rs | 52 +++-- kernel/src/log/console.rs | 215 +++++++++++++++--- kernel/src/log/handoff.rs | 46 ++++ kernel/src/log/mod.rs | 1 + kernel/src/power.rs | 39 ++-- kernel/src/syscall/machine.rs | 26 ++- tests/common/power.rs | 73 ++++++ tests/common/serial.rs | 3 + tests/toyos.rs | 26 ++- 18 files changed, 540 insertions(+), 145 deletions(-) create mode 100644 issues/a-woken-klogd-can-wait-seconds-on-an-idle-cpu-under-hvf.md delete mode 100644 issues/the-power-offs-last-drain-gives-up-on-a-wire-whose-holder-cannot-run.md create mode 100644 kernel/loom/tests/console_handoff.rs create mode 100644 kernel/src/log/handoff.rs diff --git a/issues/a-counters-read-under-host-load-can-go-silent-for-15-s.md b/issues/a-counters-read-under-host-load-can-go-silent-for-15-s.md index 6de1f2db100..98081336f78 100644 --- a/issues/a-counters-read-under-host-load-can-go-silent-for-15-s.md +++ b/issues/a-counters-read-under-host-load-can-go-silent-for-15-s.md @@ -136,6 +136,26 @@ the step each stopped in is not read from it: 77 (38 s, with ceilings paid at 8.00x and 31 s between its image and its first guest line) and 75 to 67 (7 s). +**What a last-word stall of `virt_mask_windows` can be, measured.** Under +HVF, on the entropy stage's branch at `863d73ed3` with a probe on the stop's +two drains, `virt_mask_windows` stalled with the same line, `STALLED: waiting +for the boot's last word — it went quiet`, and the guest had not gone quiet +but off: the last word's drain found the console wire free with one ticket +outstanding (`ticket=197 now=196`), its turn posted to `klogd` and never +taken, and `serial::flush_final` spun 2.95 s on it, gave up and the machine +powered off with its last records on no console. A red `virt_el1_smp`, probed +before the ticket was, found the holder word free and spun 4.16 s; 2 reds in +21 runs of the five SMP tests side by side, load 23 +to 52. That is fixed by the change that deleted `flush_final`: the stop takes +the wire from `klogd` for good and parks while it waits, bounded by +`log::console::LET_GO`, past which it says so and writes over the holder. +What links the two stalls without a console above to it: the same test, the +same wait, ended by the same bound, on a boot whose last word went through +that drain. What does not: they ran under TCG, where the entropy stage saw 0 +of 50 emulated runs stall, and nothing of theirs names the wire, so neither +is shown to be it. The occurrences that stall at a job's end are not this: +they stop before the stop begins. + Not known of any of them: whether the fork compiler's fault reaches `test_rs_counters_read` or the kernel under it. `issues/the-forks-llvm-deletes-a-loops-exit-on-a-no-wrap-flag-scalar-evolution-gives-the-wrong-value.md` diff --git a/issues/a-holders-queued-line-can-reach-the-console-after-the-last-word.md b/issues/a-holders-queued-line-can-reach-the-console-after-the-last-word.md index 4e035ace570..ff553e7ea0c 100644 --- a/issues/a-holders-queued-line-can-reach-the-console-after-the-last-word.md +++ b/issues/a-holders-queued-line-can-reach-the-console-after-the-last-word.md @@ -34,7 +34,7 @@ leaves a line in the queue at the stop goes red without that and green with it. The stop drains the queue on the wire right after `quiesce::stop()`, before `Syncing filesystems...` -(`log::console::drain_for_the_stop`). +(`log::console::take_for_the_stop`). - The drain disabled as a checked patch: `cargo test --test toyos-build -- --nightly quiesce_stops_the_machine` EXIT=1, `1 line(s) reached the console after the boot's last word: console: a holder's line, queued once diff --git a/issues/a-woken-klogd-can-wait-seconds-on-an-idle-cpu-under-hvf.md b/issues/a-woken-klogd-can-wait-seconds-on-an-idle-cpu-under-hvf.md new file mode 100644 index 00000000000..7be3385edae --- /dev/null +++ b/issues/a-woken-klogd-can-wait-seconds-on-an-idle-cpu-under-hvf.md @@ -0,0 +1,54 @@ +--- +status: open +kind: defect +opened: 2026-10-09 +--- + +# A woken `klogd` can wait five seconds on an idle CPU under HVF + +A wake that makes `klogd` runnable on an idle AArch64 CPU under HVF can leave +it undispatched until something else wakes that CPU. + +**Measured.** `virt_reboot_wire_kept` on `Profile::Virt` (HVF, two CPUs), +the entropy stage's branch at `863d73ed3` with this fix applied, an +Apple-silicon host of 14 cores, 1-minute load 16 at the one reading taken: +the stop sets the +staging's flag and `post_wake`s `klogd` at guest 1.574 s, and `klogd`'s next +loop top is at 6.579 s, on cpu1, as each of its six tops that boot was. The +stop, on cpu0, was parked on the staging's watch the whole time. `klogd` ran +5 ms after the stop's deadline, when a probe on that path had kicked every +CPU. The staging's wait timed out in 6 of 10 runs of that test, and in none +of 4 of `virt_reboot_wire_held`, whose staging is the same code to that +point. The probe is a patch on the pull request that deleted +`serial::flush_final`. + +The same shape, read off the probe on that branch's own kernel: a stop that +let the console wire go to a queued `klogd` found its turn posted and still +not taken 2.95 s later, on an 8-CPU guest +(`issues/a-counters-read-under-host-load-can-go-silent-for-15-s.md`). + +One occurrence that may be it, on x86-64: `machine_shutdown_wire_held` (q35, +one CPU, TCG) in the whole suite at `c2a4542f0`, 1-minute load 21.53 when the +suite began and 36.77 when it ended, on the same host: the staging's wait, +then bounded at 5 s of guest time, panicked, `the staged klogd never took the +wire`, 27 s of wall clock into a test that passes in about 7. Its console was +virtio-console's, which the harness keeps no copy of, so it does not say +whether `klogd` ran or the host starved the guest. Eighteen whole suites after +it with a probe on that wait, at load 18 to 67, did not repeat it. The +staging's wait now has no bound in guest time, so a repeat is a stall the +harness's ceiling names. + +**What it costs now.** The stop waits `log::console::LET_GO` for `klogd`, +then alerts and writes over it; nothing is lost. A program woken the same +way waits the same. + +**Not known.** Whether the wake reached cpu1 at all, whether cpu1's sleep +handshake missed it, or whether HVF delivered the kick late; no register +capture of cpu1 exists. Whether TCG or x86-64 can do the same: the staged +tests run under TCG (`Profile::VirtEl2`) and on q35, and have not. + +**Exit**: the cause named from a capture of the idle CPU, and fixed; +`virt_reboot_wire_kept` and `virt_reboot_wire_held` move to `Profile::Virt` +and pass 100 runs each under HVF with no staging timeout. + +Owner: the orchestrator. diff --git a/issues/the-panic-lock-spin-limit-is-a-count-its-comment-calls-a-second.md b/issues/the-panic-lock-spin-limit-is-a-count-its-comment-calls-a-second.md index ed33d6b0bd7..e74504e0758 100644 --- a/issues/the-panic-lock-spin-limit-is-a-count-its-comment-calls-a-second.md +++ b/issues/the-panic-lock-spin-limit-is-a-count-its-comment-calls-a-second.md @@ -6,13 +6,13 @@ opened: 2026-09-27 # The panic lock spin limit is a count its comment calls a second -`PANIC_LOCK_SPIN_LIMIT` in `kernel/src/drivers/serial.rs` bounds two waits: -`panic_flush`'s for `BackendGuard`, and `flush_final`'s for the console wire. -It is 100,000,000 iterations of a `try_lock` and a `pause`, and its comment +`PANIC_LOCK_SPIN_LIMIT` in `kernel/src/drivers/serial.rs` bounds the fatal +path's wait for `BackendGuard` (`panic_registers`, which `panic_flush` and the +stop's write over a kept wire take). It is 100,000,000 iterations of a `try_lock` and a `pause`, and its comment calls that "~1s of spin". Nothing converts it to time, so the wait lasts whatever that many `pause`s cost on the CPU running them. **Evidence:** the code. -**Exit condition:** both waits are bounded by time against the counter the -panic path already times its bound with, and the comment says what is measured. +**Exit condition:** the wait is bounded by time against the counter the panic +path already times its bound with, and the comment says what is measured. diff --git a/issues/the-power-offs-give-back-line-is-in-no-black-box-tail.md b/issues/the-power-offs-give-back-line-is-in-no-black-box-tail.md index 8c75f9660fa..45bb12a9c6f 100644 --- a/issues/the-power-offs-give-back-line-is-in-no-black-box-tail.md +++ b/issues/the-power-offs-give-back-line-is-in-no-black-box-tail.md @@ -17,7 +17,7 @@ On the console it follows `Shutting down.`, which `quiesce` calls the boot's last word. So on a machine with no serial port no reader keeps the line: `/log`'s writer -was stopped with the rest of userland, `flush_final` has no wire to drain to, +was stopped with the rest of userland, the stop's last drain has no wire to drain to, and the page was sealed without it. The T14 is such a machine, and one where the kernel writes `ACPI_ENABLE` itself and a holder can be stopped holding the lock. diff --git a/issues/the-power-offs-last-drain-gives-up-on-a-wire-whose-holder-cannot-run.md b/issues/the-power-offs-last-drain-gives-up-on-a-wire-whose-holder-cannot-run.md deleted file mode 100644 index e812387367d..00000000000 --- a/issues/the-power-offs-last-drain-gives-up-on-a-wire-whose-holder-cannot-run.md +++ /dev/null @@ -1,62 +0,0 @@ ---- -status: open -kind: defect -opened: 2026-10-08 ---- - -# The power-off's last drain counts iterations on a wire whose holder may be unable to run, and then powers off without the tail - -Read from the code at `d78350c71`, not run. Named by the review of pull -request #767 (its comment 6058801505); every line below was read again here. - -`serial::flush_final` (`kernel/src/drivers/serial.rs:263`) is the last drain -before `power::shutdown` and `power::reboot` end the machine -(`kernel/src/power.rs:21`, `:53`). It asks `try_wire` up to -`PANIC_LOCK_SPIN_LIMIT` times (`serial.rs:131`, `:264`, `serial_lock::within`) -and, if the wire never came free, appends one line to the black box and -returns: the machine powers off with its last records undrained. - -The wire is a `SleepLock` "held with interrupts on and preemption allowed" -(`serial.rs:278-279`), and `klogd` takes it once per pass -(`kernel/src/log/console.rs:417`, `body`: `serial::wire(&parkable)`). On the -way to the power-off, `quiesce` (`kernel/src/syscall/machine.rs:69`) logs the -boot's last word (`:109`) and calls `console::drain_inline` (`:112`), which -declines a held wire (`console.rs:94`: -`let Some(wire) = serial::try_wire() else { return }`). Its last call is -`xhci::seal_shut` (`machine.rs:132`), which, where it gets the controller -lock, forgets the guard: "Preemption stays disabled with it" -(`kernel/src/drivers/xhci/mod.rs:1550`; the `forget` is `:1565`). - -The seal is the point this turns on. Up to it nothing read here takes -preemption from the stop's thread (it parks at `:94`), so a `klogd` holding -the wire when `drain_inline` declined can still run, finish its pass and let -go: nothing between `:112` and `:132` prevents that. From a seal that was -taken to the power-off the stop's thread has preemption off. So on one CPU, -a `klogd` descheduled inside its hold when `seal_shut` takes the controller -lock is never run again: `flush_final`'s count is then a wait on a -holder that cannot run, and it expires. Whatever that hold had not yet put on -the wire, and every record committed after it, is on no console. On more than -one CPU the holder runs elsewhere and lets go. Where the seal is refused -(`seal_shut`'s `None` arm) no guard is forgotten, and this reading does not -apply. - -**Not established**: how `klogd` comes to be descheduled inside its hold at -the seal. `drain_for_the_stop` (`machine.rs:94`) parks on the wire and so -finds it free once, but the two censuses, the stop's record and the last -word are logged after it (`:96`-`:109`) and before the seal, and a record's -commit wakes `klogd`. No run shows the loss. `machine_shutdown_short_stop` -waits on `Shutting down.` on one CPU through this drain, so its history on -`main` is the base rate. - -## Owner - -The orchestrator. - -## Exit condition - -`flush_final` waits on the wire's release where its holder can still run, or -the stop keeps the holder from being left inside its hold at the seal; and a -one-CPU guest test, whose actuator leaves `klogd` descheduled inside its hold -of the wire as the stop's thread takes the seal in `seal_shut`, reads -`Shutting down.` on the console. That test is red on a kernel whose last -drain is today's. diff --git a/kernel/loom/src/lib.rs b/kernel/loom/src/lib.rs index 9dd8a9b0cf3..8051dcc80d9 100644 --- a/kernel/loom/src/lib.rs +++ b/kernel/loom/src/lib.rs @@ -378,6 +378,11 @@ pub mod scheduler { #[path = "../../src/sleeplock.rs"] pub mod sleeplock; +/// The stop's claim on the console wire and `klogd`'s answer, driven over the +/// sleep lock above by `tests/console_handoff.rs`. Atomics and nothing else. +#[path = "../../src/log/handoff.rs"] +pub mod log_handoff; + /// The i8042's interrupt tally. `tests/i8042_tally.rs` is the only model whose /// subject is a *driver*, and it is here for the reason the others are: the /// property is "no reader ever sees this pair disagree", which is a claim about diff --git a/kernel/loom/tests/console_handoff.rs b/kernel/loom/tests/console_handoff.rs new file mode 100644 index 00000000000..ba4261b6360 --- /dev/null +++ b/kernel/loom/tests/console_handoff.rs @@ -0,0 +1,40 @@ +//! Loom: the stop's claim on the console wire against `klogd`'s letting go +//! (`kernel/src/log/handoff.rs`), over the real `SleepLock`. +//! +//! `klogd` holds the wire, lets it go, and reads whether the stop asked; the +//! stop asks, and tries the wire. One of them must see the other: the stop's +//! try finds the wire free, or `klogd` sees the ask, and so posts the let-go +//! the stop parks on. Where neither does, the stop waits out its whole budget +//! on a wire nobody holds and writes over it. Removing either `SeqCst` fence +//! from `handoff.rs` reds this model with exactly that outcome. + +#![cfg(feature = "loom")] + +use kernel_loom::log_handoff::Handoff; +use kernel_loom::scheduler::{become_task, TaskId}; +use kernel_loom::sleeplock::SleepLock; + +const KLOGD: TaskId = TaskId(1, 0); +const STOP: TaskId = TaskId(2, 1); + +#[test] +fn the_stop_finds_the_wire_free_or_klogd_sees_the_ask() { + loom::model(|| { + let wire: &'static SleepLock<()> = Box::leak(Box::new(SleepLock::new(()))); + let handoff: &'static Handoff = Box::leak(Box::new(Handoff::new())); + + become_task(KLOGD); + let held = wire.try_lock().expect("nobody else has the wire yet"); + let klogd = loom::thread::spawn(move || { + become_task(KLOGD); + drop(held); + handoff.asked() + }); + + become_task(STOP); + handoff.ask(); + let took = wire.try_lock().is_some(); + let saw = klogd.join().unwrap(); + assert!(took || saw, "the stop's try found the wire held and klogd never saw the ask: nobody posts"); + }); +} diff --git a/kernel/src/actuator.rs b/kernel/src/actuator.rs index 93117b8e7f9..4f8d7cc7d0c 100644 --- a/kernel/src/actuator.rs +++ b/kernel/src/actuator.rs @@ -79,6 +79,14 @@ actuators! { /// it outlasts the stop. Judged by `machine_shutdown_short_stop`. stop_budget_spent = "stop-budget-spent"; + /// Have `klogd` take the console's wire as the stop begins and keep it + /// until the stop asks for it. Judged by `machine_shutdown_wire_held`. + wire_held_across_the_stop = "wire-held-across-the-stop"; + + /// The same, with `klogd` keeping the wire through the stop's whole + /// `LET_GO`. Judged by `machine_shutdown_wire_kept`. + wire_kept_through_the_stop = "wire-kept-through-the-stop"; + /// Make one CPU ignore a kick. dump_deaf_cpu = "dump-deaf-cpu"; @@ -189,6 +197,7 @@ const IMPLIES: &[(&str, &[&str])] = &[ // so the control that ends a machine no other bound ends is staged over the // one that stops this machine ending itself. ("hard-lockup-probe", &["wedge-before-reset"]), + ("wire-kept-through-the-stop", &["wire-held-across-the-stop"]), ]; #[cfg(feature = "boot-actuators")] diff --git a/kernel/src/drivers/serial.rs b/kernel/src/drivers/serial.rs index 111358ad6cd..7dc11c80ef6 100644 --- a/kernel/src/drivers/serial.rs +++ b/kernel/src/drivers/serial.rs @@ -12,7 +12,7 @@ use core::sync::atomic::{AtomicBool, Ordering}; use crate::arch::IrqGuard; use crate::log; -use super::serial_lock::{self, BackendLock, Held, Seized}; +use super::serial_lock::{BackendLock, Held, Seized}; use crate::scheduler::Parkable; use crate::sleeplock::{SleepGuard, SleepLock}; @@ -253,29 +253,27 @@ pub unsafe fn panic_flush() { unsafe { crate::log::console::drain_bypassed(&mut uart) }; } -/// Drains the ring before the machine powers off, so the tail of a shutdown -/// is not lost to `power::shutdown()` cutting power with logs still queued. -/// -/// Bounded on the wire like `panic_flush`, but never bypasses: every CPU is -/// still live here, and reading the ring unsynchronized is only safe once -/// nothing else runs. Losing the tail is better than not powering off, and -/// the black box says it was lost, since the console cannot. -pub fn flush_final() { - if let Some(wire) = serial_lock::within(PANIC_LOCK_SPIN_LIMIT, try_wire) { - crate::log::console::drain_all(&wire); +/// Every committed record through the registers, for a stop whose wire +/// `klogd` kept: a line of the holder's still in flight may interleave with +/// these. Never bypasses: every CPU is still live here, and reading the ring +/// unsynchronised is only safe once nothing else runs. +pub fn drain_over_the_wire() { + if !has_console() { return; } - crate::blackbox::append(|lines| { - let _ = writeln!( - lines, - "console: the wire stayed held through the stop's last drain, so this boot's last \ - records are not on the console" - ); - }); + let mut uart = panic_registers(); + match &mut uart.0 { + Hold::Held(guard) => crate::log::console::drain_locked(guard), + Hold::Reentered(_) | Hold::Expired(_) => uart.write(NOT_DRAINED), + } } -/// Who may put a line on the wire: `klogd`, and the few drains that stand in -/// for it (boot before it runs, the stop, the power-off). **Held with +/// What a stop whose registers stayed held too writes in place of its records. +const NOT_DRAINED: &[u8] = + b"\n[serial] the stop's records are not on the console: its wire and its registers stayed held\n"; + +/// Who may put a line on the wire: `klogd`, the drains that stand in for it +/// before it runs, and the stop, which takes it from `klogd` for good. **Held with /// interrupts on and preemption allowed**, for a whole line, so a line is one /// holder's; [`BackendGuard`] is taken inside it once per burst, which is the /// only interrupts-off window the console costs. @@ -286,6 +284,20 @@ pub fn wire(parkable: &Parkable) -> SleepGuard<'_, ()> { WIRE.lock(parkable) } +/// Who holds the wire, for the stop that waited it out. +pub fn wire_holder() -> impl core::fmt::Display { + struct Holder(Option); + impl core::fmt::Display for Holder { + fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result { + match self.0 { + Some(task) => write!(f, "task {task}"), + None => write!(f, "a context with no task"), + } + } + } + Holder(WIRE.holder()) +} + /// The wire, if it is free, from any context — the boot before per-CPU state /// exists included, which has no task to hold it as. pub fn try_wire() -> Option> { diff --git a/kernel/src/log/console.rs b/kernel/src/log/console.rs index 32450524d4f..a11459d7dca 100644 --- a/kernel/src/log/console.rs +++ b/kernel/src/log/console.rs @@ -9,6 +9,12 @@ //! //! [`Drain::Inline`] and [`Drain::Thread`] are phases, not fallbacks: exactly //! one is active, and `Drain::Inline` *is* [`KLOGD`] being null. +//! +//! **The stop takes the wire from `klogd` for good** ([`take_for_the_stop`]): +//! asked, `klogd` lets it go between two writes and never takes it again, and +//! the stop holds it to the machine's end, so every record the stop commits +//! reaches the wire before a CPU is taken down. A `klogd` that keeps it through +//! [`LET_GO`] has the stop write over it, through the registers. use core::sync::atomic::{AtomicPtr, AtomicU64, AtomicU8, Ordering}; @@ -23,11 +29,13 @@ use crate::hw::HW; use crate::sched::driver::{cpus, irq_off}; use crate::sched::kthread; use crate::sleeplock::SleepGuard; +use crate::time::{Budget, Deadline, Duration, DEAF_CPU}; use crate::watch; use crate::sched::payload::KShared; -use crate::scheduler; +use crate::scheduler::{self, Parkable}; use crate::sync::Lock; +use super::handoff::Handoff; use super::read::{drain_ordered, Published, RecordSink}; use super::shard; @@ -84,35 +92,109 @@ pub fn post_wake() { } /// Put every committed record this machine has not yet spoken on the wire, -/// where the wire is free: the boot before `klogd` runs, and the few contexts -/// that stand in for it. Declining loses nothing: the record stays committed, -/// and whoever holds the wire drains it too. +/// where the wire is free: the boot before `klogd` runs, and a backend's +/// arrival. Declining loses nothing: the record stays committed, and whoever +/// holds the wire drains it too. pub fn drain_inline() { if !serial::has_console() { return; } let Some(wire) = serial::try_wire() else { return }; - drain_records(&wire, u64::MAX); + drain_records(&wire, u64::MAX, Yield::Never); } -/// Everything owed to the wire — records and queued lines — for a caller that -/// holds it and is about to take the machine down. -pub fn drain_all(wire: &SleepGuard<'_, ()>) { - drain_records(wire, u64::MAX); - drain_queue(wire, usize::MAX); +/// Whether a drain lets the wire go to the stop that asks for it. +#[derive(Clone, Copy, PartialEq, Eq)] +enum Yield { + /// `klogd`'s: it stops between two writes once the stop asks. + ToTheStop, + Never, } -/// Every queued line onto the wire, for the stop once it has stopped every -/// console holder: what a holder queued before it was stopped goes on the wire -/// under the boot's last word and never after it. The record backlog stays -/// `klogd`'s, so the sync behind this is not spent behind a slow wire. -pub fn drain_for_the_stop() { - if !serial::has_console() { - return; +/// The stop's claim on the wire, which `klogd` answers. +static HANDOFF: Handoff = Handoff::new(); + +/// Posted by `klogd` once it has let the wire go for the stop. +static LET_GO_POSTED: watch::Watch = watch::Watch::new(); + +/// How long the stop waits for `klogd` to let the wire go once asked. +/// +/// `klogd` lets go between two writes, so what it owes is the write it is in: +/// one rendered line, at most [`LINE_BYTES`], which the slowest wire this +/// kernel programs, the 16550 at 38400 baud, takes in 300 ms. [`DEAF_CPU`]'s +/// span is far past that and is the span after which a CPU that has not run +/// what it was given is a wedged one: a `klogd` that has not let go by then is +/// on one, or holds the wire through a defect. +pub(crate) const LET_GO: Budget = Budget::of( + Duration::from_nanos(DEAF_CPU.nanos()), + "the stop says who kept the wire, and writes every record over it through the registers", +); + +/// The console as the stop holds it, from the moment it has stopped every +/// console holder to the machine's end. Never dropped: what holds one ends +/// the machine. +pub enum StopWire { + /// The wire, which `klogd` let go of and never takes again. + Held(SleepGuard<'static, ()>), + /// `klogd` kept the wire through [`LET_GO`]; the stop writes over it. + Kept, +} + +impl StopWire { + /// Every committed record onto the console, and every line console + /// holders queued where the wire is held. + pub fn drain(&self) { + match self { + Self::Held(wire) => { + drain_records(wire, u64::MAX, Yield::Never); + drain_queue(wire, usize::MAX, Yield::Never); + } + Self::Kept => serial::drain_over_the_wire(), + } } - let parkable = scheduler::Parkable::at_entry(); - let wire = serial::wire(&parkable); - drain_queue(&wire, usize::MAX); +} + +/// The wire, for the stop once it has stopped every console holder, held from +/// here to the machine's end; and every queued line onto it, so what a holder +/// queued before it was stopped goes on the wire under the boot's last word +/// and never after it. +/// +/// Waits on `klogd`'s letting go, bounded by [`LET_GO`]: past it the stop +/// alerts by name and writes over the holder (a line of `klogd`'s still in +/// flight may interleave; nothing is lost but the queued lines, which the +/// alert says). The record backlog stays undrained here, so the sync behind +/// this is not spent behind a slow wire: the boot's last word drains it. +pub fn take_for_the_stop(parkable: &Parkable) -> StopWire { + // Armed before the ask: a let-go posted between the ask and the park is + // one the park returns on at once. + let armed = watch::arm(&LET_GO_POSTED, 0, kernel::sched::task::WaitClass::Other) + .expect("console: the stop holds no task to park"); + HANDOFF.ask(); + // A staged `klogd` waits for the ask parked, with the wire held; a + // shipping one never parks holding it. + #[cfg(feature = "boot-actuators")] + post_wake(); + let deadline = Deadline::at(crate::clock::now() + LET_GO.duration()); + loop { + let late = deadline.reached(crate::clock::now()); + if let Some(wire) = serial::try_wire() { + if late { + crate::alert!("console: klogd held the wire through the stop's {LET_GO}, and let it go only after"); + } + drain_queue(&wire, usize::MAX, Yield::Never); + return StopWire::Held(wire); + } + if late { + break; + } + watch::wait_uncancellable(parkable, &armed, deadline); + } + crate::alert!( + "console: {} kept the wire through the stop's {LET_GO}; the lines console holders queued are not \ + on it", + serial::wire_holder(), + ); + StopWire::Kept } /// Records and queued lines `klogd` takes per hold of the wire, so a console @@ -140,9 +222,9 @@ fn discard_pending() { } /// At most `budget` records onto the wire the caller holds. Returns how many went. -fn drain_records(wire: &SleepGuard<'_, ()>, budget: u64) -> u64 { +fn drain_records(wire: &SleepGuard<'_, ()>, budget: u64, yields: Yield) -> u64 { let mut cursor = DRAINED.take(); - let mut sink = Wire { wire, records: 0, budget }; + let mut sink = Wire { wire, records: 0, budget, yields }; drain_ordered(&super::shards(), &mut cursor, &mut sink); let records = sink.records; DRAINED.put(&cursor); @@ -257,12 +339,16 @@ pub static SPACE: watch::Watch = watch::Watch::new(); /// with a newline, so a line a holder left unended is not joined to the next. /// A line's pieces go on together, whatever the budget: they are one line, /// and a queue's worth past it at most. Answers whether it freed room. -fn drain_queue(wire: &SleepGuard<'_, ()>, budget: usize) -> bool { +fn drain_queue(wire: &SleepGuard<'_, ()>, budget: usize, yields: Yield) -> bool { let mut line = [0u8; MAX_CONSOLE_LINE + 1]; let mut freed = false; let (mut ended, mut taken) = (0, 0); // A holder that never ends its line gets a queue's worth past the budget. while (ended < budget || MID_LINE.load(Ordering::Relaxed)) && taken < budget.saturating_add(QUEUED_LINES) { + // A line left mid-way is the stop's to end: `MID_LINE` goes with the wire. + if yields == Yield::ToTheStop && HANDOFF.asked() { + break; + } taken += 1; let (len, continues) = { let mut queue = QUEUE.lock(); @@ -360,11 +446,12 @@ struct Wire<'w, 'g> { wire: &'w SleepGuard<'g, ()>, records: u64, budget: u64, + yields: Yield, } impl RecordSink for Wire<'_, '_> { fn put(&mut self, record: &LogRecord) -> bool { - if self.records >= self.budget { + if self.records >= self.budget || (self.yields == Yield::ToTheStop && HANDOFF.asked()) { return false; } end_the_line(self.wire); @@ -412,15 +499,21 @@ extern "C" fn body(_arg: u64) -> ! { let parkable = scheduler::Parkable::at_entry(); let handle = crate::sched::driver::current_handle().expect("klogd runs as a task"); loop { + #[cfg(feature = "boot-actuators")] + staged::hold_if_staged(&parkable, &handle); let freed = if serial::has_console() { // A chunk of each per hold, with interrupts on throughout. let wire = serial::wire(&parkable); - drain_records(&wire, CHUNK); - drain_queue(&wire, CHUNK as usize) + drain_records(&wire, CHUNK, Yield::ToTheStop); + drain_queue(&wire, CHUNK as usize, Yield::ToTheStop) } else { discard_pending(); discard_queue() }; + // With the wire let go of: the read the stop's try pairs with. + if HANDOFF.asked() { + let_go(&parkable, &handle); + } // A holder that found the queue full waits on room; this is the room. if freed { SPACE.post(); @@ -456,6 +549,76 @@ extern "C" fn body(_arg: u64) -> ! { } } +/// `klogd`'s end: the wire is the stop's, and this thread parks for the +/// machine's life, a commit's wake answered by parking again. +fn let_go(parkable: &Parkable, handle: &crate::sched::payload::TaskHandle) -> ! { + // The backlog this leaves reaches the wire at the boot's last word. + crate::log!("console: klogd let the wire go to the stop"); + LET_GO_POSTED.post(); + loop { + let armed = watch::arm(handle.watch(), 0, WaitClass::Other).expect("klogd runs as a task"); + let _ = watch::wait(parkable, &armed, crate::time::Deadline::never()); + } +} + +#[cfg(feature = "boot-actuators")] +pub use staged::hold_the_wire as stage_a_held_wire; + +/// `klogd` holding the wire across the stop, which only an actuator stages. +#[cfg(feature = "boot-actuators")] +mod staged { + use core::sync::atomic::{AtomicBool, Ordering}; + + use kernel::sched::task::WaitClass; + use crate::sched::payload::TaskHandle; + + use crate::drivers::serial; + use crate::scheduler::Parkable; + use crate::time::Deadline; + use crate::watch; + + /// Set by the stop: `klogd` takes the wire at its next pass. + static STAGED: AtomicBool = AtomicBool::new(false); + /// Set by `klogd` once it holds the wire, and posted. + static HOLDING: AtomicBool = AtomicBool::new(false); + static HELD: watch::Watch = watch::Watch::new(); + + /// The stop's, before it takes anything down: `klogd` takes the wire, and + /// this returns once it has. + pub fn hold_the_wire(parkable: &Parkable) { + let armed = watch::arm(&HELD, 0, WaitClass::Other).expect("the stop holds a task"); + STAGED.store(true, Ordering::Release); + super::post_wake(); + // No bound in guest time, which runs on while a host starves the + // guest: the harness's ceiling, scaled by the host, is this wait's. + while !HOLDING.load(Ordering::Acquire) { + watch::wait_uncancellable(parkable, &armed, Deadline::never()); + } + crate::log!("console: klogd holds the wire as the stop begins, staged"); + } + + /// `klogd`'s, at the top of its loop: once staged, it takes the wire and + /// keeps it — until the stop asks for it, then lets it go and goes on as + /// a shipping `klogd` does, or, with `wire-kept-through-the-stop`, for good. + pub fn hold_if_staged(parkable: &Parkable, handle: &TaskHandle) { + if !STAGED.swap(false, Ordering::Acquire) { + return; + } + let wire = serial::wire(parkable); + HOLDING.store(true, Ordering::Release); + HELD.post(); + let kept = crate::actuator::wire_kept_through_the_stop(); + loop { + let armed = watch::arm(handle.watch(), 0, WaitClass::Other).expect("klogd runs as a task"); + if !kept && super::HANDOFF.asked() { + break; + } + let _ = watch::wait(parkable, &armed, Deadline::never()); + } + drop(wire); + } +} + /// Three counters read by `sched::dump`: records drained, records lost, and parks. static RECORDS: AtomicU64 = AtomicU64::new(0); static LOST: AtomicU64 = AtomicU64::new(0); diff --git a/kernel/src/log/handoff.rs b/kernel/src/log/handoff.rs new file mode 100644 index 00000000000..0d06c517190 --- /dev/null +++ b/kernel/src/log/handoff.rs @@ -0,0 +1,46 @@ +//! The stop's claim on the console wire, and `klogd`'s answer to it. +//! +//! The stop [`Handoff::ask`]s and then tries the wire; `klogd` lets the wire go +//! and then reads [`Handoff::asked`], and posts that it let go when it was. +//! Each side's write and its later read are split by a `SeqCst` fence, so at +//! least one of them sees the other's: the stop's try finds the wire free, or +//! `klogd` sees the ask and posts. Without them both can read stale, and the +//! stop waits out its whole budget on a wire nobody holds. +//! Compiled a second time by `kernel-loom`, whose `console_handoff` drives +//! both sides over the real `SleepLock`. + +#[cfg(not(feature = "loom"))] +use core::sync::atomic::{fence, AtomicBool, Ordering}; + +#[cfg(feature = "loom")] +use loom::sync::atomic::{fence, AtomicBool, Ordering}; + +pub struct Handoff { + asked: AtomicBool, +} + +impl Handoff { + /// Must stay `const`: the console's hand-off is a `static`. + #[cfg(not(feature = "loom"))] + pub const fn new() -> Self { + Self { asked: AtomicBool::new(false) } + } + + #[allow(clippy::new_without_default)] + #[cfg(feature = "loom")] + pub fn new() -> Self { + Self { asked: AtomicBool::new(false) } + } + + /// The stop's, once, before it first tries the wire. + pub fn ask(&self) { + self.asked.store(true, Ordering::Relaxed); + fence(Ordering::SeqCst); + } + + /// `klogd`'s, after it let the wire go, and between two writes it makes. + pub fn asked(&self) -> bool { + fence(Ordering::SeqCst); + self.asked.load(Ordering::Relaxed) + } +} diff --git a/kernel/src/log/mod.rs b/kernel/src/log/mod.rs index c2028de61ab..887af5b372f 100644 --- a/kernel/src/log/mod.rs +++ b/kernel/src/log/mod.rs @@ -6,6 +6,7 @@ #![warn(clippy::undocumented_unsafe_blocks)] pub mod console; +mod handoff; pub mod read; pub mod recovery; pub mod registry; diff --git a/kernel/src/power.rs b/kernel/src/power.rs index b0147c70bbf..72dc672ba13 100644 --- a/kernel/src/power.rs +++ b/kernel/src/power.rs @@ -9,17 +9,18 @@ //! it is owed. Resets this kernel does not perform — a TCO or firmware //! watchdog, a triple fault, power loss — are outside it and always will be. //! -//! **Nothing an end says is logged after the console's last drain.** -//! `serial::flush_final` is the log ring's last reader for the console: a -//! record committed past it reaches the wire only if `klogd`, on another CPU, -//! beats the register write. What an end says through the ring it says above -//! the flush (`arch::power::settle`); `arch::power::off` and -//! `arch::power::reset` log nothing, and a panic in either drains for itself. -//! The black box's page is another reader and an earlier one: its tail is -//! sealed before either end is entered (`log::seal_tail`), so what `settle` -//! says is on the console and in no page. +//! **Nothing an end says is logged after the console's last drain.** The +//! stop holds the console's wire (`log::console::StopWire`), which `klogd` +//! let go of for good, and its drain here is the log ring's last reader for +//! the console: a record committed past it reaches no wire. What an end says +//! through the ring it says above the drain (`arch::power::settle`); +//! `arch::power::off` and `arch::power::reset` log nothing, and a panic in +//! either drains for itself. The black box's page is another reader and an +//! earlier one: its tail is sealed before either end is entered +//! (`log::seal_tail`), so what `settle` says is on the console and in no page. -use crate::drivers::{serial, xhci::stop}; +use crate::drivers::xhci::stop; +use crate::log::console::StopWire; /// Whether this machine has a reset this kernel can perform. pub fn can_reboot() -> bool { @@ -32,8 +33,8 @@ pub fn shutdown_refused() -> Option<&'static str> { } /// Return the machine to firmware. -pub fn reboot() -> ! { - serial::flush_final(); +pub fn reboot(wire: StopWire) -> ! { + wire.drain(); // Kernel-internal, so a bug rather than a machine quiesced and then left halted quietly. assert!(can_reboot(), "reboot: no reset, and the caller did not ask can_reboot() first"); reset_now() @@ -42,10 +43,10 @@ pub fn reboot() -> ! { /// Reset the machine and do nothing else. /// /// **[`reboot`] is not reachable from a wedge**, which is why this exists -/// beside it: that path opens with `serial::flush_final`, and a `BackendGuard` -/// masks interrupts for its whole life — so a CPU stuck inside one holds what -/// the call would wait for, on exactly the boots `crate::deadline` exists for. -/// This takes no lock. +/// beside it: that path is the stop's, which waits on `klogd` and the +/// console's registers, and a `BackendGuard` masks interrupts for its whole +/// life — so a CPU stuck inside one holds what the stop would wait for, on +/// exactly the boots `crate::deadline` exists for. This takes no lock. /// /// A machine with no reset halts here rather than returning: the caller has /// already sealed why, and holding is what such a machine has always done. @@ -63,11 +64,11 @@ pub fn reset_now() -> ! { } /// Power the machine off. The caller asked [`shutdown_refused`] first. -pub fn shutdown(stopping: crate::quiesce::Stopping) -> ! { - // Above the flush, because it logs. +pub fn shutdown(stopping: crate::quiesce::Stopping, wire: StopWire) -> ! { + // Above the drain, because it logs. let settled = crate::arch::power::settle(stopping); // Nothing drains the log ring after this point, and nothing below logs. - serial::flush_final(); + wire.drain(); // A power-off takes VBUS with it on a machine whose ports are not // always-on and takes nothing on one whose are, so the devices are handed // back here for the same reason as at a reboot. diff --git a/kernel/src/syscall/machine.rs b/kernel/src/syscall/machine.rs index e18c15ef275..3b41eb4f4bf 100644 --- a/kernel/src/syscall/machine.rs +++ b/kernel/src/syscall/machine.rs @@ -7,6 +7,7 @@ use alloc::vec::Vec; +use crate::log::console::StopWire; use crate::power; use crate::user_ptr::{SyscallContext, UserBytesMut}; use crate::UserAddr; @@ -66,7 +67,7 @@ fn read_on_cursor( } } -fn quiesce(last: &str) -> Result { +fn quiesce(last: &str) -> Result<(crate::quiesce::Stopping, StopWire), SyscallError> { // Refused by name, and first: nothing below runs twice. if !crate::quiesce::claim_the_shutdown() { log!("power: this machine is already stopping, so this caller stops with the rest"); @@ -86,15 +87,24 @@ fn quiesce(last: &str) -> Result { if crate::actuator::usb_reset_under_load() { crate::usb_gate::sweep_under_load(); } + let parkable = crate::scheduler::Parkable::at_entry(); + // The console's writer holding the wire as the stop begins, which a + // shipping `klogd` does at any moment. + #[cfg(feature = "boot-actuators")] + if crate::actuator::wire_held_across_the_stop() { + crate::log::console::stage_a_held_wire(&parkable); + } // First: what follows outlasts a feed cadence, and no pass runs to feed again. crate::arch::watchdog::disarm(); // Every userland thread stops here, the log's writer with the rest: // `/system/bin/supervisor` had it flush before it asked for this stop. let (stopped, stopping) = crate::quiesce::stop(); - crate::log::console::drain_for_the_stop(); // From here on nothing carries a record to a file: the seal below takes // every one stamped after this one, the newest the stop found. let stop_began = crate::log::read::newest_committed(); + // Held to the machine's end: every record below reaches the wire before a + // CPU is taken down, whoever was writing it when the stop began. + let wire = crate::log::console::take_for_the_stop(&parkable); // The machine's census, which no process's start or end takes. crate::census::log(); #[cfg(feature = "mask-windows")] @@ -113,7 +123,7 @@ fn quiesce(last: &str) -> Result { log!("{last}"); // Order is load-bearing: the console drain, the seal, then the caller's // non-returning call. - crate::log::console::drain_inline(); + wire.drain(); // The next boot's loader reads this page to learn how the last one ended, // and a machine that was asked to stop is the one answer that is not a // death. Without it the loader would find the loader's own `ARMED` and @@ -134,7 +144,7 @@ fn quiesce(last: &str) -> Result { // `power::reboot`/`power::shutdown` do — which every reset this kernel // performs goes through. It is bounded, and the reset follows either way. crate::drivers::xhci::seal_shut(); - Ok(stopping) + Ok((stopping, wire)) } /// Powers the machine off; requires a `SysCap` carrying [`Rights::POWER`]. Returns only when refused. @@ -148,7 +158,7 @@ pub(super) fn sys_shutdown(syscap: RawHandle) -> u64 { return SyscallError::NotSupported.to_u64(); } match quiesce("Shutting down.") { - Ok(stopping) => power::shutdown(stopping), + Ok((stopping, wire)) => power::shutdown(stopping, wire), Err(e) => e.to_u64(), } } @@ -163,10 +173,10 @@ pub(super) fn sys_reboot(syscap: RawHandle) -> u64 { log!("reboot: this machine has no reset this kernel performs — refused"); return SyscallError::NotSupported.to_u64(); } - if let Err(e) = quiesce("Rebooting.") { - return e.to_u64(); + match quiesce("Rebooting.") { + Ok((_, wire)) => power::reboot(wire), + Err(e) => e.to_u64(), } - power::reboot(); } /// The most live threads `SYS_SYSINFO` will describe; kept under `mm::MAX_HEAP_ALLOC` so an unbounded thread count cannot trip the allocator's fail-fast assert. diff --git a/tests/common/power.rs b/tests/common/power.rs index 5728053528c..782212d1355 100644 --- a/tests/common/power.rs +++ b/tests/common/power.rs @@ -74,6 +74,79 @@ pub fn machine_shutdown(test_config: &Path) -> Result<(), String> { Ok(()) } +/// What the stop alerts where `klogd` kept the console's wire through the +/// stop's whole budget, in `kernel/src/log/console.rs`. +const WIRE_KEPT: &str = "kept the wire through the stop's"; + +/// What both of the stop's alerts say where `klogd` let the wire go only past +/// the stop's budget or not at all, in `kernel/src/log/console.rs`. +pub const WIRE_LATE: &str = "the wire through the stop's"; + +/// What a stop staged by `wire-held-across-the-stop` logs once `klogd` holds +/// the console's wire, in `kernel/src/log/console.rs`. +const WIRE_HELD: &str = "console: klogd holds the wire as the stop begins, staged"; + +/// What `klogd` logs as it lets the console's wire go to the stop, in +/// `kernel/src/log/console.rs`. +const WIRE_LET_GO: &str = "console: klogd let the wire go to the stop"; + +/// The actuators that stage `klogd` holding the wire across the stop: until +/// the stop asks for it, or, `kept`, for good. +pub fn wire_staged(kept: bool) -> &'static [&'static str] { + if kept { &["wire-kept-through-the-stop"] } else { &["wire-held-across-the-stop"] } +} + +/// A stop that found `klogd` holding the console's wire, judged on the whole +/// `console` of a boot that ended with the `last` word: the staged hold, the +/// stop's record and the last word are all on it, in that order; where `klogd` +/// `kept` the wire the stop said so between the hold and the record, and +/// where it did not `klogd` said it let the wire go there and the console is +/// otherwise clean. +pub fn judge_the_held_wire(console: &str, last: &str, kept: bool) -> Result<(), String> { + let lines: Vec<&str> = console.lines().collect(); + let at = |what: &str| lines.iter().position(|l| l.contains(what)); + let held = at(WIRE_HELD).ok_or_else(|| format!("the staged klogd never said it held the wire\n{console}"))?; + let record = lines + .iter() + .position(|l| toyos_quiesce::Record::parse(l).is_some()) + .ok_or_else(|| format!("the stop's record is not on the console\n{console}"))?; + let said = at(last).ok_or_else(|| format!("{last:?} is not on the console\n{console}"))?; + if !(held < record && record < said) { + return Err(format!("the hold, the stop's record and {last:?} are on lines {held}, {record} and {said}\n{console}")); + } + match (kept, at(WIRE_KEPT), at(WIRE_LET_GO)) { + (true, Some(alert), None) if held < alert && alert < record => Ok(()), + (false, None, Some(let_go)) if held < let_go && let_go < record => { + serial::Serial::named("the stop", console.to_string()).must_be_clean() + } + (_, alert, let_go) => Err(format!( + "klogd {} the wire, and the stop's alert is on line {alert:?} and klogd's let-go on line {let_go:?}\n{console}", + if kept { "kept" } else { "was asked for" }, + )), + } +} + +/// `klogd` holds the console's wire as the stop begins, on one CPU, where it +/// runs only when the stop gives the CPU back: the machine powers off with the +/// stop's record and its last word on the console. `kept`, `klogd` keeps the +/// wire through the stop's whole budget, and the stop says so and writes +/// over it. +pub fn machine_shutdown_wire_held(test_config: &Path, kept: bool) -> Result<(), String> { + let options = BootOptions { qmp: true, smp: 1, kernel_params: wire_staged(kept), ..Default::default() }; + let mut qemu = QemuInstance::boot_with_options(test_config, &[], &[], options); + let boot = serial::Serial::boot(&qemu); + boot.must_be_clean()?; + let mut console = boot.text().to_string(); + qemu::await_marker(&mut qemu, &mut console, Q35_S5_SUPPLIED, "the ACPI server to hand the kernel \\_S5")?; + let mut stop = qemu::QmpShutdown::open(qemu.qmp_socket(), qemu.budget(qemu::GUEST_QUIET)); + writeln!(qemu.stdin_mut(), "run shutdown").expect("write to QEMU stdin"); + qemu.flush_stdin(); + ended(&mut qemu, &mut stop, &mut console, SHUTTING_DOWN, "guest-shutdown")?; + judge_the_held_wire(&console, SHUTTING_DOWN, kept)?; + eprintln!(" [power] klogd held the wire across the stop{}; the record and the last word reached it", if kept { " and kept it" } else { "" }); + Ok(()) +} + /// A stop that ends with a userland thread still running is followed by a /// power-off all the same, with the sleep type `acpiserver` handed the /// kernel: q35 hands over in ACPI mode, so the power-off diff --git a/tests/common/serial.rs b/tests/common/serial.rs index 82b68fc8426..cd587c8bce1 100644 --- a/tests/common/serial.rs +++ b/tests/common/serial.rs @@ -354,4 +354,7 @@ const NEVER_CLEAN: &[&str] = &[ // descriptors are wrong, and a netstack that did it on every boot would // otherwise pass everywhere. "iommu: DMA FAULT owner=slot", + // kernel/src/log/console.rs — the stop waited out its whole budget for + // `klogd` to let the console's wire go. + super::power::WIRE_LATE, ]; diff --git a/tests/toyos.rs b/tests/toyos.rs index b9e778df55c..21f37a468fe 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -253,6 +253,8 @@ const SCREEN_TESTS: &[(&str, qemu::Profile)] = &[ ("virt_reboot", qemu::Profile::VirtEl2), ("virt_off_names_the_cpus_left_on", qemu::Profile::VirtEl2), ("virt_reboot_refused_without_psci", qemu::Profile::VirtEl2), + ("virt_reboot_wire_held", qemu::Profile::VirtEl2), + ("virt_reboot_wire_kept", qemu::Profile::VirtEl2), ]; /// The tests whose machine shape *is* the test, each on a boot of its own. @@ -301,6 +303,12 @@ const MACHINE_TESTS: &[&str] = &[ // ends the machine, so only one QEMU reports stopping can be asked, and // the T14 hands over in legacy mode, where no holder means no quieting. "machine_shutdown_short_stop", + // The power-off with `klogd` holding the console's wire as the stop + // begins, on one CPU: a staged hold of a kernel thread, read off a console + // QEMU keeps past the power-off, and the T14 is never asked to power off. + "machine_shutdown_wire_held", + // The same with `klogd` keeping the wire through the stop's budget. + "machine_shutdown_wire_kept", // A claimable function with a mappable BAR that no program of the boot // holds: QEMU's virtio NIC on `tests/testcases`. The T14's one such // function is its I219, and a kernel that dies on this takes the bench's @@ -2138,8 +2146,10 @@ fn virt_failed_ap_leaves_no_hole(profile: qemu::Profile) -> Result<(), String> { /// `tests/virtrebootcase`'s one job asks for a reboot: the boot's last word is /// `Rebooting.`, QEMU stops for `guest-reset`, and its trace of PSCI holds one -/// `SYSTEM_RESET` and neither `CPU_OFF` nor `SYSTEM_OFF`. -fn virt_reboot(profile: qemu::Profile) -> Result<(), String> { +/// `SYSTEM_RESET` and neither `CPU_OFF` nor `SYSTEM_OFF`. With `staged` +/// actuators `klogd` holds the console's wire as the stop begins, judged by +/// [`power::judge_the_held_wire`]. +fn virt_reboot(profile: qemu::Profile, staged: &'static [&'static str]) -> Result<(), String> { let config = compile::repo_root().join("tests/virtrebootcase/system.toml"); let case = config.parent().expect("system.toml has a directory"); let trace = common::lane::dir().join("virt_reboot.psci"); @@ -2151,6 +2161,7 @@ fn virt_reboot(profile: qemu::Profile) -> Result<(), String> { profile, qmp: true, psci_trace: Some(trace.clone()), + kernel_params: staged, ready_marker: "control registers: SCTLR_EL1=", ..Default::default() }, @@ -2171,6 +2182,9 @@ fn virt_reboot(profile: qemu::Profile) -> Result<(), String> { if asked != [PSCI_SYSTEM_RESET] { return Err(format!("QEMU traced {asked:x?} of CPU_OFF, SYSTEM_OFF and SYSTEM_RESET, not one SYSTEM_RESET")); } + if !staged.is_empty() { + power::judge_the_held_wire(&console, bootlog::REBOOTING, staged == power::wire_staged(true))?; + } eprintln!(" [virt] Rebooting., then one SYSTEM_RESET, and QEMU stopped for guest-reset"); Ok(()) } @@ -2633,7 +2647,11 @@ fn run_screen_test(name: &str, profile: qemu::Profile, test_config: &Path) -> Re "virt_el1_smp" => virt_smp(profile, "HVC", 1), "virt_failed_ap_leaves_no_hole" => virt_failed_ap_leaves_no_hole(profile), "virt_fatal_halts_the_others_first" => virt_fatal_halts_the_others_first(profile), - "virt_reboot" => virt_reboot(profile), + "virt_reboot" => virt_reboot(profile, &[]), + // The reboot with `klogd` holding the PL011's wire as the stop begins, + // then keeping it through the stop's budget. + "virt_reboot_wire_held" => virt_reboot(profile, power::wire_staged(false)), + "virt_reboot_wire_kept" => virt_reboot(profile, power::wire_staged(true)), "virt_off_names_the_cpus_left_on" => virt_off_names_the_cpus_left_on(profile), "virt_reboot_refused_without_psci" => virt_reboot_refused_without_psci(profile), "screen_fatal_behind_a_painter" => { @@ -3099,6 +3117,8 @@ fn run_machine_test(name: &str, test_config: &Path) -> Result<(), String> { "acpi_lock_given_back_on_one_cpu" => acpi_mediated_access(1), "acpi_supply_outlives_holder" => acpi_supply_outlives_holder(), "machine_shutdown_short_stop" => power::machine_shutdown_short_stop(test_config), + "machine_shutdown_wire_held" => power::machine_shutdown_wire_held(test_config, false), + "machine_shutdown_wire_kept" => power::machine_shutdown_wire_held(test_config, true), "bar_map_again" => bar_map_again(test_config), "console_image_boots" => console_image_boots(), "nvme_disk_keeps_log_and_home" => nvme_disk_keeps_log_and_home(test_config), From 241832e01ceeacd33f23682654ed1b74e523b88c Mon Sep 17 00:00:00 2001 From: japabu Date: Fri, 9 Oct 2026 16:54:36 +0200 Subject: [PATCH 2/5] The stop survives any holder of the wire, writes over a kept one from its own cursor, and a staging reds main through its last drain Answers the first review of #805. - Every holder that lets the wire go once the stop asked posts the stop (`let_wire_go`), and the stop always wakes `klogd`: a shipping and an actuator kernel take the same path, and a holder other than `klogd` (`drain_inline` at a backend's arrival) releases into the same store-buffering pair the loom model checks. - `StopWire::Kept` owns the cursor the stop took once and never publishes, so a `klogd` preempted inside `drain_records` cannot put a stale position back under the stop and have its records written twice after the last word. - The staged hold parks inside `body`'s own hold of the wire: the release under test is `body`'s, with no gap for the stop's try to take the wire in. - `wire-held-at-the-last-word` stages `klogd` inside its hold from the boot's last word until after `xhci::seal_shut`, where the stop does not hold the wire itself; `machine_shutdown_wire_at_the_seal` judges it on one CPU. On main's stop it reds through `serial::flush_final` expiring after the seal, the defect the closed issue names. - The staging says `klogd`'s scheduler state and the stop's CPU's run queue `DEAF_CPU` into its wait, and every staged test reds on that line. - `SleepLock::holder_name` names a holder, a context with no task, a contender whose turn came and has not taken it, or nobody; `try_wire` answers it on a refusal and `serial::wire_holder` is gone. - The tracker: main's record of this defect is folded into `issues/a-woken-klogd-can-wait-seconds-on-an-idle-cpu-under-hvf.md`, which keeps the virt stop tests emulated, and the one-CPU TCG staging red has its own defect, `issues/a-staged-klogd-went-unrun-for-five-seconds-on-a-one-cpu-guest.md`. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_017cSFvbD35xJ2kGANVdm23C --- ...-under-host-load-can-go-silent-for-15-s.md | 39 +-- ...run-for-five-seconds-on-a-one-cpu-guest.md | 40 +++ ...n-wait-seconds-on-an-idle-cpu-under-hvf.md | 111 +++++---- ...s-the-console-when-klogd-holds-the-wire.md | 84 ------- issues/toyos-runs-on-arm64.md | 4 +- kernel/loom/tests/console_handoff.rs | 10 +- kernel/src/actuator.rs | 5 + kernel/src/drivers/serial.rs | 44 ++-- kernel/src/log/console.rs | 229 +++++++++++++----- kernel/src/log/handoff.rs | 12 +- kernel/src/power.rs | 10 +- kernel/src/sched/driver.rs | 12 + kernel/src/sleeplock.rs | 29 ++- kernel/src/syscall/machine.rs | 14 +- tests/common/power.rs | 54 ++++- tests/toyos.rs | 13 +- 16 files changed, 432 insertions(+), 278 deletions(-) create mode 100644 issues/a-staged-klogd-went-unrun-for-five-seconds-on-a-one-cpu-guest.md delete mode 100644 issues/the-boots-last-word-can-miss-the-console-when-klogd-holds-the-wire.md diff --git a/issues/a-counters-read-under-host-load-can-go-silent-for-15-s.md b/issues/a-counters-read-under-host-load-can-go-silent-for-15-s.md index 98081336f78..656805437cc 100644 --- a/issues/a-counters-read-under-host-load-can-go-silent-for-15-s.md +++ b/issues/a-counters-read-under-host-load-can-go-silent-for-15-s.md @@ -136,25 +136,26 @@ the step each stopped in is not read from it: 77 (38 s, with ceilings paid at 8.00x and 31 s between its image and its first guest line) and 75 to 67 (7 s). -**What a last-word stall of `virt_mask_windows` can be, measured.** Under -HVF, on the entropy stage's branch at `863d73ed3` with a probe on the stop's -two drains, `virt_mask_windows` stalled with the same line, `STALLED: waiting -for the boot's last word — it went quiet`, and the guest had not gone quiet -but off: the last word's drain found the console wire free with one ticket -outstanding (`ticket=197 now=196`), its turn posted to `klogd` and never -taken, and `serial::flush_final` spun 2.95 s on it, gave up and the machine -powered off with its last records on no console. A red `virt_el1_smp`, probed -before the ticket was, found the holder word free and spun 4.16 s; 2 reds in -21 runs of the five SMP tests side by side, load 23 -to 52. That is fixed by the change that deleted `flush_final`: the stop takes -the wire from `klogd` for good and parks while it waits, bounded by -`log::console::LET_GO`, past which it says so and writes over the holder. -What links the two stalls without a console above to it: the same test, the -same wait, ended by the same bound, on a boot whose last word went through -that drain. What does not: they ran under TCG, where the entropy stage saw 0 -of 50 emulated runs stall, and nothing of theirs names the wire, so neither -is shown to be it. The occurrences that stall at a job's end are not this: -they stop before the stop begins. +The fifth and sixth silent ones, two guests of one run: `virt_smp` and +`virt_mask_windows`, in the whole suite on `wt/toyos-lastword` at +`aa7448db0`, whose diff changes the stop's hold of the console wire and +nothing these guests run before the stop begins. + +- **The lines.** `FAIL virt_smp: STALLED: waiting for the job + test_rs_counters_read to end — it went quiet` and `FAIL virt_mask_windows: + STALLED: waiting for the boot's last word — it went quiet`, three seconds + apart on the host's clock; 44 of 46 passed. +- **The load.** 12 wide on the 14-core host, 1-minute load 35.09 when the + run began and 79.44 when it ended; liveness ceilings paid at 1.00x; + workers 346 s building against 752 s testing. +- **The same profile as the second.** `virt_smp`'s last three lines are + `===TEST_END unmap_touch exit=0===` at 11.730, `===TEST_START + test_rs_counters_read===` at 11.731 and the kernel's `spawn: + /system/bin/test_rs_counters_read pid=13` at 11.739 on cpu4. + `virt_mask_windows` said nothing while its second wait ran, as the two + stalls below did; the run kept no PL011 log of it. +- **What is known.** The next whole suite at that commit, at load 79.44 + rising to 78.28, passed 46 of 46. Not known of any of them: whether the fork compiler's fault reaches `test_rs_counters_read` or the kernel under it. diff --git a/issues/a-staged-klogd-went-unrun-for-five-seconds-on-a-one-cpu-guest.md b/issues/a-staged-klogd-went-unrun-for-five-seconds-on-a-one-cpu-guest.md new file mode 100644 index 00000000000..10d73d73c18 --- /dev/null +++ b/issues/a-staged-klogd-went-unrun-for-five-seconds-on-a-one-cpu-guest.md @@ -0,0 +1,40 @@ +--- +status: open +kind: defect +opened: 2026-10-09 +--- + +# A staged `klogd` went unrun for five seconds on a one-CPU guest + +On one CPU, the stop parked and woke `klogd`, and `klogd` did not run for 5 s +of guest time. The stop's hand-off of the console's wire rests on the +opposite (`log::console::take_for_the_stop`): parked, the stop leaves its own +CPU to `klogd`. + +**Measured once.** `machine_shutdown_wire_held` (q35, one CPU, x86-64 under +TCG on an Apple-silicon host of 14 cores), in the whole guest suite at +`c2a4542f0`, 1-minute load 21.53 when the suite began and 36.77 when it +ended. The staging's wait for `klogd` to take the wire, then bounded at 5 s +of guest time, panicked at guest 12.437 s, `the staged klogd never took the +wire`, 27 s of wall clock into a test that passes in about 7. Its console +was virtio-console's, which the harness keeps no copy of, so it does not +say whether `klogd` ran. Eighteen whole suites after +it, at load 18 to 67, did not repeat it. + +**Who could run instead.** Only the stop was parked; `klogd` had been +woken, and userland was still live, since the staging runs before the stop +stops it. So userland holding the CPU is a cause as open as a lost wake or +a host that starved the guest. + +**The capture.** The staging (`log::console::staged`) no longer has a bound +in guest time; `DEAF_CPU` into its wait it logs `klogd`'s scheduler state, +the stop's CPU, what that CPU runs and every task on its run queue, and goes +on waiting. Every staged test reds on that line +(`tests/common/power.rs`, `STAGED_KLOGD_UNRUN`), so a repeat is a red with +its capture, not a stall. + +**Exit**: the cause named from that capture, and fixed; then +`machine_shutdown_wire_held` passes 200 side-by-side runs at 1-minute load +30 or more. + +Owner: the orchestrator. diff --git a/issues/a-woken-klogd-can-wait-seconds-on-an-idle-cpu-under-hvf.md b/issues/a-woken-klogd-can-wait-seconds-on-an-idle-cpu-under-hvf.md index 7be3385edae..42f37d16752 100644 --- a/issues/a-woken-klogd-can-wait-seconds-on-an-idle-cpu-under-hvf.md +++ b/issues/a-woken-klogd-can-wait-seconds-on-an-idle-cpu-under-hvf.md @@ -4,51 +4,66 @@ kind: defect opened: 2026-10-09 --- -# A woken `klogd` can wait five seconds on an idle CPU under HVF - -A wake that makes `klogd` runnable on an idle AArch64 CPU under HVF can leave -it undispatched until something else wakes that CPU. - -**Measured.** `virt_reboot_wire_kept` on `Profile::Virt` (HVF, two CPUs), -the entropy stage's branch at `863d73ed3` with this fix applied, an -Apple-silicon host of 14 cores, 1-minute load 16 at the one reading taken: -the stop sets the -staging's flag and `post_wake`s `klogd` at guest 1.574 s, and `klogd`'s next -loop top is at 6.579 s, on cpu1, as each of its six tops that boot was. The -stop, on cpu0, was parked on the staging's watch the whole time. `klogd` ran -5 ms after the stop's deadline, when a probe on that path had kicked every -CPU. The staging's wait timed out in 6 of 10 runs of that test, and in none -of 4 of `virt_reboot_wire_held`, whose staging is the same code to that -point. The probe is a patch on the pull request that deleted -`serial::flush_final`. - -The same shape, read off the probe on that branch's own kernel: a stop that -let the console wire go to a queued `klogd` found its turn posted and still -not taken 2.95 s later, on an 8-CPU guest -(`issues/a-counters-read-under-host-load-can-go-silent-for-15-s.md`). - -One occurrence that may be it, on x86-64: `machine_shutdown_wire_held` (q35, -one CPU, TCG) in the whole suite at `c2a4542f0`, 1-minute load 21.53 when the -suite began and 36.77 when it ended, on the same host: the staging's wait, -then bounded at 5 s of guest time, panicked, `the staged klogd never took the -wire`, 27 s of wall clock into a test that passes in about 7. Its console was -virtio-console's, which the harness keeps no copy of, so it does not say -whether `klogd` ran or the host starved the guest. Eighteen whole suites after -it with a probe on that wait, at load 18 to 67, did not repeat it. The -staging's wait now has no bound in guest time, so a repeat is a stall the -harness's ceiling names. - -**What it costs now.** The stop waits `log::console::LET_GO` for `klogd`, -then alerts and writes over it; nothing is lost. A program woken the same -way waits the same. - -**Not known.** Whether the wake reached cpu1 at all, whether cpu1's sleep -handshake missed it, or whether HVF delivered the kick late; no register -capture of cpu1 exists. Whether TCG or x86-64 can do the same: the staged -tests run under TCG (`Profile::VirtEl2`) and on q35, and have not. - -**Exit**: the cause named from a capture of the idle CPU, and fixed; -`virt_reboot_wire_kept` and `virt_reboot_wire_held` move to `Profile::Virt` -and pass 100 runs each under HVF with no staging timeout. - -Owner: the orchestrator. +# A woken `klogd` can wait seconds on an idle CPU under HVF + +A wake that makes `klogd` runnable on an AArch64 CPU under HVF can leave it +undispatched for seconds, until something else wakes that CPU. + +**What it cost before the stop held the wire.** A boot asked to stop could +power off without `Shutting down.` on its console. The last word's drain +declined a held wire, and `serial::flush_final` spun on it and gave up. +Measured on 8-CPU `virt` guests under `Profile::Virt`, an Apple-silicon host +of 14 cores, QEMU 11.1.1: + +- On the entropy stage's branch at `7522ec61e`, load 28 to 46: + `virt_el1_smp`, `virt_mask_windows` and `virt_off_names_the_cpus_left_on` + side by side with `virt_smp` and `virt_failed_ap_leaves_no_hole`, 131 + runs, five reds, each `STALLED: waiting for the boot's last word`; a + sixth in a whole suite at load 41 to 47. Emulated at EL1 the same session, + 50 runs, no red. One red's PSCI trace held seven `CPU_OFF` and one + `SYSTEM_OFF`, and its console stopped with `klogd` about 100 ms of guest + clock behind the stop. The probe is `debug-shutdown-regs.patch` in + https://github.com/ToyOSOrg/ToyOS/pull/802#issuecomment-6080912601. +- At `863d73ed3`, with a probe on the stop's two drains (on + https://github.com/ToyOSOrg/ToyOS/pull/805), 2 reds in 21 runs of the same + five, load 23 to 52. A red `virt_mask_windows`: at the decline the wire + was free with one ticket outstanding (`ticket=197 now=196`), its turn + posted to `klogd` and not taken, and the same 2.95 s later when + `flush_final` gave up. A red `virt_el1_smp`: the wire free, `flush_final` + spent 4.16 s. + +**The dispatch delay itself.** `virt_reboot_wire_kept` on `Profile::Virt` +(two CPUs), at `863d73ed3` with the stop holding the wire, load 16: the +stop `post_wake`s `klogd` at guest 1.574 s, and `klogd`'s next loop top is at +6.579 s, on cpu1, where each of its tops that boot ran. The stop, on cpu0, +was parked the whole time. `klogd` ran 5 ms after the stop's deadline, when +a probe on that path kicked every CPU. That staging's wait timed out in 6 of +10 runs of that test. + +**What it costs now.** The stop holds the console's wire from right after it +stops userland to the machine's end (`log::console::take_for_the_stop`), so +no record waits on `klogd` past it. A `klogd` not dispatched when the stop +asks costs the stop `log::console::LET_GO`, 5 s, and an alert, which reds +every test (`tests/common/serial.rs`, `NEVER_CLEAN`); where it never lets +go, the lines console holders had queued are not on the console, which the +alert says. + +**Until it is fixed** these stay emulated (`tests/toyos.rs`): +`virt_mask_windows`, `virt_off_names_the_cpus_left_on`, `virt_reboot`, +`virt_reboot_wire_held` and `virt_reboot_wire_kept` at EL2, and +`virt_el1_smp` on `Profile::VirtTcg`. + +**Not known.** Whether the wake reached the idle CPU, whether its sleep +handshake missed it, or whether HVF delivered the kick late: no register +capture of the idle CPU exists. + +**Exit**: the cause named from a capture of the idle CPU, and fixed; then +`virt_el1_smp`, `virt_mask_windows`, `virt_off_names_the_cpus_left_on`, +`virt_reboot` and the two `virt_reboot_wire_` tests under `Profile::Virt` on +an Apple host, 300 side-by-side runs at load 30 or more with no red, the +harness's PSCI trace allowed under HVF; they then move to `Profile::Virt`, +`virt_reboot` keeping an EL2 row of its own for `SYSTEM_RESET` through the +SMC conduit, and `Profile::VirtTcg` is deleted. + +Owner: the kernel's AArch64 bring-up, `issues/toyos-runs-on-arm64.md`, held +by the orchestrator's next kernel worker. diff --git a/issues/the-boots-last-word-can-miss-the-console-when-klogd-holds-the-wire.md b/issues/the-boots-last-word-can-miss-the-console-when-klogd-holds-the-wire.md deleted file mode 100644 index d5f35cb8adb..00000000000 --- a/issues/the-boots-last-word-can-miss-the-console-when-klogd-holds-the-wire.md +++ /dev/null @@ -1,84 +0,0 @@ ---- -status: open -kind: defect -opened: 2026-10-09 ---- - -# The boot's last word can miss the console: the stop's drain declines while `klogd` holds the wire - -A boot that was asked to stop can power off without `Shutting down.` on its -console. Seen on 8-CPU `virt` guests under HVF, six times, each a test red as -`STALLED: waiting for the boot's last word — it went quiet`: the guest was not -quiet but gone. - -**What the code does, by reading.** `quiesce` (`kernel/src/syscall/machine.rs`) -logs the last word and calls `log::console::drain_inline`, which takes the -wire with `serial::try_wire` and returns at once where it is held: "whoever -holds the wire drains it too". The holder is `klogd`, on another CPU, part-way -through its backlog. Nothing waits for it. The caller goes on to the power-off -or the reset, which turns `klogd`'s CPU off before it reaches the record. The -stop's record and the census, logged above the last word, go the same way. - -**What was measured.** The entropy stage's branch at `7522ec61e`, an -Apple-silicon host of 14 cores at 1-minute load 28 to 46, QEMU 11.1.1, -`tests/virtsmpcase` on eight CPUs under `Profile::Virt` (HVF), whose first job -`unmap_touch` has the kernel report eight faults, each at length: - -- `virt_el1_smp`, `virt_mask_windows` and `virt_off_names_the_cpus_left_on` - each wait for the last word. Side by side with `virt_smp` and - `virt_failed_ap_leaves_no_hole`, 131 runs: five reds, two of `virt_el1_smp`, - two of `virt_mask_windows`, one of `virt_off_names_the_cpus_left_on`. A - sixth, `virt_el1_smp`, in the whole suite at load 41 to 47. -- The same five tests with `Profile::Virt` emulated at EL1 (`-cpu max`), the - same session: 50 runs, no red. Five in 393 guests against none in 150 does - not separate the two by itself (Fisher's exact test, p = 0.33): the place - the reds stop in does. -- One red `virt_el1_smp`, captured: QEMU's `arm_psci_call` trace holds seven - `CPU_OFF` and one `SYSTEM_OFF`, so the kernel powered the machine off. Its - console's last line is the supervisor's `power: the machine stops, and - logkeeper makes the log whole first (Shutdown)`, stamped 2.361, in among - the kernel's fault-report records stamped 2.264: `klogd` was about 100 ms - of guest clock behind when the stop began. No stop record, no census, no - `Shutting down.`. -- The red `virt_off_names_the_cpus_left_on` said, after the wait began, - `power: cpu6 is not off by PSCI's answer inside the budget; SYSTEM_OFF - regardless` and the same of cpu7, which `arch::power::off` writes straight - to the UART after `quiesce` has returned, and no `Shutting down.`. - -The probe that captured it is `debug-shutdown-regs.patch` in -https://github.com/ToyOSOrg/ToyOS/pull/802#issuecomment-6080912601. - -**Not the counters-read silences.** The third and fourth silent guests of -`issues/a-counters-read-under-host-load-can-go-silent-for-15-s.md` stop at -another step: each console ends at the kernel's `spawn:` record of -`test_rs_counters_read`, with no `===TEST_END test_rs_counters_read` and no -supervisor stop line. In this defect's capture every userland line through -`power: the machine stops …` reached the wire, as `drain_for_the_stop` waits -for the wire and drains the queue; only the kernel's own records after it -went missing. The two `virt_mask_windows` stalls that issue records with no -console, and no PSCI trace, are not decidable either way. What tells the -next capture's silence apart: whether `===TEST_END test_rs_counters_read` -and the supervisor's stop line are on its console, and QEMU's PSCI trace of -it, a powered-off guest's `CPU_OFF` and `SYSTEM_OFF` being this defect's. - -**Not known.** Whether the wire's holder was `klogd`: no capture names it. -Whether an x86-64 guest with a 16550 loses its last word the same way. -Whether `virt_reboot`, which waits for `Rebooting.` through the same -`quiesce`, loses it under HVF: it was moved there and back unmeasured. - -**Until it is fixed** these stay emulated (`tests/toyos.rs`): the three -tests above, and `virt_reboot`; `Profile::VirtTcg` stays for -`virt_el1_smp`. - -**Exit**: the stop puts its last word on the wire before it takes a CPU down, -waiting for the wire's holder as `drain_for_the_stop` does, or the cause is -shown to be another from a capture. It is shown by a test that reds without -the fix on every boot, the wire held across the stop by an actuator, and by -the four tests under `Profile::Virt` on an Apple host: 300 side-by-side -runs at load 30 or more with no red, the harness's PSCI trace allowed under -HVF as the probe allowed it. They then move to `Profile::Virt`, -`virt_reboot` with an EL2 row of its own kept for `SYSTEM_RESET` through -the SMC conduit, and `Profile::VirtTcg` is deleted. - -Owner: the kernel's AArch64 bring-up, `issues/toyos-runs-on-arm64.md`, held -by the orchestrator's next kernel worker. diff --git a/issues/toyos-runs-on-arm64.md b/issues/toyos-runs-on-arm64.md index 6f98b613235..10dd0b735c1 100644 --- a/issues/toyos-runs-on-arm64.md +++ b/issues/toyos-runs-on-arm64.md @@ -294,8 +294,8 @@ Each stage names its exit; "measured" means a number from a run. answers from a virtio-rng (`kernel/src/random.rs`); `virt_el2_drop`, `virt_smp` and `virt_jobs_at_el2`, one boot of the job case with the timer and FP jobs in it, stay emulated at EL2, which HVF gives no guest, and - `virt_reboot` and three more stay emulated at EL2 until - `issues/the-boots-last-word-can-miss-the-console-when-klogd-holds-the-wire.md` + `virt_reboot` and five more stay emulated until + `issues/a-woken-klogd-can-wait-seconds-on-an-idle-cpu-under-hvf.md` is fixed. Each judges an event, never a rate: no QEMU test measures time. **Accepted with the move to HVF:** `virt_user_mode`, `virt_irq_storm`, `virt_timer_floor`, `virt_failed_ap_leaves_no_hole` and diff --git a/kernel/loom/tests/console_handoff.rs b/kernel/loom/tests/console_handoff.rs index ba4261b6360..c48479b8f7f 100644 --- a/kernel/loom/tests/console_handoff.rs +++ b/kernel/loom/tests/console_handoff.rs @@ -1,10 +1,10 @@ -//! Loom: the stop's claim on the console wire against `klogd`'s letting go +//! Loom: the stop's claim on the console wire against a holder's letting go //! (`kernel/src/log/handoff.rs`), over the real `SleepLock`. //! -//! `klogd` holds the wire, lets it go, and reads whether the stop asked; the -//! stop asks, and tries the wire. One of them must see the other: the stop's -//! try finds the wire free, or `klogd` sees the ask, and so posts the let-go -//! the stop parks on. Where neither does, the stop waits out its whole budget +//! The holder, `klogd` here, lets the wire go and reads whether the stop +//! asked; the stop asks, and tries the wire. One of them must see the other: +//! the stop's try finds the wire free, or the holder sees the ask, and so +//! posts the release the stop parks on. Where neither does, the stop waits out its whole budget //! on a wire nobody holds and writes over it. Removing either `SeqCst` fence //! from `handoff.rs` reds this model with exactly that outcome. diff --git a/kernel/src/actuator.rs b/kernel/src/actuator.rs index 4f8d7cc7d0c..5dffb8814ab 100644 --- a/kernel/src/actuator.rs +++ b/kernel/src/actuator.rs @@ -87,6 +87,11 @@ actuators! { /// `LET_GO`. Judged by `machine_shutdown_wire_kept`. wire_kept_through_the_stop = "wire-kept-through-the-stop"; + /// Have `klogd` hold the console's wire from the boot's last word until the + /// stop has taken the seal, where the stop does not hold it itself. Judged + /// by `machine_shutdown_wire_at_the_seal`. + wire_held_at_the_last_word = "wire-held-at-the-last-word"; + /// Make one CPU ignore a kick. dump_deaf_cpu = "dump-deaf-cpu"; diff --git a/kernel/src/drivers/serial.rs b/kernel/src/drivers/serial.rs index 7dc11c80ef6..37c8723ac89 100644 --- a/kernel/src/drivers/serial.rs +++ b/kernel/src/drivers/serial.rs @@ -14,7 +14,7 @@ use crate::arch::IrqGuard; use crate::log; use super::serial_lock::{BackendLock, Held, Seized}; use crate::scheduler::Parkable; -use crate::sleeplock::{SleepGuard, SleepLock}; +use crate::sleeplock::{Holder, SleepGuard, SleepLock}; use crate::arch::console_uart as uart; @@ -253,17 +253,16 @@ pub unsafe fn panic_flush() { unsafe { crate::log::console::drain_bypassed(&mut uart) }; } -/// Every committed record through the registers, for a stop whose wire -/// `klogd` kept: a line of the holder's still in flight may interleave with -/// these. Never bypasses: every CPU is still live here, and reading the ring -/// unsynchronised is only safe once nothing else runs. -pub fn drain_over_the_wire() { +/// The registers for a stop whose wire `klogd` kept, to write its records +/// over the holder through: a line of the holder's still in flight may +/// interleave with them. Never bypasses: every CPU is still live here. +pub fn over_the_wire(write: impl FnOnce(&mut BackendGuard)) { if !has_console() { return; } let mut uart = panic_registers(); match &mut uart.0 { - Hold::Held(guard) => crate::log::console::drain_locked(guard), + Hold::Held(guard) => write(guard), Hold::Reentered(_) | Hold::Expired(_) => uart.write(NOT_DRAINED), } } @@ -284,28 +283,23 @@ pub fn wire(parkable: &Parkable) -> SleepGuard<'_, ()> { WIRE.lock(parkable) } -/// Who holds the wire, for the stop that waited it out. -pub fn wire_holder() -> impl core::fmt::Display { - struct Holder(Option); - impl core::fmt::Display for Holder { - fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result { - match self.0 { - Some(task) => write!(f, "task {task}"), - None => write!(f, "a context with no task"), - } - } - } - Holder(WIRE.holder()) -} - /// The wire, if it is free, from any context — the boot before per-CPU state -/// exists included, which has no task to hold it as. -pub fn try_wire() -> Option> { - if crate::log::PERCPU_READY.load(Ordering::Acquire) { +/// exists included, which has no task to hold it as; and who holds it where +/// it is not. +pub fn try_wire() -> Result, Holder> { + let taken = if crate::log::PERCPU_READY.load(Ordering::Acquire) { WIRE.try_lock() } else { WIRE.try_lock_untasked() - } + }; + taken.ok_or_else(|| WIRE.holder_name()) +} + +/// Whether the running task holds the wire, for a staging that asks who holds +/// it at the boot's last word. +#[cfg(feature = "boot-actuators")] +pub fn wire_is_mine() -> bool { + WIRE.holder().is_some_and(|holder| Some(holder) == crate::scheduler::current_task()) } /// Whether the UART has refused a write, which is said once. diff --git a/kernel/src/log/console.rs b/kernel/src/log/console.rs index a11459d7dca..de74d29721e 100644 --- a/kernel/src/log/console.rs +++ b/kernel/src/log/console.rs @@ -11,10 +11,12 @@ //! one is active, and `Drain::Inline` *is* [`KLOGD`] being null. //! //! **The stop takes the wire from `klogd` for good** ([`take_for_the_stop`]): -//! asked, `klogd` lets it go between two writes and never takes it again, and -//! the stop holds it to the machine's end, so every record the stop commits -//! reaches the wire before a CPU is taken down. A `klogd` that keeps it through -//! [`LET_GO`] has the stop write over it, through the registers. +//! asked, `klogd` lets it go between two writes and never takes it again, any +//! holder that lets it go once the stop asked posts the stop, and the stop +//! holds it to the machine's end, so every record the stop commits reaches the +//! wire before a CPU is taken down. A holder that keeps it through [`LET_GO`] +//! has the stop write over it, through the registers, from a position the +//! stop alone walks. use core::sync::atomic::{AtomicPtr, AtomicU64, AtomicU8, Ordering}; @@ -36,7 +38,7 @@ use crate::scheduler::{self, Parkable}; use crate::sync::Lock; use super::handoff::Handoff; -use super::read::{drain_ordered, Published, RecordSink}; +use super::read::{drain_ordered, Cursor, Published, RecordSink}; use super::shard; const NAME: &str = "klogd"; @@ -99,8 +101,11 @@ pub fn drain_inline() { if !serial::has_console() { return; } - let Some(wire) = serial::try_wire() else { return }; + let Ok(wire) = serial::try_wire() else { return }; drain_records(&wire, u64::MAX, Yield::Never); + // The stop asks only once userland runs, by when the one inline drain is + // a backend's arrival, on a thread: the post below is never an `emit`'s. + let_wire_go(wire); } /// Whether a drain lets the wire go to the stop that asks for it. @@ -114,8 +119,20 @@ enum Yield { /// The stop's claim on the wire, which `klogd` answers. static HANDOFF: Handoff = Handoff::new(); -/// Posted by `klogd` once it has let the wire go for the stop. -static LET_GO_POSTED: watch::Watch = watch::Watch::new(); +/// Posted by any holder that lets the wire go once the stop has asked for it. +static RELEASED: watch::Watch = watch::Watch::new(); + +/// Let the wire go, and answer whether the stop has asked for it, posting the +/// stop where it has: whoever held it, the stop's next try finds it free or +/// this read sees the ask (`log/handoff.rs`). +fn let_wire_go(wire: SleepGuard<'_, ()>) -> bool { + drop(wire); + let asked = HANDOFF.asked(); + if asked { + RELEASED.post(); + } + asked +} /// How long the stop waits for `klogd` to let the wire go once asked. /// @@ -136,20 +153,24 @@ pub(crate) const LET_GO: Budget = Budget::of( pub enum StopWire { /// The wire, which `klogd` let go of and never takes again. Held(SleepGuard<'static, ()>), - /// `klogd` kept the wire through [`LET_GO`]; the stop writes over it. - Kept, + /// Its holder kept the wire through [`LET_GO`]; the stop writes over it + /// from this position, taken once and never published, so a holder + /// still inside a drain cannot move it back under the stop. + Kept(Cursor), } impl StopWire { /// Every committed record onto the console, and every line console /// holders queued where the wire is held. - pub fn drain(&self) { + pub fn drain(&mut self) { match self { Self::Held(wire) => { drain_records(wire, u64::MAX, Yield::Never); drain_queue(wire, usize::MAX, Yield::Never); } - Self::Kept => serial::drain_over_the_wire(), + Self::Kept(cursor) => serial::over_the_wire(|guard| { + drain_ordered(&super::shards(), cursor, &mut Registers { out: guard }); + }), } } } @@ -159,42 +180,43 @@ impl StopWire { /// queued before it was stopped goes on the wire under the boot's last word /// and never after it. /// -/// Waits on `klogd`'s letting go, bounded by [`LET_GO`]: past it the stop -/// alerts by name and writes over the holder (a line of `klogd`'s still in -/// flight may interleave; nothing is lost but the queued lines, which the -/// alert says). The record backlog stays undrained here, so the sync behind -/// this is not spent behind a slow wire: the boot's last word drains it. +/// Waits on the holder's letting go, bounded by [`LET_GO`]: past it the stop +/// alerts by name and writes over the holder (a line of the holder's still in +/// flight may interleave, and the lines console holders queued are lost, +/// which the alert says). The record backlog stays undrained here, so the +/// sync behind this is not spent behind a slow wire: the boot's last word +/// drains it. pub fn take_for_the_stop(parkable: &Parkable) -> StopWire { - // Armed before the ask: a let-go posted between the ask and the park is + // Armed before the ask: a release posted between the ask and the park is // one the park returns on at once. - let armed = watch::arm(&LET_GO_POSTED, 0, kernel::sched::task::WaitClass::Other) - .expect("console: the stop holds no task to park"); + let armed = watch::arm(&RELEASED, 0, WaitClass::Other).expect("console: the stop holds no task to park"); HANDOFF.ask(); - // A staged `klogd` waits for the ask parked, with the wire held; a - // shipping one never parks holding it. - #[cfg(feature = "boot-actuators")] + // A `klogd` parked idle lets go of nothing until it runs: woken, it takes + // the wire behind whoever holds it, sees the ask and lets it go. post_wake(); let deadline = Deadline::at(crate::clock::now() + LET_GO.duration()); + let mut refused = None; loop { let late = deadline.reached(crate::clock::now()); - if let Some(wire) = serial::try_wire() { - if late { - crate::alert!("console: klogd held the wire through the stop's {LET_GO}, and let it go only after"); + match serial::try_wire() { + Ok(wire) => { + if let (true, Some(holder)) = (late, &refused) { + crate::alert!("console: {holder} held the wire through the stop's {LET_GO}, and let it go only after"); + } + drain_queue(&wire, usize::MAX, Yield::Never); + return StopWire::Held(wire); } - drain_queue(&wire, usize::MAX, Yield::Never); - return StopWire::Held(wire); - } - if late { - break; + Err(holder) if late => { + crate::alert!( + "console: {holder} kept the wire through the stop's {LET_GO}; the lines console holders queued \ + are not on it" + ); + return StopWire::Kept(DRAINED.take()); + } + Err(holder) => refused = Some(holder), } watch::wait_uncancellable(parkable, &armed, deadline); } - crate::alert!( - "console: {} kept the wire through the stop's {LET_GO}; the lines console holders queued are not \ - on it", - serial::wire_holder(), - ); - StopWire::Kept } /// Records and queued lines `klogd` takes per hold of the wire, so a console @@ -499,19 +521,19 @@ extern "C" fn body(_arg: u64) -> ! { let parkable = scheduler::Parkable::at_entry(); let handle = crate::sched::driver::current_handle().expect("klogd runs as a task"); loop { - #[cfg(feature = "boot-actuators")] - staged::hold_if_staged(&parkable, &handle); - let freed = if serial::has_console() { + let (freed, asked) = if serial::has_console() { // A chunk of each per hold, with interrupts on throughout. let wire = serial::wire(&parkable); + #[cfg(feature = "boot-actuators")] + staged::hold_if_staged(&parkable, &handle); drain_records(&wire, CHUNK, Yield::ToTheStop); - drain_queue(&wire, CHUNK as usize, Yield::ToTheStop) + let freed = drain_queue(&wire, CHUNK as usize, Yield::ToTheStop); + (freed, let_wire_go(wire)) } else { discard_pending(); - discard_queue() + (discard_queue(), HANDOFF.asked()) }; - // With the wire let go of: the read the stop's try pairs with. - if HANDOFF.asked() { + if asked { let_go(&parkable, &handle); } // A holder that found the queue full waits on room; this is the room. @@ -554,7 +576,6 @@ extern "C" fn body(_arg: u64) -> ! { fn let_go(parkable: &Parkable, handle: &crate::sched::payload::TaskHandle) -> ! { // The backlog this leaves reaches the wire at the boot's last word. crate::log!("console: klogd let the wire go to the stop"); - LET_GO_POSTED.post(); loop { let armed = watch::arm(handle.watch(), 0, WaitClass::Other).expect("klogd runs as a task"); let _ = watch::wait(parkable, &armed, crate::time::Deadline::never()); @@ -562,60 +583,136 @@ fn let_go(parkable: &Parkable, handle: &crate::sched::payload::TaskHandle) -> ! } #[cfg(feature = "boot-actuators")] -pub use staged::hold_the_wire as stage_a_held_wire; +pub use staged::{hold_across_the_stop, hold_at_the_last_word, sealed}; -/// `klogd` holding the wire across the stop, which only an actuator stages. +/// `klogd` inside its hold of the wire across the stop, which only an +/// actuator stages. #[cfg(feature = "boot-actuators")] mod staged { - use core::sync::atomic::{AtomicBool, Ordering}; + use core::sync::atomic::{AtomicBool, AtomicU8, Ordering}; use kernel::sched::task::WaitClass; use crate::sched::payload::TaskHandle; use crate::drivers::serial; - use crate::scheduler::Parkable; - use crate::time::Deadline; + use crate::scheduler::{Parkable, TaskId}; + use crate::time::{Deadline, Duration, DEAF_CPU}; use crate::watch; - /// Set by the stop: `klogd` takes the wire at its next pass. - static STAGED: AtomicBool = AtomicBool::new(false); + /// What the stop staged `klogd`'s next hold of the wire to be. + static STAGED: AtomicU8 = AtomicU8::new(NONE); + const NONE: u8 = 0; + /// Held until the stop asks for the wire, or, with + /// `wire-kept-through-the-stop`, for good. + const ACROSS_THE_STOP: u8 = 1; + /// Held from the boot's last word until the stop has taken the seal. + const AT_THE_LAST_WORD: u8 = 2; + /// Set by `klogd` once it holds the wire, and posted. static HOLDING: AtomicBool = AtomicBool::new(false); static HELD: watch::Watch = watch::Watch::new(); + /// Set by the stop once it has taken the seal. + static SEALED: AtomicBool = AtomicBool::new(false); - /// The stop's, before it takes anything down: `klogd` takes the wire, and - /// this returns once it has. - pub fn hold_the_wire(parkable: &Parkable) { + /// The stop's, before it takes anything down: `klogd` holds the wire, and + /// lets it go when the stop asks for it, as a shipping one does. + pub fn hold_across_the_stop(parkable: &Parkable) { + stage(parkable, ACROSS_THE_STOP); + } + + /// The stop's, just before the boot's last word: where the wire is not + /// the stop's, `klogd` holds it, parked inside its hold until the stop + /// has taken the seal, and then lets it go the moment it runs. + pub fn hold_at_the_last_word(parkable: &Parkable) { + if serial::wire_is_mine() { + crate::log!("console: the stop holds the wire at the boot's last word, staged"); + return; + } + stage(parkable, AT_THE_LAST_WORD); + } + + /// The stop's, once it has taken the seal: a `klogd` staged at the last + /// word is runnable from here, on whatever CPU will run it. + pub fn sealed() { + SEALED.store(true, Ordering::Release); + super::post_wake(); + } + + fn stage(parkable: &Parkable, what: u8) { let armed = watch::arm(&HELD, 0, WaitClass::Other).expect("the stop holds a task"); - STAGED.store(true, Ordering::Release); + STAGED.store(what, Ordering::Release); super::post_wake(); // No bound in guest time, which runs on while a host starves the // guest: the harness's ceiling, scaled by the host, is this wait's. + // `DEAF_CPU` into it, what the scheduler holds is said once. + let mut deadline = Some(Deadline::at(crate::clock::now() + Duration::from_nanos(DEAF_CPU.nanos()))); while !HOLDING.load(Ordering::Acquire) { - watch::wait_uncancellable(parkable, &armed, Deadline::never()); + watch::wait_uncancellable(parkable, &armed, deadline.unwrap_or(Deadline::never())); + if deadline.is_some_and(|at| at.reached(crate::clock::now())) && !HOLDING.load(Ordering::Acquire) { + say_klogd_unrun(); + deadline = None; + } } - crate::log!("console: klogd holds the wire as the stop begins, staged"); } - /// `klogd`'s, at the top of its loop: once staged, it takes the wire and - /// keeps it — until the stop asks for it, then lets it go and goes on as - /// a shipping `klogd` does, or, with `wire-kept-through-the-stop`, for good. + /// What the judge reds on: `klogd`'s state and this CPU's run queue, + /// `DEAF_CPU` into a wait for a woken `klogd` to take the wire. + fn say_klogd_unrun() { + let ptr = super::KLOGD.load(Ordering::Acquire); + // SAFETY: leaked once from a `Box`, never cleared; set before userland, which asked for this stop, ran. + let state = unsafe { &*ptr }.state(); + let mut ready = [None::; 8]; + let mut queued = 0usize; + let read = crate::sched::driver::irq_off(|_| { + crate::sched::driver::for_each_ready(|id| { + if let Some(slot) = ready.get_mut(queued) { + *slot = Some(id); + } + queued += 1; + }) + }); + crate::log!( + "console: the staged klogd has not taken the wire {DEAF_CPU} into the stop's wait: klogd is {state:?}, \ + and the stop's {:?} has its run queue {}read, {queued} ready", + crate::sched::driver::current_cpu(), + if read { "" } else { "not " }, + ); + for id in ready.iter().flatten() { + crate::log!("console: ready behind the staged klogd's wait: {id}"); + } + } + + /// `klogd`'s, inside its hold of the wire: a staged hold parks here, the + /// wire held, until what the stop staged it for has passed; then `body` + /// drains and lets the wire go as a shipping `klogd` does. pub fn hold_if_staged(parkable: &Parkable, handle: &TaskHandle) { - if !STAGED.swap(false, Ordering::Acquire) { + let what = STAGED.swap(NONE, Ordering::Acquire); + if what == NONE { return; } - let wire = serial::wire(parkable); + // `klogd`'s own: the wake this commit owes is spent on `klogd`'s next + // park, so the stop's commits after it wake nothing, and only the + // stop's ask can end the hold. + match what { + ACROSS_THE_STOP => crate::log!("console: klogd holds the wire as the stop begins, staged"), + AT_THE_LAST_WORD => crate::log!("console: klogd holds the wire at the boot's last word, staged"), + _ => unreachable!("console: a staged hold of {what}"), + } HOLDING.store(true, Ordering::Release); HELD.post(); let kept = crate::actuator::wire_kept_through_the_stop(); loop { let armed = watch::arm(handle.watch(), 0, WaitClass::Other).expect("klogd runs as a task"); - if !kept && super::HANDOFF.asked() { - break; + let over = match what { + ACROSS_THE_STOP => !kept && super::HANDOFF.asked(), + AT_THE_LAST_WORD => SEALED.load(Ordering::Acquire), + _ => unreachable!("console: a staged hold of {what}"), + }; + if over { + return; } let _ = watch::wait(parkable, &armed, Deadline::never()); } - drop(wire); } } diff --git a/kernel/src/log/handoff.rs b/kernel/src/log/handoff.rs index 0d06c517190..8a133694426 100644 --- a/kernel/src/log/handoff.rs +++ b/kernel/src/log/handoff.rs @@ -1,10 +1,10 @@ -//! The stop's claim on the console wire, and `klogd`'s answer to it. +//! The stop's claim on the console wire, and its holder's answer to it. //! -//! The stop [`Handoff::ask`]s and then tries the wire; `klogd` lets the wire go -//! and then reads [`Handoff::asked`], and posts that it let go when it was. -//! Each side's write and its later read are split by a `SeqCst` fence, so at -//! least one of them sees the other's: the stop's try finds the wire free, or -//! `klogd` sees the ask and posts. Without them both can read stale, and the +//! The stop [`Handoff::ask`]s and then tries the wire; every holder lets the +//! wire go and then reads [`Handoff::asked`], and posts that it let go when it +//! was. Each side's write and its later read are split by a `SeqCst` fence, so +//! at least one of them sees the other's: the stop's try finds the wire free, +//! or the holder sees the ask and posts. Without them both can read stale, and the //! stop waits out its whole budget on a wire nobody holds. //! Compiled a second time by `kernel-loom`, whose `console_handoff` drives //! both sides over the real `SleepLock`. diff --git a/kernel/src/power.rs b/kernel/src/power.rs index 72dc672ba13..77ad74d493f 100644 --- a/kernel/src/power.rs +++ b/kernel/src/power.rs @@ -10,9 +10,9 @@ //! watchdog, a triple fault, power loss — are outside it and always will be. //! //! **Nothing an end says is logged after the console's last drain.** The -//! stop holds the console's wire (`log::console::StopWire`), which `klogd` -//! let go of for good, and its drain here is the log ring's last reader for -//! the console: a record committed past it reaches no wire. What an end says +//! stop holds the console's wire (`log::console::StopWire`), or writes over +//! the holder that kept it, and its drain here is the log ring's last reader +//! for the console: a record committed past it reaches no wire. What an end says //! through the ring it says above the drain (`arch::power::settle`); //! `arch::power::off` and `arch::power::reset` log nothing, and a panic in //! either drains for itself. The black box's page is another reader and an @@ -33,7 +33,7 @@ pub fn shutdown_refused() -> Option<&'static str> { } /// Return the machine to firmware. -pub fn reboot(wire: StopWire) -> ! { +pub fn reboot(mut wire: StopWire) -> ! { wire.drain(); // Kernel-internal, so a bug rather than a machine quiesced and then left halted quietly. assert!(can_reboot(), "reboot: no reset, and the caller did not ask can_reboot() first"); @@ -64,7 +64,7 @@ pub fn reset_now() -> ! { } /// Power the machine off. The caller asked [`shutdown_refused`] first. -pub fn shutdown(stopping: crate::quiesce::Stopping, wire: StopWire) -> ! { +pub fn shutdown(stopping: crate::quiesce::Stopping, mut wire: StopWire) -> ! { // Above the drain, because it logs. let settled = crate::arch::power::settle(stopping); // Nothing drains the log ring after this point, and nothing below logs. diff --git a/kernel/src/sched/driver.rs b/kernel/src/sched/driver.rs index d613be313d2..ec61f50c915 100644 --- a/kernel/src/sched/driver.rs +++ b/kernel/src/sched/driver.rs @@ -798,6 +798,18 @@ pub fn for_each_dying(mut f: impl FnMut(TaskId)) -> bool { .is_some() } +/// Every thread on this CPU's run queue, in pick order, for a staging that +/// says why a woken thread has not run. `false` means a pass owns the state. +#[cfg(feature = "boot-actuators")] +pub fn for_each_ready(mut f: impl FnMut(TaskId)) -> bool { + try_with_cpu(|cpu| { + for task in cpu.rq().tasks() { + f(task.ext().id); + } + }) + .is_some() +} + /// The thread this CPU has loaded, if any. pub fn running_id() -> Option { try_with_cpu(|cpu| cpu.running().map(|t| t.ext().id)).flatten() diff --git a/kernel/src/sleeplock.rs b/kernel/src/sleeplock.rs index 601b7072407..3b3427a1e18 100644 --- a/kernel/src/sleeplock.rs +++ b/kernel/src/sleeplock.rs @@ -88,7 +88,7 @@ impl SleepLock { assert!( me.is_none() || self.holder() != me, "sleeplock: {} already holds this lock", - OwnerName(word_of(me)), + Holder { word: word_of(me), turn_untaken: false }, ); let owner = word_of(me); if let Some(guard) = self.take(owner) { @@ -135,16 +135,31 @@ impl SleepLock { word => Some(TaskId::unpack(word)), } } + + /// Who holds the lock as of this read, for a message and never a + /// decision: it may have moved by the time it is said. + pub fn holder_name(&self) -> Holder { + // A ticket issued past `now` with no holder stored is a contender + // whose turn was posted and has not run to take it. + let turn_untaken = self.ticket.load(Ordering::Relaxed) != self.now.load(Ordering::Relaxed); + Holder { word: self.holder.load(Ordering::Relaxed), turn_untaken } + } } -/// Prints as a task where it names one, or "a context with no task" rather than the raw packed word. -struct OwnerName(u64); +/// A lock's holder by name: a task, a context with no task, a contender whose +/// turn came and has not taken it, or nobody. +pub struct Holder { + word: u64, + turn_untaken: bool, +} -impl core::fmt::Display for OwnerName { +impl core::fmt::Display for Holder { fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result { - match self.0 { - FREE | NOT_A_TASK => write!(f, "a context with no task"), - word => write!(f, "{}", TaskId::unpack(word)), + match (self.word, self.turn_untaken) { + (FREE, true) => write!(f, "a contender whose turn came and has not taken it"), + (FREE, false) => write!(f, "nobody"), + (NOT_A_TASK, _) => write!(f, "a context with no task"), + (word, _) => write!(f, "{}", TaskId::unpack(word)), } } } diff --git a/kernel/src/syscall/machine.rs b/kernel/src/syscall/machine.rs index 3b41eb4f4bf..752d396fe6d 100644 --- a/kernel/src/syscall/machine.rs +++ b/kernel/src/syscall/machine.rs @@ -92,7 +92,7 @@ fn quiesce(last: &str) -> Result<(crate::quiesce::Stopping, StopWire), SyscallEr // shipping `klogd` does at any moment. #[cfg(feature = "boot-actuators")] if crate::actuator::wire_held_across_the_stop() { - crate::log::console::stage_a_held_wire(&parkable); + crate::log::console::hold_across_the_stop(&parkable); } // First: what follows outlasts a feed cadence, and no pass runs to feed again. crate::arch::watchdog::disarm(); @@ -104,7 +104,7 @@ fn quiesce(last: &str) -> Result<(crate::quiesce::Stopping, StopWire), SyscallEr let stop_began = crate::log::read::newest_committed(); // Held to the machine's end: every record below reaches the wire before a // CPU is taken down, whoever was writing it when the stop began. - let wire = crate::log::console::take_for_the_stop(&parkable); + let mut wire = crate::log::console::take_for_the_stop(&parkable); // The machine's census, which no process's start or end takes. crate::census::log(); #[cfg(feature = "mask-windows")] @@ -120,6 +120,12 @@ fn quiesce(last: &str) -> Result<(crate::quiesce::Stopping, StopWire), SyscallEr // volume that carries them is still there: every USB disk's write cache is // emptied and waited for before anything is taken down. crate::drivers::xhci::flush_disks(); + // `klogd` inside its hold of the wire as the last word is logged, which a + // stop that did not hold the wire would leave it in at the seal below. + #[cfg(feature = "boot-actuators")] + if crate::actuator::wire_held_at_the_last_word() { + crate::log::console::hold_at_the_last_word(&parkable); + } log!("{last}"); // Order is load-bearing: the console drain, the seal, then the caller's // non-returning call. @@ -144,6 +150,10 @@ fn quiesce(last: &str) -> Result<(crate::quiesce::Stopping, StopWire), SyscallEr // `power::reboot`/`power::shutdown` do — which every reset this kernel // performs goes through. It is bounded, and the reset follows either way. crate::drivers::xhci::seal_shut(); + #[cfg(feature = "boot-actuators")] + if crate::actuator::wire_held_at_the_last_word() { + crate::log::console::sealed(); + } Ok((stopping, wire)) } diff --git a/tests/common/power.rs b/tests/common/power.rs index 782212d1355..3b66eeafb25 100644 --- a/tests/common/power.rs +++ b/tests/common/power.rs @@ -74,14 +74,24 @@ pub fn machine_shutdown(test_config: &Path) -> Result<(), String> { Ok(()) } -/// What the stop alerts where `klogd` kept the console's wire through the -/// stop's whole budget, in `kernel/src/log/console.rs`. +/// What the stop alerts where the console's wire was kept through the stop's +/// whole budget, in `kernel/src/log/console.rs`. const WIRE_KEPT: &str = "kept the wire through the stop's"; -/// What both of the stop's alerts say where `klogd` let the wire go only past -/// the stop's budget or not at all, in `kernel/src/log/console.rs`. +/// What both of the stop's alerts say where the wire's holder let it go only +/// past the stop's budget or not at all, in `kernel/src/log/console.rs`. pub const WIRE_LATE: &str = "the wire through the stop's"; +/// What a staging says where the `klogd` it woke had not taken the wire +/// `DEAF_CPU` into the stop's wait, with `klogd`'s state and the run queue, in +/// `kernel/src/log/console.rs`. Every staged test reds on it. +const STAGED_KLOGD_UNRUN: &str = "console: the staged klogd has not taken the wire"; + +/// What a stop staged by `wire-held-at-the-last-word` logs where it holds the +/// console's wire itself, in `kernel/src/log/console.rs`; where it does not, +/// `klogd` holds it inside its hold from here to the seal. +const STOP_HOLDS_AT_THE_LAST_WORD: &str = "console: the stop holds the wire at the boot's last word, staged"; + /// What a stop staged by `wire-held-across-the-stop` logs once `klogd` holds /// the console's wire, in `kernel/src/log/console.rs`. const WIRE_HELD: &str = "console: klogd holds the wire as the stop begins, staged"; @@ -103,6 +113,7 @@ pub fn wire_staged(kept: bool) -> &'static [&'static str] { /// where it did not `klogd` said it let the wire go there and the console is /// otherwise clean. pub fn judge_the_held_wire(console: &str, last: &str, kept: bool) -> Result<(), String> { + serial::Serial::named("staged stop", console.to_string()).must_not_say(STAGED_KLOGD_UNRUN)?; let lines: Vec<&str> = console.lines().collect(); let at = |what: &str| lines.iter().position(|l| l.contains(what)); let held = at(WIRE_HELD).ok_or_else(|| format!("the staged klogd never said it held the wire\n{console}"))?; @@ -117,7 +128,7 @@ pub fn judge_the_held_wire(console: &str, last: &str, kept: bool) -> Result<(), match (kept, at(WIRE_KEPT), at(WIRE_LET_GO)) { (true, Some(alert), None) if held < alert && alert < record => Ok(()), (false, None, Some(let_go)) if held < let_go && let_go < record => { - serial::Serial::named("the stop", console.to_string()).must_be_clean() + serial::Serial::named("staged stop", console.to_string()).must_be_clean() } (_, alert, let_go) => Err(format!( "klogd {} the wire, and the stop's alert is on line {alert:?} and klogd's let-go on line {let_go:?}\n{console}", @@ -147,6 +158,39 @@ pub fn machine_shutdown_wire_held(test_config: &Path, kept: bool) -> Result<(), Ok(()) } +/// `klogd` is staged to hold the console's wire from the boot's last word to +/// past the stop's seal, on one CPU, which from the seal on runs nothing but +/// the stop: a stop that left the wire to `klogd` there powers off with the +/// last word on no console. This one holds the wire itself, says so above the +/// last word, and puts the last word on the console. +pub fn machine_shutdown_wire_at_the_seal(test_config: &Path) -> Result<(), String> { + let options = + BootOptions { qmp: true, smp: 1, kernel_params: &["wire-held-at-the-last-word"], ..Default::default() }; + let mut qemu = QemuInstance::boot_with_options(test_config, &[], &[], options); + let boot = serial::Serial::boot(&qemu); + boot.must_be_clean()?; + let mut console = boot.text().to_string(); + qemu::await_marker(&mut qemu, &mut console, Q35_S5_SUPPLIED, "the ACPI server to hand the kernel \\_S5")?; + let mut stop = qemu::QmpShutdown::open(qemu.qmp_socket(), qemu.budget(qemu::GUEST_QUIET)); + writeln!(qemu.stdin_mut(), "run shutdown").expect("write to QEMU stdin"); + qemu.flush_stdin(); + ended(&mut qemu, &mut stop, &mut console, SHUTTING_DOWN, "guest-shutdown")?; + let lines: Vec<&str> = console.lines().collect(); + let at = |what: &str| lines.iter().position(|l| l.contains(what)); + match (at(STOP_HOLDS_AT_THE_LAST_WORD), at(SHUTTING_DOWN)) { + (Some(holds), Some(said)) if holds < said => {} + (holds, said) => { + return Err(format!( + "the stop's hold of the wire at the last word is on line {holds:?} and {SHUTTING_DOWN:?} on \ + {said:?}\n{console}" + )) + } + } + serial::Serial::named("staged stop", console.clone()).must_be_clean()?; + eprintln!(" [power] the stop held the wire at the last word and across the seal; the last word reached it"); + Ok(()) +} + /// A stop that ends with a userland thread still running is followed by a /// power-off all the same, with the sleep type `acpiserver` handed the /// kernel: q35 hands over in ACPI mode, so the power-off diff --git a/tests/toyos.rs b/tests/toyos.rs index 0828792ffeb..38b1774a8af 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -250,10 +250,10 @@ const SCREEN_TESTS: &[(&str, qemu::Profile)] = &[ ("virt_debug_refused", qemu::Profile::Virt), ("virt_readonly_copyout", qemu::Profile::Virt), ("virt_ring0_timer_in_syscall", qemu::Profile::Virt), - // Emulated, with `virt_el1_smp` and `virt_off_names_the_cpus_left_on`: each - // waits for the boot's last word behind `unmap_touch`'s fault reports, and - // under HVF the power-off can come before `klogd` has put it on the wire - // (issues/the-boots-last-word-can-miss-the-console-when-klogd-holds-the-wire.md). + // Emulated, with `virt_el1_smp`, `virt_off_names_the_cpus_left_on` and the + // reboots: under HVF a `klogd` the stop wakes can go undispatched past the + // stop's whole wait for the console's wire + // (issues/a-woken-klogd-can-wait-seconds-on-an-idle-cpu-under-hvf.md). ("virt_mask_windows", qemu::Profile::VirtEl2), ("virt_smp", qemu::Profile::VirtEl2), ("virt_el1_smp", qemu::Profile::VirtTcg), @@ -325,6 +325,10 @@ const MACHINE_TESTS: &[&str] = &[ "machine_shutdown_wire_held", // The same with `klogd` keeping the wire through the stop's budget. "machine_shutdown_wire_kept", + // The same with `klogd` staged inside its hold of the wire from the boot's + // last word past the seal, where the stop does not hold it: the one CPU + // runs nothing but the stop from the seal on. + "machine_shutdown_wire_at_the_seal", // A claimable function with a mappable BAR that no program of the boot // holds: QEMU's virtio NIC on `tests/testcases`. The T14's one such // function is its I219, and a kernel that dies on this takes the bench's @@ -3206,6 +3210,7 @@ fn run_machine_test(name: &str, test_config: &Path) -> Result<(), String> { "machine_shutdown_short_stop" => power::machine_shutdown_short_stop(test_config), "machine_shutdown_wire_held" => power::machine_shutdown_wire_held(test_config, false), "machine_shutdown_wire_kept" => power::machine_shutdown_wire_held(test_config, true), + "machine_shutdown_wire_at_the_seal" => power::machine_shutdown_wire_at_the_seal(test_config), "bar_map_again" => bar_map_again(test_config), "console_image_boots" => console_image_boots(), "nvme_disk_keeps_log_and_home" => nvme_disk_keeps_log_and_home(test_config), From a78f4a44967dc617e708dec429d06f89d99dfb60 Mon Sep 17 00:00:00 2001 From: japabu Date: Fri, 9 Oct 2026 19:34:52 +0200 Subject: [PATCH 3/5] The stop wakes klogd at its ask only where a staging parks it holding the wire, and the held judge drops the let-go order A shipping klogd never parks while it holds the wire (a virtio wait spins, and a wake reaches only a parked task), and an idle one holds nothing, so the stop's first try takes the wire. The only holder the wake at the ask released was the one `wire-held-across-the-stop` parks inside its hold: the wake now runs under `boot-actuators` and that staging's predicate, and an unstaged kernel runs the shipping stop. `drain_inline` drops the wire plainly: it runs only before klogd starts (the boot, and a backend's arrival, which precedes `log::console::start`), when the stop cannot have asked, so its post could never fire. `SleepLock::holder_name` names three states: a task, a context with no task, or nobody. The contender-whose-turn-came arm is cut: klogd queues on the wire only behind the stop itself, after the stop stopped asking. The held judge no longer orders klogd's let-go line before the stop's record: klogd posts RELEASED before it logs that line, and the woken stop races it to the census (1 ms apart on SMP; on one CPU a tick between the post and the log can leave the line uncommitted). The hold, the record and the last word stay ordered, and the console must be clean, which is what the release-never-posts and stop-wakes-no-klogd mutations red on. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_017cSFvbD35xJ2kGANVdm23C --- kernel/src/log/console.rs | 29 ++++++++++++++--------------- kernel/src/sleeplock.rs | 24 ++++++++---------------- tests/common/power.rs | 19 ++++++------------- 3 files changed, 28 insertions(+), 44 deletions(-) diff --git a/kernel/src/log/console.rs b/kernel/src/log/console.rs index de74d29721e..4a340c14df6 100644 --- a/kernel/src/log/console.rs +++ b/kernel/src/log/console.rs @@ -11,12 +11,11 @@ //! one is active, and `Drain::Inline` *is* [`KLOGD`] being null. //! //! **The stop takes the wire from `klogd` for good** ([`take_for_the_stop`]): -//! asked, `klogd` lets it go between two writes and never takes it again, any -//! holder that lets it go once the stop asked posts the stop, and the stop -//! holds it to the machine's end, so every record the stop commits reaches the -//! wire before a CPU is taken down. A holder that keeps it through [`LET_GO`] -//! has the stop write over it, through the registers, from a position the -//! stop alone walks. +//! asked, `klogd` lets it go between two writes, posts the stop and never +//! takes it again, and the stop holds it to the machine's end, so every +//! record the stop commits reaches the wire before a CPU is taken down. A +//! holder that keeps it through [`LET_GO`] has the stop write over it, through +//! the registers, from a position the stop alone walks. use core::sync::atomic::{AtomicPtr, AtomicU64, AtomicU8, Ordering}; @@ -103,9 +102,6 @@ pub fn drain_inline() { } let Ok(wire) = serial::try_wire() else { return }; drain_records(&wire, u64::MAX, Yield::Never); - // The stop asks only once userland runs, by when the one inline drain is - // a backend's arrival, on a thread: the post below is never an `emit`'s. - let_wire_go(wire); } /// Whether a drain lets the wire go to the stop that asks for it. @@ -119,12 +115,12 @@ enum Yield { /// The stop's claim on the wire, which `klogd` answers. static HANDOFF: Handoff = Handoff::new(); -/// Posted by any holder that lets the wire go once the stop has asked for it. +/// Posted by `klogd` as it lets the wire go once the stop has asked for it. static RELEASED: watch::Watch = watch::Watch::new(); /// Let the wire go, and answer whether the stop has asked for it, posting the -/// stop where it has: whoever held it, the stop's next try finds it free or -/// this read sees the ask (`log/handoff.rs`). +/// stop where it has: the stop's next try finds it free or this read sees +/// the ask (`log/handoff.rs`). fn let_wire_go(wire: SleepGuard<'_, ()>) -> bool { drop(wire); let asked = HANDOFF.asked(); @@ -191,9 +187,12 @@ pub fn take_for_the_stop(parkable: &Parkable) -> StopWire { // one the park returns on at once. let armed = watch::arm(&RELEASED, 0, WaitClass::Other).expect("console: the stop holds no task to park"); HANDOFF.ask(); - // A `klogd` parked idle lets go of nothing until it runs: woken, it takes - // the wire behind whoever holds it, sees the ask and lets it go. - post_wake(); + // A shipping `klogd` never parks holding the wire; a staged one does, and + // reads the ask only once woken. + #[cfg(feature = "boot-actuators")] + if crate::actuator::wire_held_across_the_stop() { + post_wake(); + } let deadline = Deadline::at(crate::clock::now() + LET_GO.duration()); let mut refused = None; loop { diff --git a/kernel/src/sleeplock.rs b/kernel/src/sleeplock.rs index 3b3427a1e18..73e52397e7f 100644 --- a/kernel/src/sleeplock.rs +++ b/kernel/src/sleeplock.rs @@ -88,7 +88,7 @@ impl SleepLock { assert!( me.is_none() || self.holder() != me, "sleeplock: {} already holds this lock", - Holder { word: word_of(me), turn_untaken: false }, + Holder(word_of(me)), ); let owner = word_of(me); if let Some(guard) = self.take(owner) { @@ -139,27 +139,19 @@ impl SleepLock { /// Who holds the lock as of this read, for a message and never a /// decision: it may have moved by the time it is said. pub fn holder_name(&self) -> Holder { - // A ticket issued past `now` with no holder stored is a contender - // whose turn was posted and has not run to take it. - let turn_untaken = self.ticket.load(Ordering::Relaxed) != self.now.load(Ordering::Relaxed); - Holder { word: self.holder.load(Ordering::Relaxed), turn_untaken } + Holder(self.holder.load(Ordering::Relaxed)) } } -/// A lock's holder by name: a task, a context with no task, a contender whose -/// turn came and has not taken it, or nobody. -pub struct Holder { - word: u64, - turn_untaken: bool, -} +/// A lock's holder by name: a task, a context with no task, or nobody. +pub struct Holder(u64); impl core::fmt::Display for Holder { fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result { - match (self.word, self.turn_untaken) { - (FREE, true) => write!(f, "a contender whose turn came and has not taken it"), - (FREE, false) => write!(f, "nobody"), - (NOT_A_TASK, _) => write!(f, "a context with no task"), - (word, _) => write!(f, "{}", TaskId::unpack(word)), + match self.0 { + FREE => write!(f, "nobody"), + NOT_A_TASK => write!(f, "a context with no task"), + word => write!(f, "{}", TaskId::unpack(word)), } } } diff --git a/tests/common/power.rs b/tests/common/power.rs index 3b66eeafb25..c9c90433fd7 100644 --- a/tests/common/power.rs +++ b/tests/common/power.rs @@ -96,10 +96,6 @@ const STOP_HOLDS_AT_THE_LAST_WORD: &str = "console: the stop holds the wire at t /// the console's wire, in `kernel/src/log/console.rs`. const WIRE_HELD: &str = "console: klogd holds the wire as the stop begins, staged"; -/// What `klogd` logs as it lets the console's wire go to the stop, in -/// `kernel/src/log/console.rs`. -const WIRE_LET_GO: &str = "console: klogd let the wire go to the stop"; - /// The actuators that stage `klogd` holding the wire across the stop: until /// the stop asks for it, or, `kept`, for good. pub fn wire_staged(kept: bool) -> &'static [&'static str] { @@ -110,8 +106,7 @@ pub fn wire_staged(kept: bool) -> &'static [&'static str] { /// `console` of a boot that ended with the `last` word: the staged hold, the /// stop's record and the last word are all on it, in that order; where `klogd` /// `kept` the wire the stop said so between the hold and the record, and -/// where it did not `klogd` said it let the wire go there and the console is -/// otherwise clean. +/// where it did not the console is clean. pub fn judge_the_held_wire(console: &str, last: &str, kept: bool) -> Result<(), String> { serial::Serial::named("staged stop", console.to_string()).must_not_say(STAGED_KLOGD_UNRUN)?; let lines: Vec<&str> = console.lines().collect(); @@ -125,13 +120,11 @@ pub fn judge_the_held_wire(console: &str, last: &str, kept: bool) -> Result<(), if !(held < record && record < said) { return Err(format!("the hold, the stop's record and {last:?} are on lines {held}, {record} and {said}\n{console}")); } - match (kept, at(WIRE_KEPT), at(WIRE_LET_GO)) { - (true, Some(alert), None) if held < alert && alert < record => Ok(()), - (false, None, Some(let_go)) if held < let_go && let_go < record => { - serial::Serial::named("staged stop", console.to_string()).must_be_clean() - } - (_, alert, let_go) => Err(format!( - "klogd {} the wire, and the stop's alert is on line {alert:?} and klogd's let-go on line {let_go:?}\n{console}", + match (kept, at(WIRE_KEPT)) { + (true, Some(alert)) if held < alert && alert < record => Ok(()), + (false, None) => serial::Serial::named("staged stop", console.to_string()).must_be_clean(), + (_, alert) => Err(format!( + "klogd {} the wire, and the stop's alert is on line {alert:?}\n{console}", if kept { "kept" } else { "was asked for" }, )), } From 7e5534dc1fef39e169a8c3568cd2bc55b7287b50 Mon Sep 17 00:00:00 2001 From: japabu Date: Fri, 9 Oct 2026 19:48:08 +0200 Subject: [PATCH 4/5] A staged klogd's park rechecks the staging's word, so the stage's wake it forgot at its registration is not lost The whole guest suite at 6d1d1e60b redded virt_reboot_wire_held on the staging's capture: klogd Blocked on cpu1, the stop's cpu0 with 0 ready, 5 s into the stop's wait for klogd to take the wire. `stage` stores STAGED and then wakes klogd; a klogd that is running then is flagged, not claimed, and `Watch::register` forgets that flag before klogd reads its condition. klogd's park recheck read the record backlog and the queue, never STAGED, so it parked on a staging nothing would wake again. The recheck now reads STAGED under `boot-actuators`, the staging's own condition. A shipping klogd's every wake is posted after a condition its recheck reads (a committed record, a queued line, a backend's rewind), so the forgetting loses it nothing; a shipping kernel is unchanged. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_017cSFvbD35xJ2kGANVdm23C --- kernel/src/log/console.rs | 13 +++++++++++++ 1 file changed, 13 insertions(+) diff --git a/kernel/src/log/console.rs b/kernel/src/log/console.rs index 4a340c14df6..a1d477a6310 100644 --- a/kernel/src/log/console.rs +++ b/kernel/src/log/console.rs @@ -558,6 +558,12 @@ extern "C" fn body(_arg: u64) -> ! { let armed = watch::arm(handle.watch(), 0, WaitClass::Other).expect("klogd runs as a task"); // Safe with no backend because `discard_pending` still advances the position each pass. if shard::arm_waiter(shard::log_waiter(), || { + // The registration above forgot the staging's wake if it came + // while this thread ran: the staging's own word is the recheck. + #[cfg(feature = "boot-actuators")] + if staged::pending() { + return true; + } // Under the lock `queue` stores under, ahead of the fence its wake takes. DRAINED.any_pending() || QUEUE.lock().len > 0 }) { @@ -681,6 +687,13 @@ mod staged { } } + /// Whether the stop has staged a hold `klogd` has not yet taken: stored + /// before the stage's wake, so `klogd`'s park, which a wake made before its + /// registration does not end, reads it after registering. + pub fn pending() -> bool { + STAGED.load(Ordering::Acquire) != NONE + } + /// `klogd`'s, inside its hold of the wire: a staged hold parks here, the /// wire held, until what the stop staged it for has passed; then `body` /// drains and lets the wire go as a shipping `klogd` does. From 3f1dea947de0dbd0913e49b6d7d376eedb869b5a Mon Sep 17 00:00:00 2001 From: japabu Date: Fri, 9 Oct 2026 20:14:50 +0200 Subject: [PATCH 5/5] Close the staged klogd that went unrun: the stage's wake was forgotten at klogd's registration, and the park now rechecks STAGED The cause, from the staging's capture: the whole guest suite at 6d1d1e60b redded virt_reboot_wire_held with `klogd is Blocked(CpuId(1)), and the stop's CpuId(0) has its run queue read, 0 ready`, 5 s into the stop's wait. `stage` stores STAGED and wakes klogd; a running klogd is flagged, not claimed; `Watch::register` forgets the flag; and klogd's recheck read the backlog and the queue but never STAGED, so it parked with nothing left to wake it. The same order loses the wake on one CPU, where a klogd preempted between its drain and its park is resumed after the stop's stage; the first, uncaptured one-CPU red is attributed by that mechanism, not by a capture of its own. Fixed in 7e5534dc1 under `boot-actuators`. The exit, at 7e5534dc1: 20 + 23 rounds of `cargo test --test toyos-build -- machine_shutdown_wire_held` (10, then 14, side by side) and `virt_reboot_wire_held` (4 side by side) on a 14-core Apple-silicon host, 694 runs, every one EXIT=0: 522 machine_shutdown_wire_held, 172 virt_reboot_wire_held. 16 of those rounds began at 1-minute load 30 or more (up to 47.99), holding 200 machine_shutdown_wire_held runs, 200 green. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_017cSFvbD35xJ2kGANVdm23C --- ...run-for-five-seconds-on-a-one-cpu-guest.md | 40 ------------------- 1 file changed, 40 deletions(-) delete mode 100644 issues/a-staged-klogd-went-unrun-for-five-seconds-on-a-one-cpu-guest.md diff --git a/issues/a-staged-klogd-went-unrun-for-five-seconds-on-a-one-cpu-guest.md b/issues/a-staged-klogd-went-unrun-for-five-seconds-on-a-one-cpu-guest.md deleted file mode 100644 index 10d73d73c18..00000000000 --- a/issues/a-staged-klogd-went-unrun-for-five-seconds-on-a-one-cpu-guest.md +++ /dev/null @@ -1,40 +0,0 @@ ---- -status: open -kind: defect -opened: 2026-10-09 ---- - -# A staged `klogd` went unrun for five seconds on a one-CPU guest - -On one CPU, the stop parked and woke `klogd`, and `klogd` did not run for 5 s -of guest time. The stop's hand-off of the console's wire rests on the -opposite (`log::console::take_for_the_stop`): parked, the stop leaves its own -CPU to `klogd`. - -**Measured once.** `machine_shutdown_wire_held` (q35, one CPU, x86-64 under -TCG on an Apple-silicon host of 14 cores), in the whole guest suite at -`c2a4542f0`, 1-minute load 21.53 when the suite began and 36.77 when it -ended. The staging's wait for `klogd` to take the wire, then bounded at 5 s -of guest time, panicked at guest 12.437 s, `the staged klogd never took the -wire`, 27 s of wall clock into a test that passes in about 7. Its console -was virtio-console's, which the harness keeps no copy of, so it does not -say whether `klogd` ran. Eighteen whole suites after -it, at load 18 to 67, did not repeat it. - -**Who could run instead.** Only the stop was parked; `klogd` had been -woken, and userland was still live, since the staging runs before the stop -stops it. So userland holding the CPU is a cause as open as a lost wake or -a host that starved the guest. - -**The capture.** The staging (`log::console::staged`) no longer has a bound -in guest time; `DEAF_CPU` into its wait it logs `klogd`'s scheduler state, -the stop's CPU, what that CPU runs and every task on its run queue, and goes -on waiting. Every staged test reds on that line -(`tests/common/power.rs`, `STAGED_KLOGD_UNRUN`), so a repeat is a red with -its capture, not a stall. - -**Exit**: the cause named from that capture, and fixed; then -`machine_shutdown_wire_held` passes 200 side-by-side runs at 1-minute load -30 or more. - -Owner: the orchestrator.