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 2940cb30a33..5324b4860af 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 @@ -147,6 +147,31 @@ which tests a count where the other tests sixteen times it; a counters read calls neither, and no function of `counters_read`, `test-runner`, `supervisor`, `logkeeper`, `toybox`, `kernelprobe` or the loader differs. +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 without a console above 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 compared.** These two ran the kernel of `wt/toyos-lastword` at + `aa7448db0`, built by the compiler before the ScalarEvolution fix. The + comparison across the fix above was of `main`'s `tests/virtsmpcase` image; + theirs was not compared, so whether the fault reaches them is not known. + The slow ones, with registers: a probe that captured `info registers -a` over QMP whenever the read had not ended 3 s after `unmap_touch` (`debug-slow.patch` in https://github.com/ToyOSOrg/ToyOS/pull/719#issuecomment-5978643928, which 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..42f37d16752 --- /dev/null +++ b/issues/a-woken-klogd-can-wait-seconds-on-an-idle-cpu-under-hvf.md @@ -0,0 +1,69 @@ +--- +status: open +kind: defect +opened: 2026-10-09 +--- + +# 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/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/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/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..c48479b8f7f --- /dev/null +++ b/kernel/loom/tests/console_handoff.rs @@ -0,0 +1,40 @@ +//! Loom: the stop's claim on the console wire against a holder's letting go +//! (`kernel/src/log/handoff.rs`), over the real `SleepLock`. +//! +//! 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. + +#![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..5dffb8814ab 100644 --- a/kernel/src/actuator.rs +++ b/kernel/src/actuator.rs @@ -79,6 +79,19 @@ 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"; + + /// 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"; @@ -189,6 +202,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..37c8723ac89 100644 --- a/kernel/src/drivers/serial.rs +++ b/kernel/src/drivers/serial.rs @@ -12,9 +12,9 @@ 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}; +use crate::sleeplock::{Holder, SleepGuard, SleepLock}; use crate::arch::console_uart as uart; @@ -253,29 +253,26 @@ 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); +/// 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; } - 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) => write(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. @@ -287,13 +284,22 @@ pub fn wire(parkable: &Parkable) -> SleepGuard<'_, ()> { } /// 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 32450524d4f..a1d477a6310 100644 --- a/kernel/src/log/console.rs +++ b/kernel/src/log/console.rs @@ -9,6 +9,13 @@ //! //! [`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, 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}; @@ -23,12 +30,14 @@ 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::read::{drain_ordered, Published, RecordSink}; +use super::handoff::Handoff; +use super::read::{drain_ordered, Cursor, Published, RecordSink}; use super::shard; const NAME: &str = "klogd"; @@ -84,35 +93,129 @@ 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); + let Ok(wire) = serial::try_wire() else { return }; + 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` 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: 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. +/// +/// `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, ()>), + /// 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(&mut self) { + match self { + Self::Held(wire) => { + drain_records(wire, u64::MAX, Yield::Never); + drain_queue(wire, usize::MAX, Yield::Never); + } + Self::Kept(cursor) => serial::over_the_wire(|guard| { + drain_ordered(&super::shards(), cursor, &mut Registers { out: guard }); + }), + } + } +} + +/// 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 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 release posted between the ask and the park is + // 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 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 { + let late = deadline.reached(crate::clock::now()); + 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); + } + 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); } - let parkable = scheduler::Parkable::at_entry(); - let wire = serial::wire(&parkable); - drain_queue(&wire, usize::MAX); } /// Records and queued lines `klogd` takes per hold of the wire, so a console @@ -140,9 +243,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 +360,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 +467,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 +520,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 { - 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); - drain_records(&wire, CHUNK); - drain_queue(&wire, CHUNK as usize) + #[cfg(feature = "boot-actuators")] + staged::hold_if_staged(&parkable, &handle); + drain_records(&wire, CHUNK, 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()) }; + if asked { + let_go(&parkable, &handle); + } // A holder that found the queue full waits on room; this is the room. if freed { SPACE.post(); @@ -444,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 }) { @@ -456,6 +576,158 @@ 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"); + 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_across_the_stop, hold_at_the_last_word, sealed}; + +/// `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, AtomicU8, Ordering}; + + use kernel::sched::task::WaitClass; + use crate::sched::payload::TaskHandle; + + use crate::drivers::serial; + use crate::scheduler::{Parkable, TaskId}; + use crate::time::{Deadline, Duration, DEAF_CPU}; + use crate::watch; + + /// 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` 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(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.unwrap_or(Deadline::never())); + if deadline.is_some_and(|at| at.reached(crate::clock::now())) && !HOLDING.load(Ordering::Acquire) { + say_klogd_unrun(); + deadline = None; + } + } + } + + /// 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}"); + } + } + + /// 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. + pub fn hold_if_staged(parkable: &Parkable, handle: &TaskHandle) { + let what = STAGED.swap(NONE, Ordering::Acquire); + if what == NONE { + return; + } + // `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"); + 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()); + } + } +} + /// 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..8a133694426 --- /dev/null +++ b/kernel/src/log/handoff.rs @@ -0,0 +1,46 @@ +//! 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; 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`. + +#[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..77ad74d493f 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`), 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 +//! 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(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"); 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, 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. - 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/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..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", - OwnerName(word_of(me)), + Holder(word_of(me)), ); let owner = word_of(me); if let Some(guard) = self.take(owner) { @@ -135,15 +135,22 @@ 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 { + Holder(self.holder.load(Ordering::Relaxed)) + } } -/// 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, or nobody. +pub struct Holder(u64); -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"), + FREE => 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 e18c15ef275..752d396fe6d 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::hold_across_the_stop(&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 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")] @@ -110,10 +120,16 @@ fn quiesce(last: &str) -> Result { // 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. - 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 +150,11 @@ 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) + #[cfg(feature = "boot-actuators")] + if crate::actuator::wire_held_at_the_last_word() { + crate::log::console::sealed(); + } + Ok((stopping, wire)) } /// Powers the machine off; requires a `SysCap` carrying [`Rights::POWER`]. Returns only when refused. @@ -148,7 +168,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 +183,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..c9c90433fd7 100644 --- a/tests/common/power.rs +++ b/tests/common/power.rs @@ -74,6 +74,116 @@ pub fn machine_shutdown(test_config: &Path) -> Result<(), String> { Ok(()) } +/// 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 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"; + +/// 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 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(); + 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)) { + (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" }, + )), + } +} + +/// `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(()) +} + +/// `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/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 6297f0b73f8..57d22fce2b6 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -267,10 +267,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), @@ -281,6 +281,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::Virt), + ("virt_reboot_wire_held", qemu::Profile::VirtEl2), + ("virt_reboot_wire_kept", qemu::Profile::VirtEl2), // The job case entered at EL2, once: the entry's EL2 writes for the timer // and FP, which no boot under HVF runs. ("virt_jobs_at_el2", qemu::Profile::VirtEl2), @@ -348,6 +350,16 @@ 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", + // 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 @@ -2273,8 +2285,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"); @@ -2286,6 +2300,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() }, @@ -2306,6 +2321,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(()) } @@ -2759,7 +2777,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" => { @@ -3504,6 +3526,9 @@ 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), + "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),