From b11ce6f9a3ce8e0acba8a898c4945a5fc8214a35 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 16:44:25 +0200 Subject: [PATCH 1/8] counters row: measure the idle second before printing anything test_rs_counters_metal printed its idle0 read, 81 lines, at the start of the very second it then measured. logkeeper writes and syncs those lines to the stick through the /log fileserver, which every counters boot so far placed on cpu7, so cpu7's idle busy fraction was the row's own output. The cpu7_scout row (wt/toyos-cpu7 at 22d241174, one T14 boot, judge EXIT=0) measured back-to-back idle seconds between counters rounds, four of each arm after a discarded warm-up. Mean idle busy: quiet (prints nothing): cpu0-6 0.00-0.03%, cpu7 0.12% loud (the row's 81 lines): cpu0-6 0.34-0.45%, cpu7 0.84% dose (four times the lines): cpu0-6 0.23-0.55%, cpu7 1.27% The row now takes idle0, idle1 and spin first and prints the three after the spin's read; the lines and their parsing are unchanged. The judge also says how many SMIs landed in the idle second: in the scout's seconds the cpu0-6 floor of about 0.45% appears exactly in the seconds whose SMI count moved, so a row's idle reading is read beside it. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- .../src/bin/counters_metal.rs | 32 ++++++++++++++----- tests/toyos.rs | 8 +++-- 2 files changed, 29 insertions(+), 11 deletions(-) diff --git a/tests/toyos-rust-tests/src/bin/counters_metal.rs b/tests/toyos-rust-tests/src/bin/counters_metal.rs index 757e1845b3e..97c68cc87f6 100644 --- a/tests/toyos-rust-tests/src/bin/counters_metal.rs +++ b/tests/toyos-rust-tests/src/bin/counters_metal.rs @@ -6,7 +6,9 @@ //! Three reads: `idle0` and `idle1` either side of [`IDLE`], and `spin` after //! [`SPIN`] iterations on a thread per CPU begun at `idle1`. Each read's //! records follow a line with the clock after it and what the read took, a -//! whole round each, none joining another's. +//! whole round each, none joining another's. **Nothing is printed until all +//! three are taken**: a printed line reaches the stick within the second, +//! through the `/log` fileserver on that fileserver's CPU. //! //! **Then `loaded`: how late the round's kick reaches each CPU** while a thread //! per CPU spawns a program that exits at once, which is the load Linux's @@ -118,14 +120,25 @@ fn loaded(cap: &SysCap) { } } -fn read(cap: &SysCap, phase: &str) { +/// One read: the clock after it, what it took, and every CPU's records. +struct Read { + at: u64, + took: Duration, + records: Vec, +} + +fn read(cap: &SysCap) -> Read { let mut raw = vec![RawRecord::EMPTY; syscall::cpu_count() as usize]; let asked = Instant::now(); let n = cap.counters(&mut raw).expect("the estate's capability reads the counters"); let took = asked.elapsed(); - println!("counters_metal {phase}: at {} ns, the read took {} ns", toyos_abi::clock::nanos_since_boot(), took.as_nanos()); - let records: Vec = raw[..n].iter().map(|r| Record::decode(r).expect("a record that decodes")).collect(); - for (path, value) in toyos_inspect::kernel::render(&records).expect("one record per cpu") { + let at = toyos_abi::clock::nanos_since_boot(); + Read { at, took, records: raw[..n].iter().map(|r| Record::decode(r).expect("a record that decodes")).collect() } +} + +fn print(phase: &str, read: &Read) { + println!("counters_metal {phase}: at {} ns, the read took {} ns", read.at, read.took.as_nanos()); + for (path, value) in toyos_inspect::kernel::render(&read.records).expect("one record per cpu") { println!("counters_metal {phase}: {}", toyos_inspect::line(&path, &value)); } } @@ -135,9 +148,9 @@ fn main() { return; } let cap: SysCap = Endowments::get().take(SYSCAP_LABEL).expect("test-runner endows a capability"); - read(&cap, "idle0"); + let idle0 = read(&cap); std::thread::sleep(IDLE); - read(&cap, "idle1"); + let idle1 = read(&cap); std::thread::scope(|s| { for _ in 0..syscall::cpu_count() { s.spawn(|| { @@ -148,6 +161,9 @@ fn main() { }); } }); - read(&cap, "spin"); + let spin = read(&cap); + for (phase, read) in [("idle0", &idle0), ("idle1", &idle1), ("spin", &spin)] { + print(phase, read); + } loaded(&cap); } diff --git a/tests/toyos.rs b/tests/toyos.rs index cbead411bd6..e1a14d605e5 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -3383,7 +3383,8 @@ const SMI_SPAN_NS: u64 = 4_444_000_000; /// same span of load (`tests/t14-linux/turbostat-loaded.txt`). /// /// Read and not held, beside Linux's turbostat: each CPU's idle busy -/// fraction, and what one round cost its reader; and beside Linux's loaded +/// fraction, which an SMI in the idle second raises on every CPU alike by the +/// time it held them, and what one round cost its reader; and beside Linux's loaded /// timer reading (`issues/toyos-beats-linuxs-latency-on-the-t14.md`), /// how late each CPU's kick handler ran under the `loaded` phase. fn counters_on_metal(back: &metal::Readback) -> Result<(), String> { @@ -3507,9 +3508,10 @@ fn counters_on_metal(back: &metal::Readback) -> Result<(), String> { } let spinning: Vec = (0..cpus).map(|cpu| tsc_mhz * ratio(idle1, spin, cpu, "aperf", "mperf")).collect(); eprintln!( - " [counters] {cpus} cpus, SMI +{} each over {} ms; TSC {tsc_mhz:.0} MHz", + " [counters] {cpus} cpus, SMI +{} each over {} ms, +{} in the idle second; TSC {tsc_mhz:.0} MHz", smis[0], - (at2 - at0) / 1_000_000 + (at2 - at0) / 1_000_000, + delta(idle0, idle1, 0, "smi") ); for (cpu, busy) in busy.iter().enumerate() { eprintln!( From 35cd631421b4cc54a829ce451e4aa19ffe1611b7 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 16:45:14 +0200 Subject: [PATCH 2/8] issues: close the cpu7 idle issue; the SMI issue reads the stop off MPERF t14-cpu7-idles-busier-under-toyos-than-any-cpu-under-linux.md is closed: its exit asked for a reading naming what ran on cpu7 across the counters row's idle second, and for the row's doc if it was the row's own work. The cpu7_scout row (wt/toyos-cpu7 at 22d241174, image sha256 a5dcc2a77f5d35f016a663e634d1003ad30e9de027fdd53868cd8dd20fafa035, one T14 boot run by the orchestrator, judge EXIT=0) names it: the /log fileserver, pid 4, spawned onto cpu7 (dst=7), writing the row's own 81-line idle0 print to the stick. With nothing printed cpu7 reads 22 to 28 ppm in a second no earlier print spills into, under a tenth of the lowest machine-wide 10 s interval Linux's idle turbostat reads on that machine (0.11%). The fold is test_rs_counters_metal's header: nothing is printed until the three reads are taken. The SMI issue gains the MPERF reading of the same boot. The scout's seconds, as its judge printed them (busy in ppm of each CPU's stamp, cpu0..cpu7): second 0 warmup Loud: from 1172790890 ns to 2172974091 ns, smi +1, busy ppm [4979 4793 4839 5343 7107 4558 4573 19060], kicks [12 4 2 5 1 1 1 4] second 1 round Quiet: from 2172974091 ns to 3173035738 ns, smi +0, busy ppm [26 63 25 230 26 285 27 28], kicks [1 1 1 1 1 1 1 1] second 2 round Loud: from 3173035738 ns to 4173341548 ns, smi +1, busy ppm [4884 4897 4556 5831 4554 4540 4555 9875], kicks [6 2 1 3 1 1 1 3] second 3 round Dose: from 4173341548 ns to 5174342442 ns, smi +0, busy ppm [389 1470 24 3723 22 7 24 7388], kicks [6 2 1 3 1 1 1 3] second 4 round Loud: from 5174342442 ns to 6174633115 ns, smi +0, busy ppm [336 341 22 1089 22 7 22 4578], kicks [6 1 1 3 1 1 1 3] second 5 round Dose: from 6174633115 ns to 7175633698 ns, smi +1, busy ppm [4904 5746 4551 7810 4546 4535 4550 12208], kicks [6 1 1 3 1 1 1 3] second 6 round Quiet: from 7175633698 ns to 8175690541 ns, smi +0, busy ppm [21 58 25 217 24 7 25 22], kicks [1 0 1 1 1 1 1 1] second 7 round Dose: from 8175690541 ns to 9176698816 ns, smi +1, busy ppm [4819 5635 4570 7501 4568 4553 4571 13604], kicks [6 2 1 3 1 1 1 3] second 8 round Quiet: from 9176698816 ns to 10176757787 ns, smi +0, busy ppm [22 59 21 218 22 6 23 25], kicks [1 0 1 1 1 1 1 1] second 9 round Loud: from 10176757787 ns to 11177135943 ns, smi +1, busy ppm [4867 4937 4557 5511 4552 4541 4557 9970], kicks [6 2 1 4 1 1 1 3] second 10 round Quiet: from 11177135943 ns to 12177194852 ns, smi +0, busy ppm [387 73 40 356 35 16 36 4875], kicks [6 1 1 3 1 1 1 3] second 11 round Loud: from 12177194852 ns to 13177496481 ns, smi +1, busy ppm [4879 4879 4561 5643 4555 4545 4559 9318], kicks [6 1 1 3 1 1 1 3] second 12 round Dose: from 13177496481 ns to 14178489116 ns, smi +0, busy ppm [247 1076 25 3026 24 6 21 17694], kicks [6 3 1 3 1 1 1 3] Dose: mean idle busy cpu0=0.26% cpu1=0.35% cpu2=0.23% cpu3=0.55% cpu4=0.23% cpu5=0.23% cpu6=0.23% cpu7=1.27% Loud: mean idle busy cpu0=0.37% cpu1=0.38% cpu2=0.34% cpu3=0.45% cpu4=0.34% cpu5=0.34% cpu6=0.34% cpu7=0.84% Quiet: mean idle busy cpu0=0.01% cpu1=0.01% cpu2=0.00% cpu3=0.03% cpu4=0.00% cpu5=0.01% cpu6=0.00% cpu7=0.12% Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- ...er-under-toyos-than-any-cpu-under-linux.md | 28 ------------------- ...rupts-every-cpu-every-2-2-s-under-toyos.md | 8 ++++++ 2 files changed, 8 insertions(+), 28 deletions(-) delete mode 100644 issues/t14-cpu7-idles-busier-under-toyos-than-any-cpu-under-linux.md diff --git a/issues/t14-cpu7-idles-busier-under-toyos-than-any-cpu-under-linux.md b/issues/t14-cpu7-idles-busier-under-toyos-than-any-cpu-under-linux.md deleted file mode 100644 index 4d891d1538a..00000000000 --- a/issues/t14-cpu7-idles-busier-under-toyos-than-any-cpu-under-linux.md +++ /dev/null @@ -1,28 +0,0 @@ ---- -status: open -kind: defect -opened: 2026-10-04 ---- - -# T14 cpu7 idles busier under ToyOS than any CPU under Linux - -The `counters` metal row reads each CPU's MPERF over its stamp across the idle -second between its `idle0` and `idle1` reads. Linux's turbostat on the same -machine, idle (`tests/t14-linux/turbostat-idle.txt`), reads 0.11 to 0.36% -machine-wide per 10 s and no CPU above 0.69%. - -cpu7 reads about four times that, on every boot so far: 1.45% at `ce1786ff0` -(pull request #705), 1.42% at `a059144e2`, and 1.86% and 1.85% on the two arms -of pull request #725's run. - -cpu0 read 1.37% and 1.35% on the first two boots. That was the idle loop -spinning on an `irq_ring` record `xhci::poll_if_pending` left when a USB-stick -transfer held `XHCI`; since `XHCI` became an `OwedLock`, cpu0 reads 0.50% with -the change (`a65205a81`) and 1.77% with the whole change reverted -(`b0cae9a19`), cpu1 to cpu6 0.45 to 0.68% on both arms. - -Not yet attributed: the row's own reader runs between the two reads, prints -its `idle0` lines and parks, and which CPUs it and the log's path ran on that -second is not recorded. Owner: the orchestrator, which holds the T14. -**Exit**: a reading that names what ran on cpu7 across that second; then the -cause is fixed, or, if it is the row's own work, folded to the row's doc. diff --git a/issues/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md b/issues/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md index fcc34d91b5a..32c482ad59a 100644 --- a/issues/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md +++ b/issues/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md @@ -25,6 +25,14 @@ lines are quoted on #681 (comment 5962619169; the boot itself in comment 9.925 s all eight CPUs carry one at once. That the CPU stops is shown by two CPUs waiting on a lock across a step, which went 4,503,694 and 4,554,675 ns between two turns of their own spin. +- **MPERF reads the stop as about 4.55 ms of C0 on every CPU.** One T14 boot + of a scout image without ACPI mode (`22d241174`) read twelve back-to-back + idle seconds between counters rounds; the commit that added this bullet + carries its per-second lines. In the five whose SMI count moved by one, + cpu2, cpu4, cpu5 and cpu6, which ran none of the log's work, read 4535 to + 4571 ppm busy; in the seven where it did not, 6 to 285 ppm. That is the + `counters` row's "two idle floors", about 0.45% and 0.03% or less: a 1 s idle + second catches a 2.2 s-period SMI or does not. - **Linux, in one condition, read none.** On the same machine under Ubuntu's `6.8.0-142-generic`, `perf stat -a -A -e msr/smi/` read 0 on every CPU over 120.378 s beside `rtla timerlat top -q -d 2m --dma-latency 0`, which holds From 49e49a96347de837bcf58a1a76fe4b3836c4c9d5 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 17:24:12 +0200 Subject: [PATCH 3/8] counters row: idle0 waits for the log to hold the row's own line At head 35cd63142 the T14 read cpu7 at 1.40% idle busy, and 1.43% with the row's print-after change reverted: moving the row's print did not move cpu7. The readbacks show why. The job starts about 8 ms after logkeeper does, and the stick's first sync (`usb-storage: disk 0 does not implement SYNCHRONIZE CACHE`, a record the /log fileserver's path stamps on cpu7) is at 1.182 s on head against idle0 at 1.173184 s, and at 1.183 s on the revert against idle0 at 1.173472 s: logkeeper is still writing the boot so far and the job's launch lines to the stick inside the measured second, on both arms. The binary now reads the log through logkeeper's `log` port before idle0: it prints a line and reads the served log until the line comes back, which logkeeper hands a reader only after the round is written and synced. Twice, because the round that writes the first line may itself stamp a record (the stick's first sync does), which the second round writes. Each wait is bounded by two of logkeeper's 5 s write budgets and panics past it. The testcases estate gives logkeeper its `log` port and test-runner the connector to it, which the job inherits. The cpu7 issue is restored: the head's T14 reading does not meet its exit, and no reading of this change exists yet. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- ...er-under-toyos-than-any-cpu-under-linux.md | 36 +++++++++++ tests/testcases/system.toml | 12 ++-- tests/toyos-rust-tests/Cargo.lock | 8 +++ tests/toyos-rust-tests/Cargo.toml | 2 + .../src/bin/counters_metal.rs | 60 ++++++++++++++++++- 5 files changed, 113 insertions(+), 5 deletions(-) create mode 100644 issues/t14-cpu7-idles-busier-under-toyos-than-any-cpu-under-linux.md diff --git a/issues/t14-cpu7-idles-busier-under-toyos-than-any-cpu-under-linux.md b/issues/t14-cpu7-idles-busier-under-toyos-than-any-cpu-under-linux.md new file mode 100644 index 00000000000..2f48c9c0efa --- /dev/null +++ b/issues/t14-cpu7-idles-busier-under-toyos-than-any-cpu-under-linux.md @@ -0,0 +1,36 @@ +--- +status: open +kind: defect +opened: 2026-10-04 +--- + +# T14 cpu7 idles busier under ToyOS than any CPU under Linux + +The `counters` metal row reads each CPU's MPERF over its stamp across the idle +second between its `idle0` and `idle1` reads. Linux's turbostat on the same +machine, idle (`tests/t14-linux/turbostat-idle.txt`), reads 0.11 to 0.36% +machine-wide per 10 s and no CPU above 0.69%. + +cpu7 reads about four times that, on every boot so far: 1.45% at `ce1786ff0` +(pull request #705), 1.42% at `a059144e2`, and 1.86% and 1.85% on the two arms +of pull request #725's run. + +cpu0 read 1.37% and 1.35% on the first two boots. That was the idle loop +spinning on an `irq_ring` record `xhci::poll_if_pending` left when a USB-stick +transfer held `XHCI`; since `XHCI` became an `OwedLock`, cpu0 reads 0.50% with +the change (`a65205a81`) and 1.77% with the whole change reverted +(`b0cae9a19`), cpu1 to cpu6 0.45 to 0.68% on both arms. + +The readbacks put a stick write inside the second; that it is cpu7's excess +is not yet shown. Every counters boot so far places the +`/log` fileserver on cpu7, and the row's second begins about 8 ms after +logkeeper starts, while it is still writing the boot so far to the stick: on +both arms of pull request #728's run the stick's first sync is a record +stamped 9 to 10 ms inside the measured second (`usb-storage: disk 0 does not +implement SYNCHRONIZE CACHE`, at 1.182 s against `idle0` at 1.173 s), and cpu7 +read 1.40% with the row's own print moved after the second and 1.43% without. +A scout that discarded a warm-up second first read cpu7 at 0.12% in seconds +nothing printed into. The row now waits for the log to hold its own line +before `idle0`. Owner: the orchestrator, which holds the T14. **Exit**: a T14 +reading of the row with that wait in which cpu7's idle busy fraction is within +cpu0 to cpu6's; then this folds to the row's doc. diff --git a/tests/testcases/system.toml b/tests/testcases/system.toml index bd88580d82c..c5ace7eb7ea 100644 --- a/tests/testcases/system.toml +++ b/tests/testcases/system.toml @@ -6,12 +6,14 @@ start = ["logkeeper", "diskserver", "fileserver", "soundserver", "test-runner"] # image does. The kernel keeps the record ring and writes no file at all, so a # boot config without `logkeeper` is a boot whose `/log` is empty — # `every_boot_config_runs_logkeeper` is what refuses one. -# It claims no device and serves no port: its row's authority is `logread`, -# which is `Rights::LOG | Rights::WAIT` on a `SysCap` duplicate, and the supervisor hands -# it every program's output beside that. +# It claims no device: its row's authority is `logread`, which is +# `Rights::LOG | Rights::WAIT` on a `SysCap` duplicate, and the supervisor hands +# it every program's output beside that. `log` is the port it hands a reader +# the log on. [programs.logkeeper] service = true syscap = ["logread"] +serves = ["log"] [programs.soundserver] service = true @@ -38,8 +40,10 @@ syscap = ["rt"] # without it would make that arm vacuous rather than red. # `counters` and `trace` because `counters_read` reads every counter there is, # and narrows each away to prove its refusal. +# `log` because `counters_metal` measures its idle second only once the log +# holds its own line, read back off logkeeper. [programs.test-runner] -receives = ["soundserver", "power"] +receives = ["soundserver", "power", "log"] syscap = ["device", "dup", "logread", "power", "roster", "counters", "trace"] [programs.toybox] diff --git a/tests/toyos-rust-tests/Cargo.lock b/tests/toyos-rust-tests/Cargo.lock index da948ecead9..7cb00564b43 100644 --- a/tests/toyos-rust-tests/Cargo.lock +++ b/tests/toyos-rust-tests/Cargo.lock @@ -696,6 +696,13 @@ dependencies = [ name = "toyos-keymap" version = "0.1.0" +[[package]] +name = "toyos-logstream" +version = "0.1.0" +dependencies = [ + "toyos-abi", +] + [[package]] name = "toyos-rust-tests" version = "0.1.0" @@ -707,6 +714,7 @@ dependencies = [ "toyos", "toyos-abi", "toyos-inspect", + "toyos-logstream", "toyos-tco", "toyos-window", ] diff --git a/tests/toyos-rust-tests/Cargo.toml b/tests/toyos-rust-tests/Cargo.toml index b16d1b7fc47..0914f677b18 100644 --- a/tests/toyos-rust-tests/Cargo.toml +++ b/tests/toyos-rust-tests/Cargo.toml @@ -11,6 +11,8 @@ toyos = { path = "../../toyos" } toyos-window = { path = "../../userland/toyos-window" } toyos-tco = { path = "../../toyos-tco" } toyos-inspect = { path = "../../toyos-inspect" } +# The log as logkeeper serves it, for `counters_metal`'s wait on the log being quiet. +toyos-logstream = { path = "../../toyos-logstream" } # The reader's asker, for `hda_client_stall`. inspect = { path = "../../userland/inspect" } libloading = { git = "https://github.com/ToyOSOrg/rust_libloading", branch = "toyos-sdk-0.12" } diff --git a/tests/toyos-rust-tests/src/bin/counters_metal.rs b/tests/toyos-rust-tests/src/bin/counters_metal.rs index 97c68cc87f6..b749ddd71dd 100644 --- a/tests/toyos-rust-tests/src/bin/counters_metal.rs +++ b/tests/toyos-rust-tests/src/bin/counters_metal.rs @@ -10,6 +10,11 @@ //! three are taken**: a printed line reaches the stick within the second, //! through the `/log` fileserver on that fileserver's CPU. //! +//! **`idle0` waits for the log to be quiet** ([`settle`]): a job starts a +//! dozen milliseconds after logkeeper does, while it is still writing the +//! boot so far and the job's own launch lines to the stick, and a second +//! begun then measures that write. +//! //! **Then `loaded`: how late the round's kick reaches each CPU** while a thread //! per CPU spawns a program that exits at once, which is the load Linux's //! timer reading of this machine was taken under. A round's reader kicks every @@ -24,9 +29,12 @@ use std::sync::atomic::{AtomicBool, Ordering}; use std::time::{Duration, Instant}; use toyos::endow::{Endowments, SYSCAP_LABEL}; +use toyos::poller::{Poller, READABLE}; use toyos::syscap::SysCap; +use toyos::Pipe; use toyos_abi::counters::{Counter, RawRecord, Record}; -use toyos_abi::syscall; +use toyos_abi::syscall::{self, SyscallError}; +use toyos_logstream::{program_line, Lines, READ, SERVED, SERVICE}; /// The idle span: long enough that a CPU's busy fraction is its idle one and /// not the reads'. @@ -42,6 +50,10 @@ const SPIN: u64 = 4_000_000_000; /// (`toyos_tco::JOB_BOUND_MS`) the reads before it leave. const LOADED: Duration = Duration::from_secs(20); +/// How long [`settle`] waits for each of its lines: two of logkeeper's rounds +/// at its write budget (`userland/logkeeper/src/policy.rs`, 5 s). +const SETTLE_BOUND: Duration = Duration::from_secs(10); + /// What this binary's own children are asked to do: exit at once. const EXIT_AT_ONCE: &str = "exit-at-once"; @@ -143,11 +155,57 @@ fn print(phase: &str, read: &Read) { } } +/// Return once logkeeper has written, and made durable, everything stamped +/// before this call. +/// +/// A reader of the `log` port is handed each round only after it is on the +/// stick, so this prints a line and reads the log until that line comes back. +/// **Twice**: the round that writes the first may itself put a record in the +/// log — the stick's first sync is one — and the second writes it. +fn settle() { + let conn = toyos::endow::service(SERVICE).expect("test-runner's namespace carries the `log` port"); + conn.signal(READ).expect("logkeeper takes a reader's request"); + let header = conn.recv_header().expect("logkeeper answers a reader"); + assert_eq!(header.msg_type, SERVED, "logkeeper answered a reader with another frame"); + let _boot_so_far: u64 = conn.recv_payload(&header).expect("logkeeper's answer carries the boot's length"); + let [raw] = conn.recv_handles_exact::<1>().expect("logkeeper's answer carries a pipe"); + // SAFETY: the kernel moved this handle into this table with the frame + // that names it, and nothing else answers for it. + let pipe = unsafe { Pipe::from_raw(raw) }; + let poller = Poller::new(1); + let mut lines = Lines::new(); + let mut chunk = vec![0u8; 64 * 1024]; + for round in ["first", "second"] { + let said = format!("counters_metal settle: the log holds this {round} line"); + println!("{said}"); + let by = Instant::now() + SETTLE_BOUND; + let mut held = false; + while !held { + match pipe.read_nonblock(&mut chunk) { + Ok(0) => panic!("logkeeper closed the log before it held {said:?}"), + Ok(n) => lines.push(&chunk[..n], |line, _| { + let line = std::str::from_utf8(line).unwrap_or_default(); + held |= program_line(line).is_some_and(|line| line.text == said); + }), + Err(SyscallError::WouldBlock) => { + let left = by.checked_duration_since(Instant::now()).unwrap_or_else(|| { + panic!("the log did not hold {said:?} within {SETTLE_BOUND:?}") + }); + poller.watch(&pipe, READABLE, 0); + poller.wait(1, left.as_nanos() as u64, |_| {}); + } + Err(e) => panic!("the log's pipe refused a read: {e:?}"), + } + } + } +} + fn main() { if std::env::args().nth(1).as_deref() == Some(EXIT_AT_ONCE) { return; } let cap: SysCap = Endowments::get().take(SYSCAP_LABEL).expect("test-runner endows a capability"); + settle(); let idle0 = read(&cap); std::thread::sleep(IDLE); let idle1 = read(&cap); From 7ae16ca0620b1665e48197264c569a8568fb6cdf Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 17:56:47 +0200 Subject: [PATCH 4/8] counters row: one log-port handshake, and the judge holds the second quiet `userland/console` (`Log::subscribe`) and `counters_metal` (`settle`) each decoded logkeeper's answer to a `READ` on its `log` port by hand: the `SERVED` frame, the boot-so-far length, the one pipe handle. Two decoders of one answer meant a change to `serve.rs`'s answer could miss one, and `counters_metal`'s copy runs only on a T14 boot. `logkeeper_api::read` is now the one decoder, and both call it. It lives in a crate of its own beside `filepicker-api`, the client side of a userland server's port: `toyos-logstream` is pure (no I/O, no `unsafe`), and the SDK is a path dependency of std and cannot take `toyos-logstream`. `counters_on_metal` now reds a kernel record stamped in a whole millisecond between `idle0` and `idle1`. `settle` waits two of logkeeper's rounds on the one record kind seen so far that a round's own write stamps (the stick's first sync); nothing held that the second was then quiet. Rejudging the round-2 readbacks of 49e49a963 with this judge: head passes (no record in 1230220488..2230283529 ns), and the whole change reverted (0c27e4f56) fails on `[1.183 cpu7] usb-storage: disk 0 does not implement SYNCHRONIZE CACHE` inside 1173282164..2173482583 ns. `counters_metal` also panics by name on a served line that is not UTF-8: logkeeper writes every control byte as text, so such a line is its defect, not an empty line. Its header drops the job's start offset after logkeeper's (about 7 to 12 ms on the readbacks), a measurement. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- tests/toyos-rust-tests/Cargo.lock | 9 ++++++ tests/toyos-rust-tests/Cargo.toml | 4 ++- .../src/bin/counters_metal.rs | 26 ++++++--------- tests/toyos.rs | 13 +++++++- userland/Cargo.lock | 9 ++++++ userland/Cargo.toml | 1 + userland/console/Cargo.toml | 1 + userland/console/src/main.rs | 15 ++------- userland/logkeeper-api/Cargo.toml | 13 ++++++++ userland/logkeeper-api/src/lib.rs | 32 +++++++++++++++++++ 10 files changed, 91 insertions(+), 32 deletions(-) create mode 100644 userland/logkeeper-api/Cargo.toml create mode 100644 userland/logkeeper-api/src/lib.rs diff --git a/tests/toyos-rust-tests/Cargo.lock b/tests/toyos-rust-tests/Cargo.lock index 7cb00564b43..f803f22084c 100644 --- a/tests/toyos-rust-tests/Cargo.lock +++ b/tests/toyos-rust-tests/Cargo.lock @@ -280,6 +280,14 @@ version = "0.4.33" source = "registry+https://github.com/rust-lang/crates.io-index" checksum = "0ceec5bc11778974d1bcb055b18002eba7f4b3518b6a0081b3af5f21666da9ad" +[[package]] +name = "logkeeper-api" +version = "0.1.0" +dependencies = [ + "toyos", + "toyos-logstream", +] + [[package]] name = "mach2" version = "0.6.0" @@ -710,6 +718,7 @@ dependencies = [ "cpal", "inspect", "libloading", + "logkeeper-api", "memmap2", "toyos", "toyos-abi", diff --git a/tests/toyos-rust-tests/Cargo.toml b/tests/toyos-rust-tests/Cargo.toml index 0914f677b18..69e5693ed18 100644 --- a/tests/toyos-rust-tests/Cargo.toml +++ b/tests/toyos-rust-tests/Cargo.toml @@ -11,8 +11,10 @@ toyos = { path = "../../toyos" } toyos-window = { path = "../../userland/toyos-window" } toyos-tco = { path = "../../toyos-tco" } toyos-inspect = { path = "../../toyos-inspect" } -# The log as logkeeper serves it, for `counters_metal`'s wait on the log being quiet. +# The log as logkeeper serves it, and the asking for it, for `counters_metal`'s +# wait on the log being quiet. toyos-logstream = { path = "../../toyos-logstream" } +logkeeper-api = { path = "../../userland/logkeeper-api" } # The reader's asker, for `hda_client_stall`. inspect = { path = "../../userland/inspect" } libloading = { git = "https://github.com/ToyOSOrg/rust_libloading", branch = "toyos-sdk-0.12" } diff --git a/tests/toyos-rust-tests/src/bin/counters_metal.rs b/tests/toyos-rust-tests/src/bin/counters_metal.rs index b749ddd71dd..f8e46512ced 100644 --- a/tests/toyos-rust-tests/src/bin/counters_metal.rs +++ b/tests/toyos-rust-tests/src/bin/counters_metal.rs @@ -10,10 +10,9 @@ //! three are taken**: a printed line reaches the stick within the second, //! through the `/log` fileserver on that fileserver's CPU. //! -//! **`idle0` waits for the log to be quiet** ([`settle`]): a job starts a -//! dozen milliseconds after logkeeper does, while it is still writing the -//! boot so far and the job's own launch lines to the stick, and a second -//! begun then measures that write. +//! **`idle0` waits for the log to be quiet** ([`settle`]): a job starts while +//! logkeeper is still writing the boot so far and the job's own launch lines +//! to the stick, and a second begun then measures that write. //! //! **Then `loaded`: how late the round's kick reaches each CPU** while a thread //! per CPU spawns a program that exits at once, which is the load Linux's @@ -31,10 +30,9 @@ use std::time::{Duration, Instant}; use toyos::endow::{Endowments, SYSCAP_LABEL}; use toyos::poller::{Poller, READABLE}; use toyos::syscap::SysCap; -use toyos::Pipe; use toyos_abi::counters::{Counter, RawRecord, Record}; use toyos_abi::syscall::{self, SyscallError}; -use toyos_logstream::{program_line, Lines, READ, SERVED, SERVICE}; +use toyos_logstream::{program_line, Lines}; /// The idle span: long enough that a CPU's busy fraction is its idle one and /// not the reads'. @@ -161,17 +159,10 @@ fn print(phase: &str, read: &Read) { /// A reader of the `log` port is handed each round only after it is on the /// stick, so this prints a line and reads the log until that line comes back. /// **Twice**: the round that writes the first may itself put a record in the -/// log — the stick's first sync is one — and the second writes it. +/// log — the stick's first sync is one — and the second writes it. The +/// `counters` row reds a kernel record stamped inside the idle second. fn settle() { - let conn = toyos::endow::service(SERVICE).expect("test-runner's namespace carries the `log` port"); - conn.signal(READ).expect("logkeeper takes a reader's request"); - let header = conn.recv_header().expect("logkeeper answers a reader"); - assert_eq!(header.msg_type, SERVED, "logkeeper answered a reader with another frame"); - let _boot_so_far: u64 = conn.recv_payload(&header).expect("logkeeper's answer carries the boot's length"); - let [raw] = conn.recv_handles_exact::<1>().expect("logkeeper's answer carries a pipe"); - // SAFETY: the kernel moved this handle into this table with the frame - // that names it, and nothing else answers for it. - let pipe = unsafe { Pipe::from_raw(raw) }; + let pipe = logkeeper_api::read().unwrap_or_else(|why| panic!("test-runner's `log` port: {why}")).pipe; let poller = Poller::new(1); let mut lines = Lines::new(); let mut chunk = vec![0u8; 64 * 1024]; @@ -184,7 +175,8 @@ fn settle() { match pipe.read_nonblock(&mut chunk) { Ok(0) => panic!("logkeeper closed the log before it held {said:?}"), Ok(n) => lines.push(&chunk[..n], |line, _| { - let line = std::str::from_utf8(line).unwrap_or_default(); + let line = std::str::from_utf8(line) + .unwrap_or_else(|e| panic!("logkeeper served a line that is not UTF-8 ({e}): {line:?}")); held |= program_line(line).is_some_and(|line| line.text == said); }), Err(SyscallError::WouldBlock) => { diff --git a/tests/toyos.rs b/tests/toyos.rs index e1a14d605e5..000dc919954 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -3372,7 +3372,9 @@ const SMI_SPAN_NS: u64 = 4_444_000_000; /// reads` line names, and none stale; every CPU's performance request /// declared at boot, `pm_enable=1`, the request Linux makes on this machine /// (`tests/t14-linux/hwp-request.txt`), and its power envelope in every read -/// the one its `control_regs:` line holds. From `idle0` to `spin`, at least +/// the one its `control_regs:` line holds. No kernel record is stamped in a +/// whole millisecond between `idle0` and `idle1`: the second is the idle +/// machine's. From `idle0` to `spin`, at least /// [`SMI_SPAN_NS`] apart, every CPU's SMI count rose alike and by two or more: /// the firmware's legacy mode, the positive control ACPI stage 1's flatness /// is read against, and the row that stage changes. Across the spin every @@ -3421,6 +3423,15 @@ fn counters_on_metal(back: &metal::Readback) -> Result<(), String> { let (idle0, at0) = phase("idle0")?; let (idle1, at1) = phase("idle1")?; let (spin, at2) = phase("spin")?; + let (from_ms, to_ms) = (at0 / 1_000_000, at1 / 1_000_000); + let inside: Vec<&str> = kernel + .text() + .lines() + .filter(|line| bootlog::record_millis(line).is_some_and(|ms| from_ms < ms && ms < to_ms)) + .collect(); + if !inside.is_empty() { + return Err(format!("the idle second {at0}..{at1} ns holds kernel records: {inside:?}")); + } let linux_request = u64::from_str_radix(include_str!("t14-linux/hwp-request.txt").trim().trim_start_matches("0x"), 16) .map_err(|e| format!("t14-linux/hwp-request.txt: {e}"))?; let bsp = kernel.must_say("percpu: BSP cpu_id=0 lapic_id=")?; diff --git a/userland/Cargo.lock b/userland/Cargo.lock index 66ce73e9a07..1719b5080ff 100644 --- a/userland/Cargo.lock +++ b/userland/Cargo.lock @@ -542,6 +542,7 @@ dependencies = [ name = "console" version = "0.1.0" dependencies = [ + "logkeeper-api", "terminal", "toyos", "toyos-abi", @@ -1964,6 +1965,14 @@ dependencies = [ "toyos-wallclock", ] +[[package]] +name = "logkeeper-api" +version = "0.1.0" +dependencies = [ + "toyos", + "toyos-logstream", +] + [[package]] name = "mach2" version = "0.6.0" diff --git a/userland/Cargo.toml b/userland/Cargo.toml index 4897c7ecb57..8ee620ab1d8 100644 --- a/userland/Cargo.toml +++ b/userland/Cargo.toml @@ -16,6 +16,7 @@ members = [ "inspect", "kernelprobe", "logkeeper", + "logkeeper-api", "metalprobe", "netstack", "netstack/mdns", diff --git a/userland/console/Cargo.toml b/userland/console/Cargo.toml index 4e35113d4fc..90fbeab952e 100644 --- a/userland/console/Cargo.toml +++ b/userland/console/Cargo.toml @@ -11,6 +11,7 @@ toyos-abi = { path = "../../toyos-abi" } toyos-font = { path = "../toyos-font" } toyos-window = { path = "../toyos-window" } toyos-logstream = { path = "../../toyos-logstream" } +logkeeper-api = { path = "../logkeeper-api" } [package.metadata.toyos.host] exempt.owns = "ToyOS's framebuffer, keyboard and mouse, claimed from the kernel, on which it runs the shell" diff --git a/userland/console/src/main.rs b/userland/console/src/main.rs index d1e8d1e0a11..d888506fd31 100644 --- a/userland/console/src/main.rs +++ b/userland/console/src/main.rs @@ -36,7 +36,7 @@ use toyos::port::{self, Connector}; use toyos::surface::{self, Delivery, Host, Notice}; use toyos::{FramebufferDev, Keyboard, Pipe}; use toyos_abi::syscall::{DeviceType, SyscallError}; -use toyos_logstream::{Lines, READ, SERVED, SERVICE}; +use toyos_logstream::Lines; use window::Screen; const FONT: &str = "/system/share/fonts/JetBrainsMono-Regular-8x16.font"; @@ -78,18 +78,7 @@ impl Log { /// Ask `logkeeper`: one request, and a blocking read of its one answer. fn subscribe() -> Result { let asked_ms = toyos_abi::clock::nanos_since_boot() / 1_000_000; - let conn = endow::service(SERVICE).map_err(|e| format!("no `{SERVICE}` service: {e:?}"))?; - conn.signal(READ).map_err(|e| format!("logkeeper would not take the request: {e:?}"))?; - let header = conn.recv_header().map_err(|e| format!("logkeeper did not answer: {e:?}"))?; - if header.msg_type != SERVED { - return Err(format!("logkeeper answered frame type {}", header.msg_type)); - } - let handed: u64 = - conn.recv_payload(&header).map_err(|e| format!("logkeeper's answer is short: {e:?}"))?; - let [raw] = conn.recv_handles_exact::<1>().ok_or("logkeeper's answer carried no pipe")?; - // SAFETY: the kernel moved this handle into this table with the frame - // that names it, and nothing else answers for it. - let pipe = unsafe { Pipe::from_raw(raw) }; + let logkeeper_api::Served { pipe, boot_so_far: handed } = logkeeper_api::read()?; Ok(Self { pipe, lines: Lines::new(), handed, asked_ms, drawing: true, held: Vec::new() }) } diff --git a/userland/logkeeper-api/Cargo.toml b/userland/logkeeper-api/Cargo.toml new file mode 100644 index 00000000000..05e9d0daa5f --- /dev/null +++ b/userland/logkeeper-api/Cargo.toml @@ -0,0 +1,13 @@ +[package] +name = "logkeeper-api" +description = "Asking logkeeper for this boot's log on this machine: the request its `log` port answers with a pipe, and the decoding of that answer." +version = "0.1.0" +edition = "2021" +license = "MIT OR Apache-2.0" + +[lib] +doctest = false + +[dependencies] +toyos = { path = "../../toyos" } +toyos-logstream = { path = "../../toyos-logstream" } diff --git a/userland/logkeeper-api/src/lib.rs b/userland/logkeeper-api/src/lib.rs new file mode 100644 index 00000000000..dc32932d5fe --- /dev/null +++ b/userland/logkeeper-api/src/lib.rs @@ -0,0 +1,32 @@ +//! Asking `logkeeper` for this boot's log on this machine: one [`READ`] on +//! its [`SERVICE`] port, answered by one [`SERVED`] frame carrying how many +//! bytes are the boot so far and the read end of a pipe the log is written +//! into, from its first line. + +use toyos::endow; +use toyos::Pipe; +use toyos_logstream::{READ, SERVED, SERVICE}; + +/// `logkeeper`'s answer. +pub struct Served { + pub pipe: Pipe, + /// How many of the pipe's bytes are the boot so far. + pub boot_so_far: u64, +} + +/// Ask: one request, and a blocking read of its one answer. +pub fn read() -> Result { + let conn = endow::service(SERVICE).map_err(|e| format!("no `{SERVICE}` service: {e:?}"))?; + conn.signal(READ).map_err(|e| format!("logkeeper would not take the request: {e:?}"))?; + let header = conn.recv_header().map_err(|e| format!("logkeeper did not answer: {e:?}"))?; + if header.msg_type != SERVED { + return Err(format!("logkeeper answered frame type {}", header.msg_type)); + } + let boot_so_far: u64 = + conn.recv_payload(&header).map_err(|e| format!("logkeeper's answer is short: {e:?}"))?; + let [raw] = conn.recv_handles_exact::<1>().ok_or("logkeeper's answer carried no pipe")?; + // SAFETY: the kernel moved this handle into this table with the frame + // that names it, and nothing else answers for it. + let pipe = unsafe { Pipe::from_raw(raw) }; + Ok(Served { pipe, boot_so_far }) +} From 09a27943ea6b72007f4dd546c30dff300451177c Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 17:57:50 +0200 Subject: [PATCH 5/8] issues: close the cpu7 idle issue on its exit; the SMI issue quotes nothing t14-cpu7-idles-busier-under-toyos-than-any-cpu-under-linux.md's exit was "a T14 reading of the row with that wait in which cpu7's idle busy fraction is within cpu0 to cpu6's". The orchestrator's T14 run of 49e49a963 (pull request #728, comment 5981716271), one `testcases` boot per arm, judged by `cargo test --test toyos-build -- --metal --metal-readback counters`: - head 49e49a963, which waits for the log before `idle0`: EXIT=0, cpu7 0.46%, cpu0 to cpu6 0.46 to 0.49%. Both settle lines (1.175 s, 1.188 s) and the stick's first sync (1.183 s) precede `idle0` (1230220488 ns); no kernel record is stamped before `idle1` (2230283529 ns). One SMI fell in the second, which is why all eight sit near 0.45%. - the whole change reverted, 0c27e4f56: EXIT=0, cpu7 2.89%, cpu0 to cpu6 0.46 to 0.72%, the sync stamped 9.7 ms inside the second. So cpu7's excess was logkeeper's first rounds, written through the `/log` fileserver on cpu7 inside the measured second. The fold is `counters_metal.rs`'s header ("idle0 waits for the log to be quiet"), and `counters_on_metal` now reds a kernel record inside the second. No citation of the slug exists (`git grep`). The SMI issue quoted the row's "two idle floors", a phrase nothing in the tree says; it now states the two floors itself. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- ...er-under-toyos-than-any-cpu-under-linux.md | 36 ------------------- ...rupts-every-cpu-every-2-2-s-under-toyos.md | 6 ++-- 2 files changed, 3 insertions(+), 39 deletions(-) delete mode 100644 issues/t14-cpu7-idles-busier-under-toyos-than-any-cpu-under-linux.md diff --git a/issues/t14-cpu7-idles-busier-under-toyos-than-any-cpu-under-linux.md b/issues/t14-cpu7-idles-busier-under-toyos-than-any-cpu-under-linux.md deleted file mode 100644 index 2f48c9c0efa..00000000000 --- a/issues/t14-cpu7-idles-busier-under-toyos-than-any-cpu-under-linux.md +++ /dev/null @@ -1,36 +0,0 @@ ---- -status: open -kind: defect -opened: 2026-10-04 ---- - -# T14 cpu7 idles busier under ToyOS than any CPU under Linux - -The `counters` metal row reads each CPU's MPERF over its stamp across the idle -second between its `idle0` and `idle1` reads. Linux's turbostat on the same -machine, idle (`tests/t14-linux/turbostat-idle.txt`), reads 0.11 to 0.36% -machine-wide per 10 s and no CPU above 0.69%. - -cpu7 reads about four times that, on every boot so far: 1.45% at `ce1786ff0` -(pull request #705), 1.42% at `a059144e2`, and 1.86% and 1.85% on the two arms -of pull request #725's run. - -cpu0 read 1.37% and 1.35% on the first two boots. That was the idle loop -spinning on an `irq_ring` record `xhci::poll_if_pending` left when a USB-stick -transfer held `XHCI`; since `XHCI` became an `OwedLock`, cpu0 reads 0.50% with -the change (`a65205a81`) and 1.77% with the whole change reverted -(`b0cae9a19`), cpu1 to cpu6 0.45 to 0.68% on both arms. - -The readbacks put a stick write inside the second; that it is cpu7's excess -is not yet shown. Every counters boot so far places the -`/log` fileserver on cpu7, and the row's second begins about 8 ms after -logkeeper starts, while it is still writing the boot so far to the stick: on -both arms of pull request #728's run the stick's first sync is a record -stamped 9 to 10 ms inside the measured second (`usb-storage: disk 0 does not -implement SYNCHRONIZE CACHE`, at 1.182 s against `idle0` at 1.173 s), and cpu7 -read 1.40% with the row's own print moved after the second and 1.43% without. -A scout that discarded a warm-up second first read cpu7 at 0.12% in seconds -nothing printed into. The row now waits for the log to hold its own line -before `idle0`. Owner: the orchestrator, which holds the T14. **Exit**: a T14 -reading of the row with that wait in which cpu7's idle busy fraction is within -cpu0 to cpu6's; then this folds to the row's doc. diff --git a/issues/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md b/issues/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md index 32c482ad59a..aabb1e83a96 100644 --- a/issues/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md +++ b/issues/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md @@ -30,9 +30,9 @@ lines are quoted on #681 (comment 5962619169; the boot itself in comment idle seconds between counters rounds; the commit that added this bullet carries its per-second lines. In the five whose SMI count moved by one, cpu2, cpu4, cpu5 and cpu6, which ran none of the log's work, read 4535 to - 4571 ppm busy; in the seven where it did not, 6 to 285 ppm. That is the - `counters` row's "two idle floors", about 0.45% and 0.03% or less: a 1 s idle - second catches a 2.2 s-period SMI or does not. + 4571 ppm busy; in the seven where it did not, 6 to 285 ppm. So the + `counters` row's idle second reads one of two floors, about 0.45% or 0.03% + and less: a 1 s second catches a 2.2 s-period SMI or does not. - **Linux, in one condition, read none.** On the same machine under Ubuntu's `6.8.0-142-generic`, `perf stat -a -A -e msr/smi/` read 0 on every CPU over 120.378 s beside `rtla timerlat top -q -d 2m --dma-latency 0`, which holds From 19ac555c0fe1b63a26a5ebcc57a26080b156b0a7 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 18:25:16 +0200 Subject: [PATCH 6/8] counters row: the judge refuses a program's line inside the idle second too The quiet check read only kernel records ([... cpuN]), so a program line stamped inside the second -- the row's own idle0 print moved back before idle1, the regression "measure first, print after" exists to prevent -- passed it. toyos-logstream gains program_ms beside record_ms: a program line's milliseconds, found from the tag back past the optional pid=, tid= and severity words, since the wall clock before it is two words or none. The judge reads the whole log with both. The window now includes the millisecond each edge falls in: a line stamped in idle0's millisecond may follow the read, and lines carry no finer time. With the edges excluded, the review's mutation (print idle0 right after reading it) can land its 81 lines in idle0's own millisecond and pass. The SMI issue cites 35cd63142, which lands and carries the scout's image hash and per-second lines, rather than 22d241174, reachable only from a branch that goes. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- ...rupts-every-cpu-every-2-2-s-under-toyos.md | 6 +-- .../src/bin/counters_metal.rs | 2 +- tests/toyos.rs | 17 +++++--- toyos-logstream/src/lib.rs | 41 +++++++++++++++++++ 4 files changed, 56 insertions(+), 10 deletions(-) diff --git a/issues/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md b/issues/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md index aabb1e83a96..de69458b088 100644 --- a/issues/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md +++ b/issues/the-t14s-firmware-interrupts-every-cpu-every-2-2-s-under-toyos.md @@ -26,9 +26,9 @@ lines are quoted on #681 (comment 5962619169; the boot itself in comment CPUs waiting on a lock across a step, which went 4,503,694 and 4,554,675 ns between two turns of their own spin. - **MPERF reads the stop as about 4.55 ms of C0 on every CPU.** One T14 boot - of a scout image without ACPI mode (`22d241174`) read twelve back-to-back - idle seconds between counters rounds; the commit that added this bullet - carries its per-second lines. In the five whose SMI count moved by one, + of a scout image without ACPI mode read twelve back-to-back idle seconds + between counters rounds; `35cd63142`, which added this bullet, carries its + image hash and per-second lines. In the five whose SMI count moved by one, cpu2, cpu4, cpu5 and cpu6, which ran none of the log's work, read 4535 to 4571 ppm busy; in the seven where it did not, 6 to 285 ppm. So the `counters` row's idle second reads one of two floors, about 0.45% or 0.03% diff --git a/tests/toyos-rust-tests/src/bin/counters_metal.rs b/tests/toyos-rust-tests/src/bin/counters_metal.rs index f8e46512ced..4d023c89835 100644 --- a/tests/toyos-rust-tests/src/bin/counters_metal.rs +++ b/tests/toyos-rust-tests/src/bin/counters_metal.rs @@ -160,7 +160,7 @@ fn print(phase: &str, read: &Read) { /// stick, so this prints a line and reads the log until that line comes back. /// **Twice**: the round that writes the first may itself put a record in the /// log — the stick's first sync is one — and the second writes it. The -/// `counters` row reds a kernel record stamped inside the idle second. +/// `counters` row reds any line stamped inside the idle second. fn settle() { let pipe = logkeeper_api::read().unwrap_or_else(|why| panic!("test-runner's `log` port: {why}")).pipe; let poller = Poller::new(1); diff --git a/tests/toyos.rs b/tests/toyos.rs index d7b903dab0b..d42f80f52eb 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -3438,9 +3438,10 @@ const SMI_SPAN_NS: u64 = 4_444_000_000; /// reads` line names, and none stale; every CPU's performance request /// declared at boot, `pm_enable=1`, the request Linux makes on this machine /// (`tests/t14-linux/hwp-request.txt`), and its power envelope in every read -/// the one its `control_regs:` line holds. No kernel record is stamped in a -/// whole millisecond between `idle0` and `idle1`: the second is the idle -/// machine's. From `idle0` to `spin`, at least +/// the one its `control_regs:` line holds. No line, the kernel's or a +/// program's, is stamped in a millisecond from `idle0`'s to `idle1`'s, either +/// edge's included because a line stamped in it may follow the read: the +/// second is the idle machine's. From `idle0` to `spin`, at least /// [`SMI_SPAN_NS`] apart, every CPU's SMI count rose alike and by two or more: /// the firmware's legacy mode, the positive control ACPI stage 1's flatness /// is read against, and the row that stage changes. Across the spin every @@ -3490,13 +3491,17 @@ fn counters_on_metal(back: &metal::Readback) -> Result<(), String> { let (idle1, at1) = phase("idle1")?; let (spin, at2) = phase("spin")?; let (from_ms, to_ms) = (at0 / 1_000_000, at1 / 1_000_000); - let inside: Vec<&str> = kernel + let inside: Vec<&str> = log .text() .lines() - .filter(|line| bootlog::record_millis(line).is_some_and(|ms| from_ms < ms && ms < to_ms)) + .filter(|line| { + toyos_logstream::record_ms(line) + .or_else(|| toyos_logstream::program_ms(line)) + .is_some_and(|ms| (from_ms..=to_ms).contains(&ms)) + }) .collect(); if !inside.is_empty() { - return Err(format!("the idle second {at0}..{at1} ns holds kernel records: {inside:?}")); + return Err(format!("the idle second {at0}..{at1} ns holds lines: {inside:?}")); } let linux_request = u64::from_str_radix(include_str!("t14-linux/hwp-request.txt").trim().trim_start_matches("0x"), 16) .map_err(|e| format!("t14-linux/hwp-request.txt: {e}"))?; diff --git a/toyos-logstream/src/lib.rs b/toyos-logstream/src/lib.rs index 7abd58aee23..844a99adf38 100644 --- a/toyos-logstream/src/lib.rs +++ b/toyos-logstream/src/lib.rs @@ -289,6 +289,26 @@ pub fn record_ms(line: &str) -> Option { secs.checked_mul(1_000)?.checked_add(millis) } +/// The milliseconds since boot a program's line carries ([`ProgramLine`]), or +/// `None` for any other line. +/// +/// **Found from the tag back rather than by position**: the wall clock before it +/// is two words or none, and the words after it are each there or not. +pub fn program_ms(line: &str) -> Option { + let (head, _) = line.strip_prefix(OPEN)?.split_once(CLOSE)?; + let mut words = head.rsplit(' '); + Tag::new(words.next()?)?; + let field = words.find(|word| { + !(word.starts_with("pid=") + || word.starts_with("tid=") + || [Severity::Warn, Severity::Error, Severity::Alert].iter().any(|s| s.word() == Some(word))) + })?; + let (secs, millis) = field.split_once('.')?; + let secs: u64 = secs.parse().ok()?; + let millis: u64 = millis.parse().ok()?; + secs.checked_mul(1_000)?.checked_add(millis) +} + /// Whether `line` opens as a program's line: what a judge of the kernel's /// records leaves out. pub fn is_program_line(line: &str) -> bool { @@ -554,6 +574,27 @@ mod tests { assert_eq!(record_ms(""), None); } + /// Every head [`ProgramLine`] writes reads back to the time it carries, and + /// no text after the head answers for it. + #[test] + fn a_program_lines_time_is_read_inside_its_head_and_nowhere_else() { + let tag = Tag::new("test-runner").expect("a tag"); + for stamp in ["", "2026-09-24 10:00:00", "---------- --------"] { + for severity in [Severity::Info, Severity::Warn, Severity::Error, Severity::Alert] { + for (tid, pid) in [(0, None), (3, None), (0, Some(9)), (3, Some(9))] { + let line = + format!("{}", ProgramLine { stamp, at_ns: 1_500_999_999, severity, tid, pid, tag, text: b"9.000" }); + assert_eq!(program_ms(&line), Some(1_500), "{line:?}"); + } + } + } + assert_eq!(program_ms("[2026-09-07 22:57:46 3.109 cpu1] exit: a pid=7"), None); + assert_eq!(program_ms("{2026-09-24 10:00:00 netstack} 1.000"), None); + assert_eq!(program_ms("{1.000 a b} x"), None); + assert_eq!(program_ms(" its second line"), None); + assert_eq!(program_ms(""), None); + } + #[test] fn a_kernel_record_and_its_continuation_are_no_programs() { assert_eq!(program_line("[2026-09-24 10:00:00 1.216 cpu0] Boot: complete (1216ms)"), None); From 78c21c5755d3869a4b26e890c024ae18e21e97e2 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 19:59:57 +0200 Subject: [PATCH 7/8] counters row: the idle second starts where no kernel report is due The full Drive-mode T14 suite at 19ac555c0 red the `counters` row in its full profile: the job's idle second ran 10.474..11.474 s, and the kernel's idle report (`scheduler::log_health`: `sched:` per CPU and the machine's `PMM:`) printed at 11.254 s inside it. In the isolated `counters` boots the second ran at ~1.2 s, just after every CPU's first report at boot, so the row's verdict depended on where in the boot the job ran. The report is legitimate kernel work with a declared cadence (`SNAPSHOT_INTERVAL`, 10 s): each CPU prints on its first idle trip at least that long after its last, and the machine's `PMM:` on the same rule from the first idle trip of all. It never wakes a CPU, so one overdue prints at whatever next wakes it. In that boot every CPU first printed at 1.135 s, so all were due from ~11.135 s, and the first wake after (11.254 s) set off the whole round. So `counters_metal` reads the report's schedule off the log it already reads to settle: each CPU's last `sched:` record, the last `PMM:` (or, before the first, the earliest `trips=1`), each due `SNAPSHOT_INTERVAL` later. When one falls due before the second could end, it sleeps until every report is due, puts a thread on every CPU for 20 ms so each passes its idle loop and prints what it owes, settles again and rechecks. A report the log does not hold counts as due now. The whole wait keeps the 20 s ceiling the two settle waits had, so the job's budget is unchanged. The judge is unchanged and stays the oracle: any line in the second reds the row. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- .../src/bin/counters_metal.rs | 200 ++++++++++++++---- 1 file changed, 159 insertions(+), 41 deletions(-) diff --git a/tests/toyos-rust-tests/src/bin/counters_metal.rs b/tests/toyos-rust-tests/src/bin/counters_metal.rs index 4d023c89835..00720c7fff4 100644 --- a/tests/toyos-rust-tests/src/bin/counters_metal.rs +++ b/tests/toyos-rust-tests/src/bin/counters_metal.rs @@ -10,9 +10,15 @@ //! three are taken**: a printed line reaches the stick within the second, //! through the `/log` fileserver on that fileserver's CPU. //! -//! **`idle0` waits for the log to be quiet** ([`settle`]): a job starts while -//! logkeeper is still writing the boot so far and the job's own launch lines -//! to the stick, and a second begun then measures that write. +//! **`idle0` waits for the log to be quiet** ([`Log::settle`]): a job starts +//! while logkeeper is still writing the boot so far and the job's own launch +//! lines to the stick, and a second begun then measures that write. +//! +//! **And for a second the kernel's idle report cannot reach** ([`quiet`]): an +//! idle CPU prints `sched:`, and one of them `PMM:`, on its first idle trip +//! [`REPORT`] after its last, so a report is due at a time the log says, and +//! one overdue prints at whatever next wakes its CPU. The second starts only +//! where none falls due before it ends, wherever in a boot the job runs. //! //! **Then `loaded`: how late the round's kick reaches each CPU** while a thread //! per CPU spawns a program that exits at once, which is the load Linux's @@ -23,6 +29,7 @@ //! kicks. A round across which a CPU's SMI count moved is dropped, since an //! SMI stops every CPU, and so is one with a CPU stale. +use std::collections::BTreeMap; use std::process::Command; use std::sync::atomic::{AtomicBool, Ordering}; use std::time::{Duration, Instant}; @@ -32,7 +39,7 @@ use toyos::poller::{Poller, READABLE}; use toyos::syscap::SysCap; use toyos_abi::counters::{Counter, RawRecord, Record}; use toyos_abi::syscall::{self, SyscallError}; -use toyos_logstream::{program_line, Lines}; +use toyos_logstream::{program_line, record_ms, Lines}; /// The idle span: long enough that a CPU's busy fraction is its idle one and /// not the reads'. @@ -48,9 +55,25 @@ const SPIN: u64 = 4_000_000_000; /// (`toyos_tco::JOB_BOUND_MS`) the reads before it leave. const LOADED: Duration = Duration::from_secs(20); -/// How long [`settle`] waits for each of its lines: two of logkeeper's rounds -/// at its write budget (`userland/logkeeper/src/policy.rs`, 5 s). -const SETTLE_BOUND: Duration = Duration::from_secs(10); +/// How long [`quiet`] may take, a hang ceiling: a [`REPORT`] of waiting for +/// every report to fall due, and two of logkeeper's rounds at its write budget +/// (`userland/logkeeper/src/policy.rs`, 5 s). The job list's bound +/// (`toyos_tco::JOB_BOUND_MS`) holds it, the spin and [`LOADED`]. +const QUIET_BOUND: Duration = Duration::from_secs(20); + +/// The kernel's idle report period, `SNAPSHOT_INTERVAL` in +/// `kernel/src/scheduler.rs`: a CPU's next report is due this long after +/// the clock read its last one followed. +const REPORT: Duration = Duration::from_secs(10); + +/// How far a report's due time and the second's end are each held from the +/// other: a stamp follows the clock read its deadline was set from by the +/// formatting between them, and `idle1` follows [`IDLE`] by a wake and a read. +const CLEAR: Duration = Duration::from_millis(50); + +/// How long [`quiet`] keeps a thread on every CPU, so that each one wakes +/// and passes its idle loop, where an overdue report prints. +const WAKE: Duration = Duration::from_millis(20); /// What this binary's own children are asked to do: exit at once. const EXIT_AT_ONCE: &str = "exit-at-once"; @@ -153,51 +176,146 @@ fn print(phase: &str, read: &Read) { } } -/// Return once logkeeper has written, and made durable, everything stamped -/// before this call. -/// -/// A reader of the `log` port is handed each round only after it is on the -/// stick, so this prints a line and reads the log until that line comes back. -/// **Twice**: the round that writes the first may itself put a record in the -/// log — the stick's first sync is one — and the second writes it. The -/// `counters` row reds any line stamped inside the idle second. -fn settle() { - let pipe = logkeeper_api::read().unwrap_or_else(|why| panic!("test-runner's `log` port: {why}")).pipe; - let poller = Poller::new(1); - let mut lines = Lines::new(); - let mut chunk = vec![0u8; 64 * 1024]; - for round in ["first", "second"] { - let said = format!("counters_metal settle: the log holds this {round} line"); - println!("{said}"); - let by = Instant::now() + SETTLE_BOUND; - let mut held = false; - while !held { - match pipe.read_nonblock(&mut chunk) { - Ok(0) => panic!("logkeeper closed the log before it held {said:?}"), - Ok(n) => lines.push(&chunk[..n], |line, _| { - let line = std::str::from_utf8(line) - .unwrap_or_else(|e| panic!("logkeeper served a line that is not UTF-8 ({e}): {line:?}")); - held |= program_line(line).is_some_and(|line| line.text == said); - }), - Err(SyscallError::WouldBlock) => { - let left = by.checked_duration_since(Instant::now()).unwrap_or_else(|| { - panic!("the log did not hold {said:?} within {SETTLE_BOUND:?}") - }); - poller.watch(&pipe, READABLE, 0); - poller.wait(1, left.as_nanos() as u64, |_| {}); +/// What the log says of the kernel's idle report, read off its records. +#[derive(Default)] +struct Reports { + /// Each CPU's last `sched:` record, in milliseconds since boot. + last: BTreeMap, + /// Each CPU's first, `trips=1`: the earliest is the trip that set the + /// first `PMM:` deadline. + first: BTreeMap, + /// The last `PMM:` record. + pmm: Option, +} + +impl Reports { + fn see(&mut self, line: &str) { + let (Some(ms), Some((_, said))) = (record_ms(line), line.split_once("] ")) else { return }; + if let Some(rest) = said.strip_prefix("sched: cpu=") { + let cpu = rest.split(' ').next().and_then(|cpu| cpu.parse().ok()); + let cpu = cpu.unwrap_or_else(|| panic!("a `sched:` record names no cpu: {line:?}")); + self.last.insert(cpu, ms); + if rest.ends_with(" trips=1") { + self.first.insert(cpu, ms); + } + } else if said.starts_with("PMM: ") { + self.pmm = Some(ms); + } + } + + /// When, in nanoseconds since boot, each report may next print: every + /// CPU's, then the machine's `PMM:`, each [`CLEAR`] early. One the log + /// does not hold may print now. + fn due(&self, cpus: u64) -> Vec { + let after = |ms: Option| { + ms.map_or(0, |ms| (ms * 1_000_000 + REPORT.as_nanos() as u64).saturating_sub(CLEAR.as_nanos() as u64)) + }; + let first_trip = (self.first.len() as u64 == cpus).then(|| self.first.values().copied().min()).flatten(); + (0..cpus).map(|cpu| after(self.last.get(&cpu).copied())).chain([after(self.pmm.or(first_trip))]).collect() + } +} + +/// This boot's log as logkeeper serves it, from its first line. +struct Log { + pipe: toyos::Pipe, + poller: Poller, + lines: Lines, + chunk: Vec, + reports: Reports, + said: u32, +} + +impl Log { + fn open() -> Self { + let pipe = logkeeper_api::read().unwrap_or_else(|why| panic!("test-runner's `log` port: {why}")).pipe; + Self { pipe, poller: Poller::new(1), lines: Lines::new(), chunk: vec![0u8; 64 * 1024], reports: Reports::default(), said: 0 } + } + + /// Return once logkeeper has written, and made durable, everything + /// stamped before this call. + /// + /// A reader of the `log` port is handed each round only after it is on + /// the stick, so this prints a line and reads the log until that line + /// comes back. **Twice**: the round that writes the first may itself put a + /// record in the log — the stick's first sync is one — and the second + /// writes it. The `counters` row reds any line stamped inside the idle + /// second. + fn settle(&mut self, by: Instant) { + for _ in 0..2 { + self.said += 1; + let said = format!("counters_metal settle: the log holds line {}", self.said); + println!("{said}"); + let mut held = false; + while !held { + match self.pipe.read_nonblock(&mut self.chunk) { + Ok(0) => panic!("logkeeper closed the log before it held {said:?}"), + Ok(n) => { + let reports = &mut self.reports; + self.lines.push(&self.chunk[..n], |line, _| { + let line = std::str::from_utf8(line) + .unwrap_or_else(|e| panic!("logkeeper served a line that is not UTF-8 ({e}): {line:?}")); + reports.see(line); + held |= program_line(line).is_some_and(|line| line.text == said); + }) + } + Err(SyscallError::WouldBlock) => { + let left = by.checked_duration_since(Instant::now()).unwrap_or_else(|| { + panic!("the log did not hold {said:?} within {QUIET_BOUND:?} of the job's start") + }); + self.poller.watch(&self.pipe, READABLE, 0); + self.poller.wait(1, left.as_nanos() as u64, |_| {}); + } + Err(e) => panic!("the log's pipe refused a read: {e:?}"), } - Err(e) => panic!("the log's pipe refused a read: {e:?}"), } } } } +/// Return with the log written and no report of the kernel's due before +/// [`IDLE`] and [`CLEAR`] from now. +/// +/// Where one would be, this waits until every report is due and puts a thread +/// on every CPU, so each prints what it owes now and owes nothing for a +/// [`REPORT`] after. **A sleep, not a wait on an event**: a report falls due +/// on the clock alone and says so to nobody. +fn quiet() { + let by = Instant::now() + QUIET_BOUND; + let cpus = u64::from(syscall::cpu_count()); + let mut log = Log::open(); + loop { + log.settle(by); + let now = toyos_abi::clock::nanos_since_boot(); + let due = log.reports.due(cpus); + let first = *due.iter().min().expect("a machine has a cpu"); + let last = *due.iter().max().expect("a machine has a cpu"); + if first > now + (IDLE + CLEAR).as_nanos() as u64 { + return; + } + let wait = Duration::from_nanos(last.saturating_sub(now)) + 2 * CLEAR; + if Instant::now() + wait > by { + panic!("no idle second clear of the kernel's report within {QUIET_BOUND:?}: due at {due:?} ns, now {now} ns"); + } + std::thread::sleep(wait); + std::thread::scope(|s| { + for _ in 0..cpus { + s.spawn(|| { + let begun = Instant::now(); + while begun.elapsed() < WAKE { + std::hint::spin_loop(); + } + }); + } + }); + } +} + fn main() { if std::env::args().nth(1).as_deref() == Some(EXIT_AT_ONCE) { return; } let cap: SysCap = Endowments::get().take(SYSCAP_LABEL).expect("test-runner endows a capability"); - settle(); + quiet(); let idle0 = read(&cap); std::thread::sleep(IDLE); let idle1 = read(&cap); From e2ed813d143882e71878fb206f723f7d2dfe1100 Mon Sep 17 00:00:00 2001 From: japabu Date: Sun, 4 Oct 2026 21:40:12 +0200 Subject: [PATCH 8/8] The kernel's idle report is gone, and the counters row measures the second it settles to The owner ruled on 2026-10-04, asked whether to remove the ~10 s idle status report (`sched:`/`PMM:`) from the idle loop, choosing "Remove it entirely": "Delete the periodic report and its counters; hang triage uses the trace diary and panic records instead." Kernel: `scheduler::log_health` and its call on every idle trip go, with `SNAPSHOT_INTERVAL`, `NEXT_HEALTH`, `IDLE_TRIPS` and the `PMM:` deadline. `pmm::dump_stats` goes with the counters only it read: `CATEGORY_STATS`, `LAST_DUMP_NANOS`, `LAST_ALLOC`, and `Category`, which existed only to index them, so `alloc_page`, `claim`, `alloc_contiguous` and `PageAlloc::new` take no category and `PhysPage` carries none. The driver's `parked_len`, `dying_len` and `stopped_len` had no other caller, and the scheduler core's `dying_len` and `stopped_len` none but its own tests, which now count `dying()` and `stopped()`. The idle loop no longer reads the clock or counts a trip for a report. Row: `counters_metal.rs` returns to `19ac555c0`'s, the settle and the judge with no prediction of the report: `Reports`, `quiet`, `REPORT`, `CLEAR`, `WAKE` and the sleep are deleted. Review round 3's design BLOCKER is closed by the ruling rather than by a second reader of the kernel's cadence. Issues: the three that read hang triage off `sched:` lines say the report is gone and quote the ruling; `toyos-explains-itself` no longer lists `PMM:`/`sched:` among the log's numbers; the 2 MiB track says where stage 3's floor is read now; the pipe-lock issue's quoted call loses its category. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01WcU2Dsw6mDYtwYfzVHPzM8 --- ...-under-host-load-can-go-silent-for-15-s.md | 13 +- ...opped-answering-and-no-capture-says-why.md | 12 +- ...b-pages-and-that-caps-the-process-count.md | 5 +- ...sole-output-the-harness-is-slow-to-read.md | 3 + .../the-global-pipe-lock-spans-a-user-copy.md | 2 +- issues/toyos-explains-itself.md | 2 +- kernel/pure/sched/cpu.rs | 49 ++--- kernel/src/arch/x86_64/vtd/table.rs | 4 +- kernel/src/clock.rs | 2 +- kernel/src/drivers/gop.rs | 2 +- kernel/src/drivers/virtio_gpu.rs | 6 +- kernel/src/elf/cache.rs | 4 +- kernel/src/elf/mod.rs | 2 +- kernel/src/loader/mod.rs | 2 +- kernel/src/loader/tls.rs | 2 +- kernel/src/mm/alloc.rs | 2 +- kernel/src/mm/dma.rs | 2 +- kernel/src/mm/pmm.rs | 115 +--------- kernel/src/object/shm.rs | 2 +- kernel/src/pipe.rs | 2 +- kernel/src/process.rs | 6 +- kernel/src/sched/driver.rs | 17 -- kernel/src/sched/idle_stack.rs | 2 +- kernel/src/scheduler.rs | 68 +----- kernel/src/syscall/vm.rs | 4 +- .../src/bin/counters_metal.rs | 200 ++++-------------- 26 files changed, 121 insertions(+), 409 deletions(-) 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 9fe7bf58773..ebc005a0361 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 @@ -17,9 +17,9 @@ compiler; the branch `wt/toyos-counterstall` at `bc5f36c7b`, whose harness keeps every line the guest said. `test_rs_counters_read` started at 4.031, spawned at 4.044, two of its threads exited (4.174 and 4.576), and then the console carried nothing until the harness gave up 15 s later. No CPU printed -`sched: cpu=` again, though each last printed one at 2.17-2.22 s and prints -again on its first idle trip 10 s on (`scheduler::log_health`): no CPU went -idle, or the console stopped. No register capture of that guest exists. One +`sched: cpu=` again, though each last printed one at 2.17-2.22 s and that +kernel printed again on a CPU's first idle trip 10 s on: no CPU went idle, or +the console stopped. No register capture of that guest exists. One in 30 guests of that loop; none in the 1724 guests that followed on the same host at load 15-60. @@ -39,6 +39,13 @@ once per answering CPU (`762a524f0`, reverted in the next commit) changed neither the kicks taken during the read (median 116/122/118, fix/base/fix) nor its span, so the waiter-list contention is not shown to be the cause. +**The idle report is gone.** The owner ruled on 2026-10-04, choosing "Remove +it entirely": "Delete the periodic report and its counters; hang triage uses +the trace diary and panic records instead." A silent guest no longer says +whether its CPUs went idle by a `sched:` line's absence; its diary +(`kernel/src/trace.rs`, read by `/system/bin/trace`) and its panic records +(`kernel/src/panic.rs`, `kernel/src/blackbox.rs`) do. + Exit: the cause of the silence is named from a capture of a silent guest (registers over QMP before anything else touches it), and fixed with the evidence, or shown to be the host stopping the guest. diff --git a/issues/a-shared-boot-stopped-answering-and-no-capture-says-why.md b/issues/a-shared-boot-stopped-answering-and-no-capture-says-why.md index f3e2025dbe8..5c3f09cea8f 100644 --- a/issues/a-shared-boot-stopped-answering-and-no-capture-says-why.md +++ b/issues/a-shared-boot-stopped-answering-and-no-capture-says-why.md @@ -50,8 +50,16 @@ would leave a whole boot idle straight after a sibling thread's clean exit. path's two posts. **Exit condition.** A capture taken from a boot that has actually stopped, which -names the first waiter and the subject it waits on — the blocked-task dump, or a -guest whose own last line is not the periodic reporter. +names the first waiter and the subject it waits on — the blocked-task dump, or +that boot's trace diary and panic records. + +**The periodic reporter is gone.** The owner ruled on 2026-10-04, choosing +"Remove it entirely": "Delete the periodic report and its counters; hang +triage uses the trace diary and panic records instead." The `sched:` and +`PMM:` lines the sightings below quote are no longer printed, so a stopped +boot is told from a healthy idle one by its diary (`kernel/src/trace.rs`, read +by `/system/bin/trace`) and its panic records (`kernel/src/panic.rs`, +`kernel/src/blackbox.rs`). **Sighting, 2026-09-25.** `cargo test` (the full fast tier) on the dev host, 12 wide, TCG, on `wt/toyos-inspect` at `9ff0d254`. That branch touches no file under `kernel/`, diff --git a/issues/process-memory-is-2-mib-pages-and-that-caps-the-process-count.md b/issues/process-memory-is-2-mib-pages-and-that-caps-the-process-count.md index 11d066e2a44..ca1627505fa 100644 --- a/issues/process-memory-is-2-mib-pages-and-that-caps-the-process-count.md +++ b/issues/process-memory-is-2-mib-pages-and-that-caps-the-process-count.md @@ -28,7 +28,10 @@ A thousand such processes is the whole 16 GB machine. Packing a process's small regions into one shared page lowers the floor to about 4 MB, since every stack still needs its own page with an unmapped neighbour as its guard; that moves the ceiling to a few thousand and not past it. x86-64 offers no page -size between 4 KiB and 2 MiB. +size between 4 KiB and 2 MiB. That `PMM:` record and its rows went with the +kernel's idle report (the owner's ruling of 2026-10-04: "Delete the periodic +report and its counters"); stage 3's floor is read from the used memory +`SYS_SYSINFO` reports. **What this removes as a side effect:** a device window mapped at 4 KiB no longer shares a 2 MiB page with a neighbour's registers, so the relocation diff --git a/issues/qemu-drops-console-output-the-harness-is-slow-to-read.md b/issues/qemu-drops-console-output-the-harness-is-slow-to-read.md index c95daf9a9ff..b0021e4b007 100644 --- a/issues/qemu-drops-console-output-the-harness-is-slow-to-read.md +++ b/issues/qemu-drops-console-output-the-harness-is-slow-to-read.md @@ -57,6 +57,9 @@ running through the silence; the capture cannot tell a dropped marker from a `lo forwarding. The tree moved `rust` from `aca5f527f` to `9151571ca`, which changes std's exported C `malloc`, `free` and `realloc` in every Rust guest program, so reading it as this loss rests on that change being off its path. Owner: the orchestrator. +That kernel's ten-second report is gone: the owner ruled on 2026-10-04, choosing "Remove it +entirely": "Delete the periodic report and its counters; hang triage uses the trace diary and +panic records instead." A later sighting tells a live kernel from a stopped one by those. ## Exit condition diff --git a/issues/the-global-pipe-lock-spans-a-user-copy.md b/issues/the-global-pipe-lock-spans-a-user-copy.md index f2efd081b3a..f52db2d1e28 100644 --- a/issues/the-global-pipe-lock-spans-a-user-copy.md +++ b/issues/the-global-pipe-lock-spans-a-user-copy.md @@ -18,7 +18,7 @@ The bulk copy is inside that closure, not outside it. The size is bounded only by the ring: `PIPE_SIZE = PAGE_2M` (`pipe.rs:104`), `PAGE_2M = 2 * 1024 * 1024` (`toyos-userbound/src/span.rs:27`), and `capacity = total_size - size_of::()` (`ring.rs:60`) with `RingHeader` `#[repr(C, align(64))]` holding one `AtomicU32` (`ring.rs:24-27`) — so **2,097,088 bytes** is the largest single copy under the lock. Nothing above caps it: `SYS_READ`/`SYS_WRITE` pass the userland length straight through (`kernel/src/syscall/dispatch.rs:110-116`), `object::ops::try_read` hands the full window to `pipe::try_read` (`kernel/src/object/ops.rs:339-340`), and the only other bound, `user_ptr::window` (`user_ptr.rs:269`), requires physical contiguity — which a demand-paged 2 MiB frame satisfies exactly. -A pipe's **first** write is worse, because the page is allocated lazily under the same lock. `try_write` calls `pipe.back()` (`pipe.rs:250`), which calls `pmm::alloc_page(pmm::Category::Pipe)` (`pipe.rs:148`). That takes `BITMAP` nested inside `PIPES` (`kernel/src/mm/pmm.rs:221`), linearly scans up to the whole physical bitmap for a free frame (`pmm.rs:224-241`), and then `write_bytes(..., 0, PAGE_2M)` — a 2 MiB zeroing (`pmm.rs:233-237`) — before `Ring::new` and the user copy that follows it. +A pipe's **first** write is worse, because the page is allocated lazily under the same lock. `try_write` calls `pipe.back()` (`pipe.rs:250`), which calls `pmm::alloc_page()` (`pipe.rs:148`). That takes `BITMAP` nested inside `PIPES` (`kernel/src/mm/pmm.rs:221`), linearly scans up to the whole physical bitmap for a free frame (`pmm.rs:224-241`), and then `write_bytes(..., 0, PAGE_2M)` — a 2 MiB zeroing (`pmm.rs:233-237`) — before `Ring::new` and the user copy that follows it. ## What queues behind it diff --git a/issues/toyos-explains-itself.md b/issues/toyos-explains-itself.md index 795ee3852ef..b5bc757632e 100644 --- a/issues/toyos-explains-itself.md +++ b/issues/toyos-explains-itself.md @@ -8,7 +8,7 @@ opened: 2026-10-04 ToyOS answers what it is doing, what it did and what it is made of from inside itself, with programs it ships. Today the answers are scattered: the -log carries numbers in prose (`irq:`, `tlb:`, `PMM:`, `sched:`, `syscalls:`), +log carries numbers in prose (`irq:`, `tlb:`, `syscalls:`), the diary computes no lateness, nothing reads RAPL or C-state residency, and a process's memory is a byte sum that reads 0 under contention. diff --git a/kernel/pure/sched/cpu.rs b/kernel/pure/sched/cpu.rs index b622316e1ca..958a19bbf0f 100644 --- a/kernel/pure/sched/cpu.rs +++ b/kernel/pure/sched/cpu.rs @@ -398,18 +398,10 @@ impl CpuSched { self.dying.iter().map(|corpse| &corpse.task) } - pub fn dying_len(&self) -> usize { - self.dying.len() - } - pub fn stopped(&self) -> impl Iterator> + '_ { self.stopped.iter() } - pub fn stopped_len(&self) -> usize { - self.stopped.len() - } - pub fn zombie_key(&self) -> Option { self.zombie.as_ref().map(|z| z.key()) } @@ -1687,9 +1679,8 @@ impl SchedPass<'_, '_, H, P, Disposed> { // wants everything a new task would queue behind, and a corpse // mid-unwind is exactly that: it is dispatched ahead of the fair // band, so counting `rq` alone makes a CPU holding two teardowns - // look as empty as an idle one — the same blindness `dying_len` - // closes in the dump. The steal probe wants what this CPU could - // hand over, which is the fair band and only the fair band; + // look as empty as an idle one. The steal probe wants what this + // CPU could hand over, which is the fair band and only the fair band; // publishing the first number to the second reader sends thieves to // CPUs with nothing to give. // @@ -2727,7 +2718,7 @@ mod tests { w.cpus[0].parked_task(key).is_some(), "the retire lost the claim: the entry stays for the wake to find", ); - assert_eq!(w.cpus[0].dying_len(), 0, "the retire placed nothing itself"); + assert_eq!(w.cpus[0].dying().count(), 0, "the retire placed nothing itself"); assert!(w.cpus[0].rq.is_empty(), "and queued nothing either"); // Now the wake it lost to lands, and *it* places the task — in the @@ -2877,14 +2868,14 @@ mod tests { } assert!(stopped_shared.stop_pending(), "the safe point takes the mark"); - assert_eq!(w.cpus[0].stopped_len(), 1); + assert_eq!(w.cpus[0].stopped().count(), 1); assert_eq!(w.cpus[0].stopped[0].key(), stopped); assert_eq!( w.cpus[0].running().map(|t| t.key()), Some(other), "the CPU keeps working; only the stopped task is out", ); - assert_eq!(w.cpus[0].dying_len(), 0, "stopping is not dying"); + assert_eq!(w.cpus[0].dying().count(), 0, "stopping is not dying"); // Every later pass, including ones where the CPU has nothing else. w.run_a_pass_at(C0, Nanos(NOW.0 + QUANTUM_NS + 1)); @@ -2894,7 +2885,7 @@ mod tests { Some(stopped), "no pick serves the band", ); - assert_eq!(w.cpus[0].stopped_len(), 1); + assert_eq!(w.cpus[0].stopped().count(), 1); w.abandon(); } @@ -2928,7 +2919,7 @@ mod tests { w.post_claimed_wake(C0, &parked_shared, WakeReason::Woken); w.run_a_pass(C0); - assert_eq!(w.cpus[0].stopped_len(), 1, "the wake reached the band"); + assert_eq!(w.cpus[0].stopped().count(), 1, "the wake reached the band"); assert_eq!(w.cpus[0].stopped[0].key(), parked); assert!(w.cpus[0].rq.is_empty(), "and never the run queue"); assert!( @@ -2970,9 +2961,9 @@ mod tests { w.post_claimed_wake(C0, &shared, WakeReason::Woken); w.run_a_pass(C0); - assert_eq!(w.cpus[0].stopped_len(), 1); + assert_eq!(w.cpus[0].stopped().count(), 1); assert_eq!(w.cpus[0].stopped[0].key(), key); - assert_eq!(w.cpus[0].dying_len(), 0, "never dispatched to unwind"); + assert_eq!(w.cpus[0].dying().count(), 0, "never dispatched to unwind"); assert!(w.cpus[0].running().is_none()); w.abandon(); } @@ -2994,7 +2985,7 @@ mod tests { let pass = SchedPass::begin(&mut cpus[0], env, NOW); let _ = pass.dispose_stop().finish(); } - assert_eq!(w.cpus[0].stopped_len(), 1); + assert_eq!(w.cpus[0].stopped().count(), 1); assert_eq!( w.handles.get(C0).load(), 0, @@ -3044,7 +3035,7 @@ mod tests { "the corpse that has been waiting longest unwinds next", ); assert_eq!( - w.cpus[0].dying_len(), + w.cpus[0].dying().count(), 1, "and the one whose quantum expired went back to the dying list", ); @@ -3087,7 +3078,7 @@ mod tests { Some(queued), "the waiting corpse runs; the killed one did not keep the CPU", ); - assert_eq!(w.cpus[0].dying_len(), 1); + assert_eq!(w.cpus[0].dying().count(), 1); assert_eq!(w.cpus[0].dying[0].task.key(), expiring); assert!(w.cpus[0].rq.is_empty(), "never through the fair queue"); w.abandon(); @@ -3131,7 +3122,7 @@ mod tests { "the yield hands the CPU to the corpse that was waiting", ); assert_eq!( - w.cpus[0].dying_len(), + w.cpus[0].dying().count(), 1, "and the yielder went back to the dying list", ); @@ -3193,7 +3184,7 @@ mod tests { cpus[1].drain(env, NOW); } - assert_eq!(w.cpus[1].dying_len(), 1, "the arriving corpse is placed to unwind"); + assert_eq!(w.cpus[1].dying().count(), 1, "the arriving corpse is placed to unwind"); assert_eq!(w.cpus[1].dying[0].task.key(), key); assert!( w.cpus[1].rq.is_empty(), @@ -3262,7 +3253,7 @@ mod tests { Some(rt), "the RT task got the CPU on the first pass after it became ready", ); - assert_eq!(w.cpus[0].dying_len(), 1, "the corpse is queued, not running"); + assert_eq!(w.cpus[0].dying().count(), 1, "the corpse is queued, not running"); assert!(w.released().is_empty(), "and nothing was discarded"); w.abandon(); } @@ -3284,7 +3275,7 @@ mod tests { Some(rt), "the expiring quantum is not a fresh one for the corpse", ); - assert_eq!(w.cpus[0].dying_len(), 1); + assert_eq!(w.cpus[0].dying().count(), 1); w.abandon(); } @@ -3388,7 +3379,7 @@ mod tests { Some(rt), "the RT task still takes the CPU on the pass that makes it ready", ); - assert_eq!(w.cpus[0].dying_len(), 1, "and the corpse is queued"); + assert_eq!(w.cpus[0].dying().count(), 1, "and the corpse is queued"); // Follow the armed timer, which is the only thing that takes the CPU // away from a task nothing preempts — a real machine does exactly this. @@ -3537,7 +3528,7 @@ mod tests { Some(rt), "the grant ends on its own boundary and not a nanosecond later", ); - assert_eq!(w.cpus[0].dying_len(), 1, "the corpse is queued again"); + assert_eq!(w.cpus[0].dying().count(), 1, "the corpse is queued again"); w.abandon(); } @@ -3577,7 +3568,7 @@ mod tests { "the corpse is unwinding, not doing real-time work, so the sibling \ that is doing real-time work gets the CPU at the next pass", ); - assert_eq!(w.cpus[0].dying_len(), 1, "and the corpse waits its age out"); + assert_eq!(w.cpus[0].dying().count(), 1, "and the corpse waits its age out"); assert!( w.cpus[0].dying[0].task.is_rt(), "with its right intact — this is about the band it competes in, not \ @@ -3646,7 +3637,7 @@ mod tests { "and the task came out of cpu2's surplus", ); assert_eq!( - w.cpus[1].dying_len(), + w.cpus[1].dying().count(), 3, "while cpu1's corpses stayed exactly where they were", ); diff --git a/kernel/src/arch/x86_64/vtd/table.rs b/kernel/src/arch/x86_64/vtd/table.rs index 0867e4b40fb..39e2fc2d44a 100644 --- a/kernel/src/arch/x86_64/vtd/table.rs +++ b/kernel/src/arch/x86_64/vtd/table.rs @@ -8,7 +8,7 @@ use alloc::vec::Vec; use crate::iommu::{AddressWidth, IommuError, Iova, StreamId}; -use crate::mm::pmm::{self, Category, PhysPage}; +use crate::mm::pmm::{self, PhysPage}; use crate::mm::{DirectMap, Mmio, PAGE_2M}; /// 4 KiB per table: 256 16-byte entries (root/context) or 512 8-byte entries (second-level). @@ -49,7 +49,7 @@ impl Tables { /// Returns one zeroed 4 KiB table, usable as a root, context, second-level, or invalidation-queue table. pub fn alloc(&mut self) -> Table { if self.used + TABLE_BYTES > PAGE_2M as usize { - let page = pmm::alloc_page(Category::Dma) + let page = pmm::alloc_page() .expect("iommu: no physical memory for a remapping table"); self.pages.push(page); self.used = 0; diff --git a/kernel/src/clock.rs b/kernel/src/clock.rs index ee7795c7dc1..2adf21ddd57 100644 --- a/kernel/src/clock.rs +++ b/kernel/src/clock.rs @@ -32,7 +32,7 @@ fn publish_page(counter_at_boot: u64, period_fs: u64) { use toyos_abi::clock::{ClockPage, CLOCK_MAGIC}; let bytes = crate::mm::PAGE_2M as usize; // Held for the machine's life: every process maps it. - let frame = crate::process::PageAlloc::new(bytes, crate::mm::pmm::Category::SharedMemory) + let frame = crate::process::PageAlloc::new(bytes) .expect("clock: no 2 MiB frame for the clock page"); // SAFETY: a fresh allocation this function owns, `bytes` long, that no // address space maps yet; zeroed whole because all of it is mapped, and diff --git a/kernel/src/drivers/gop.rs b/kernel/src/drivers/gop.rs index cc5f6797619..bdfe4f1018b 100644 --- a/kernel/src/drivers/gop.rs +++ b/kernel/src/drivers/gop.rs @@ -77,7 +77,7 @@ pub fn init( ); log!("GOP: scanout memory type {memory_type}"); - let cursor_pages = crate::mm::pmm::alloc_contiguous(1, crate::mm::pmm::Category::Framebuffer).expect("GOP: cursor alloc failed"); + let cursor_pages = crate::mm::pmm::alloc_contiguous(1).expect("GOP: cursor alloc failed"); let cursor_phys = cursor_pages[0].direct_map().phys(); // Cursor buffer is plain system RAM, not scanout, so it keeps the default write-back type. let cursor = Region { diff --git a/kernel/src/drivers/virtio_gpu.rs b/kernel/src/drivers/virtio_gpu.rs index e58b5a251a8..fa8ade0c680 100644 --- a/kernel/src/drivers/virtio_gpu.rs +++ b/kernel/src/drivers/virtio_gpu.rs @@ -415,8 +415,8 @@ impl GpuController { let fb_pages = fb_size.div_ceil(PAGE_2M as usize); let fb_aligned = (fb_pages * PAGE_2M as usize) as u64; let all_pages = - [crate::mm::pmm::alloc_contiguous(fb_pages, crate::mm::pmm::Category::Framebuffer)?, - crate::mm::pmm::alloc_contiguous(fb_pages, crate::mm::pmm::Category::Framebuffer)?]; + [crate::mm::pmm::alloc_contiguous(fb_pages)?, + crate::mm::pmm::alloc_contiguous(fb_pages)?]; let regions = all_pages.map(|pages| { let phys = pages[0].direct_map().phys(); Region { @@ -617,7 +617,7 @@ pub fn init(devices: &[PciDevice]) -> Option<(Box, GpuInfo)> { gpu.set_scanout(0, gpu.resource, rect); let cursor_bytes = (CURSOR_SIZE * CURSOR_SIZE * 4) as usize; - let cursor_pages = crate::mm::pmm::alloc_contiguous(1, crate::mm::pmm::Category::Framebuffer).expect("VirtIO GPU: cursor alloc failed"); + let cursor_pages = crate::mm::pmm::alloc_contiguous(1).expect("VirtIO GPU: cursor alloc failed"); let cursor_ptr = cursor_pages[0].direct_map().as_mut_ptr::(); let cursor_phys = cursor_pages[0].direct_map().phys(); gpu.cursor = Region { diff --git a/kernel/src/elf/cache.rs b/kernel/src/elf/cache.rs index 963222950d0..26cdcd53195 100644 --- a/kernel/src/elf/cache.rs +++ b/kernel/src/elf/cache.rs @@ -206,7 +206,7 @@ pub fn cache_loaded_lib( let Some(relocs) = scanned else { return Ok(owned(alloc)); }; - let Some(rw_alloc) = PageAlloc::new(rw_size, crate::mm::pmm::Category::Elf) else { + let Some(rw_alloc) = PageAlloc::new(rw_size) else { return Ok(owned(alloc)); }; let alloc_ptr = alloc.ptr(); @@ -282,7 +282,7 @@ pub fn try_clone_cached( fn clone_from_cache(cached: &CachedLib) -> Option { let t0 = crate::clock::nanos_since_boot(); - let rw_alloc = PageAlloc::new(cached.rw_size, crate::mm::pmm::Category::Elf)?; + let rw_alloc = PageAlloc::new(cached.rw_size)?; // SAFETY: `rw_offset + rw_size` was validated inside `cached.alloc` when this `CachedLib` was built; `CachedLib` is immortal once cached, so `cached.alloc` is still live. let src = unsafe { cached.alloc.ptr().add(cached.rw_offset) }; // SAFETY: `src` is valid for `cached.rw_size` bytes per the `SAFETY` above; `rw_alloc` is a fresh, distinct allocation, so the ranges cannot overlap. diff --git a/kernel/src/elf/mod.rs b/kernel/src/elf/mod.rs index 41618d3d993..6da1af0b3c1 100644 --- a/kernel/src/elf/mod.rs +++ b/kernel/src/elf/mod.rs @@ -377,7 +377,7 @@ pub fn load_shared_lib( let t0 = crate::clock::nanos_since_boot(); let alloc = - PageAlloc::new(load_size, crate::mm::pmm::Category::Elf).ok_or("dlopen: allocation failed")?; + PageAlloc::new(load_size).ok_or("dlopen: allocation failed")?; let t1 = crate::clock::nanos_since_boot(); // Every offset below is bounded against what the PMM actually returned, not `load_size`. let image = alloc.window(); diff --git a/kernel/src/loader/mod.rs b/kernel/src/loader/mod.rs index 303bcee008c..deb308799aa 100644 --- a/kernel/src/loader/mod.rs +++ b/kernel/src/loader/mod.rs @@ -487,7 +487,7 @@ pub fn spawn( } // Mapped eagerly, not demand-paged: every process touches the stack immediately. - let stack_pages = match PageAlloc::new(USER_STACK_SIZE, crate::mm::pmm::Category::Stack) { + let stack_pages = match PageAlloc::new(USER_STACK_SIZE) { Some(a) => a, None => { log!("spawn: {}: failed to allocate user stack ({} bytes)", path, USER_STACK_SIZE); diff --git a/kernel/src/loader/tls.rs b/kernel/src/loader/tls.rs index a4102834b39..c459287c2a9 100644 --- a/kernel/src/loader/tls.rs +++ b/kernel/src/loader/tls.rs @@ -63,7 +63,7 @@ impl TlsBlock { /// the block's physical address, which [`rebase`] moves once it has another. fn build_combined(modules: &[TlsModule], tls: Static) -> Option { let plan = tls.plan(TCB_SIZE, DTV_BYTES, crate::mm::PAGE_2M as usize)?; - let frames = Unpublished::new(PageAlloc::new(plan.alloc_size, crate::mm::pmm::Category::InitTls)?); + let frames = Unpublished::new(PageAlloc::new(plan.alloc_size)?); let block = frames.ptr(); // SAFETY: `block` is the fresh, unpublished `plan.alloc_size`-byte allocation above. diff --git a/kernel/src/mm/alloc.rs b/kernel/src/mm/alloc.rs index 0bb60a5bb98..a8250a070a0 100644 --- a/kernel/src/mm/alloc.rs +++ b/kernel/src/mm/alloc.rs @@ -557,7 +557,7 @@ unsafe impl GlobalAlloc for KernelAllocator { }; let mut base = malloc(None); if base.is_null() { - if let Some(frame) = pmm::claim(pmm::Category::KernelHeap) { + if let Some(frame) = pmm::claim() { base = malloc(Some(frame)); } } diff --git a/kernel/src/mm/dma.rs b/kernel/src/mm/dma.rs index 87b8132c777..1b89130ff2a 100644 --- a/kernel/src/mm/dma.rs +++ b/kernel/src/mm/dma.rs @@ -217,7 +217,7 @@ impl DmaPool { /// `space` and reachable by nothing outside it. pub fn alloc_in(size: usize, space: DeviceSpace) -> Self { let pages_2m = size.div_ceil(super::PAGE_2M as usize); - let pages = super::pmm::alloc_contiguous(pages_2m, super::pmm::Category::Dma) + let pages = super::pmm::alloc_contiguous(pages_2m) .expect("DmaPool: out of physical memory"); let base = pages[0].direct_map(); let size = pages_2m * super::PAGE_2M as usize; diff --git a/kernel/src/mm/pmm.rs b/kernel/src/mm/pmm.rs index 9be7bd4919d..266b0586109 100644 --- a/kernel/src/mm/pmm.rs +++ b/kernel/src/mm/pmm.rs @@ -1,5 +1,3 @@ -use core::sync::atomic::{AtomicU64, Ordering}; - use super::{DirectMap, PAGE_2M}; use crate::sync::Lock; use crate::MemoryMapEntry; @@ -11,105 +9,15 @@ pub struct Region { pub end: u64, } - -#[derive(Clone, Copy, Debug, PartialEq, Eq)] -#[repr(u8)] -pub enum Category { - KernelHeap = 0, // dlmalloc backing pages (global allocator) - DemandPage = 1, // page fault handler - Mmap = 2, // sys_mmap - SharedMemory = 3, // shared_memory::alloc - Pipe = 4, // pipe ring buffers - Elf = 5, // ELF loading (dlopen, cache, RW overlay) - Tls = 6, // thread-local storage blocks - Dma = 7, // DMA pools (drivers) - Framebuffer = 8, // GPU framebuffers - Stack = 9, // user stacks - InitTls = 10, // initial TLS block at spawn -} - -const NUM_CATEGORIES: usize = 11; - -impl Category { - fn name(self) -> &'static str { - match self { - Category::KernelHeap => "kernel-heap", - Category::DemandPage => "demand-page", - Category::Mmap => "mmap", - Category::SharedMemory => "shared-mem", - Category::Pipe => "pipe", - Category::Elf => "elf", - Category::Tls => "tls", - Category::Dma => "dma", - Category::Framebuffer => "framebuffer", - Category::Stack => "stack", - Category::InitTls => "init-tls", - } - } -} - -struct CategoryCounters { - alloc_pages: AtomicU64, - free_pages: AtomicU64, -} - -impl CategoryCounters { - const fn new() -> Self { - Self { - alloc_pages: AtomicU64::new(0), - free_pages: AtomicU64::new(0), - } - } -} - -static CATEGORY_STATS: [CategoryCounters; NUM_CATEGORIES] = - [const { CategoryCounters::new() }; NUM_CATEGORIES]; - -/// Snapshot of the last time `dump_stats` ran, for computing rates. -static LAST_DUMP_NANOS: AtomicU64 = AtomicU64::new(0); -static LAST_ALLOC: [AtomicU64; NUM_CATEGORIES] = [const { AtomicU64::new(0) }; NUM_CATEGORIES]; - -/// Log per-category page allocation stats to serial. -pub fn dump_stats() { - let now = crate::clock::nanos_since_boot(); - let prev = LAST_DUMP_NANOS.swap(now, Ordering::Relaxed); - let dt_secs = if prev == 0 { 0.0 } else { (now - prev) as f64 / 1_000_000_000.0 }; - - let (total, used) = stats(); - crate::log!("PMM: {}/{}MB used ({} pages free)", - used / (1024 * 1024), total / (1024 * 1024), - (total - used) / PAGE_2M); - - for i in 0..NUM_CATEGORIES { - let alloc = CATEGORY_STATS[i].alloc_pages.load(Ordering::Relaxed); - let free = CATEGORY_STATS[i].free_pages.load(Ordering::Relaxed); - let held = alloc.saturating_sub(free); - if alloc == 0 { continue; } - - let prev_alloc = LAST_ALLOC[i].swap(alloc, Ordering::Relaxed); - let rate = if dt_secs > 0.0 { - ((alloc - prev_alloc) as f64 / dt_secs) as u64 - } else { - 0 - }; - - // Safety: i < NUM_CATEGORIES which equals the number of Category variants - let cat = unsafe { core::mem::transmute::(i as u8) }; - crate::log!(" {:12} alloc={:6} free={:6} held={:6} ({}MB) rate={}/s", - cat.name(), alloc, free, held, held * 2, rate); - } -} - /// Owns one 2MB physical page; dropping it returns the page to the free list. pub struct PhysPage { phys: u64, // raw physical address, 2MB-aligned - category: u8, // Category as u8 } impl PhysPage { - /// Caller must ensure `phys` is a previously allocated, 2MB-aligned page; assigned to `KernelHeap`. + /// Caller must ensure `phys` is a previously allocated, 2MB-aligned page. pub(super) fn from_raw(phys: u64) -> Self { - Self { phys, category: Category::KernelHeap as u8 } + Self { phys } } /// Access this page through the kernel direct map. @@ -121,10 +29,6 @@ impl PhysPage { impl Drop for PhysPage { fn drop(&mut self) { - let cat = self.category as usize; - if cat < NUM_CATEGORIES { - CATEGORY_STATS[cat].free_pages.fetch_add(1, Ordering::Relaxed); - } free_page(self.phys); } } @@ -263,8 +167,8 @@ pub(super) fn init(entries: &[MemoryMapEntry], reserved: &[Region]) { } /// Allocate one 2MB physical page. -pub fn alloc_page(cat: Category) -> Option { - let page = claim(cat)?; +pub fn alloc_page() -> Option { + let page = claim()?; // SAFETY: `claim` just took the frame off the bitmap, so it is unaliased, and the direct map covers every address the bitmap can name. unsafe { core::ptr::write_bytes(page.direct_map().as_mut_ptr::(), 0, PAGE_2M as usize); @@ -273,7 +177,7 @@ pub fn alloc_page(cat: Category) -> Option { } /// One 2MB physical page holding what its last owner left in it. Only the kernel heap takes one as it is: the heap answers uninitialized memory, and `alloc_zeroed` writes its own zeros. Does not heap-allocate: the heap calls it when it is full. -pub(super) fn claim(cat: Category) -> Option { +pub(super) fn claim() -> Option { let mut bm = BITMAP.lock(); if bm.free_count == 0 { return None; } let start = bm.next_hint; @@ -285,15 +189,14 @@ pub(super) fn claim(cat: Category) -> Option { bm.next_hint = if idx + 1 < bm.page_count { idx + 1 } else { 0 }; let phys = bm.idx_to_phys(idx); drop(bm); - CATEGORY_STATS[cat as usize].alloc_pages.fetch_add(1, Ordering::Relaxed); - return Some(PhysPage { phys, category: cat as u8 }); + return Some(PhysPage { phys }); } } None } /// Allocate `count` physically contiguous 2MB pages. -pub fn alloc_contiguous(count: usize, cat: Category) -> Option> { +pub fn alloc_contiguous(count: usize) -> Option> { // `count` comes from userland, so a bogus 0 and a legitimate `mmap(0)` can't be told apart here — refuse, don't assert. if count == 0 { return None; } let mut bm = BITMAP.lock(); @@ -312,8 +215,6 @@ pub fn alloc_contiguous(count: usize, cat: Category) -> Option Option(), 0, PAGE_2M as usize, ); } - pages.push(PhysPage { phys, category: cat as u8 }); + pages.push(PhysPage { phys }); } return Some(pages); } diff --git a/kernel/src/object/shm.rs b/kernel/src/object/shm.rs index 581ce8fc13e..e19eda42b91 100644 --- a/kernel/src/object/shm.rs +++ b/kernel/src/object/shm.rs @@ -83,7 +83,7 @@ impl SharedMemObject { // `SYS_SHM_CREATE`'s length, straight from a register: the rounding // itself is the checked sum. let aligned = align_2m_checked(size).ok_or(SyscallError::InvalidArgument)?; - let pages = pmm::alloc_contiguous((aligned / PAGE_2M) as usize, pmm::Category::SharedMemory) + let pages = pmm::alloc_contiguous((aligned / PAGE_2M) as usize) .ok_or(SyscallError::ResourceExhausted)?; let phys = DirectMap::from_phys(pages[0].direct_map().phys()); Ok(Self::over(Region { diff --git a/kernel/src/pipe.rs b/kernel/src/pipe.rs index 565679d4af3..b0c8122a702 100644 --- a/kernel/src/pipe.rs +++ b/kernel/src/pipe.rs @@ -142,7 +142,7 @@ impl Pipe { /// Allocate the ring page if this is the first use; `None` on exhaustion, an error return rather than a panic since userland drives it. fn back(&mut self) -> Option<&mut Backing> { if self.backing.is_none() { - let page = pmm::alloc_page(pmm::Category::Pipe)?; + let page = pmm::alloc_page()?; // SAFETY: a fresh 2 MiB page this `Pipe` owns for as long as the `Ring` addresses it. let ring = unsafe { Ring::new(page.direct_map().as_mut_ptr(), PIPE_SIZE) }; self.backing = Some(Backing { page, ring }); diff --git a/kernel/src/process.rs b/kernel/src/process.rs index 8f7a9a9e3c3..78cfa1ded34 100644 --- a/kernel/src/process.rs +++ b/kernel/src/process.rs @@ -97,9 +97,9 @@ pub struct PageAlloc(Vec); impl PageAlloc { /// Allocate `size` bytes as contiguous 2MB pages. - pub fn new(size: usize, cat: crate::mm::pmm::Category) -> Option { + pub fn new(size: usize) -> Option { let count = size.div_ceil(PAGE_2M as usize); - Some(Self(crate::mm::pmm::alloc_contiguous(count, cat)?)) + Some(Self(crate::mm::pmm::alloc_contiguous(count)?)) } /// Kernel pointer to the start of the allocation (via direct map). @@ -1443,7 +1443,7 @@ pub fn handle_page_fault(fault_addr: u64, _error_code: u64) -> bool { let reloc_index = data.elf.reloc_index.clone(); let elf_base = data.elf.elf_base.raw(); - let page_alloc = match PageAlloc::new(page_2m as usize, crate::mm::pmm::Category::DemandPage) { + let page_alloc = match PageAlloc::new(page_2m as usize) { Some(a) => a, None => return false, }; diff --git a/kernel/src/sched/driver.rs b/kernel/src/sched/driver.rs index 7fa783030a6..d613be313d2 100644 --- a/kernel/src/sched/driver.rs +++ b/kernel/src/sched/driver.rs @@ -704,7 +704,6 @@ extern "C" fn idle_loop() -> ! { if crate::drivers::panic_console::probe_due() { panic!("metal-panic-probe: a fatal report over a desktop that owns the screen"); } - crate::scheduler::log_health(); crate::scheduler::reap_finished(); // `pass` below covers this too; here as well so a CPU that // halts immediately has still run every hook first. @@ -779,22 +778,6 @@ pub fn ready_len() -> usize { try_with_cpu(|cpu| cpu.ready_len()).unwrap_or(0) } -pub fn parked_len() -> usize { - try_with_cpu(|cpu| cpu.parked().count()).unwrap_or(0) -} - -/// Killed threads on this CPU that are unwinding or waiting to. -/// -/// The dump's fourth container — without it a dying task is invisible to `unheld = claimed − scheduled`. -pub fn dying_len() -> usize { - try_with_cpu(|cpu| cpu.dying_len()).unwrap_or(0) -} - -/// Threads on this CPU the machine's stop banded; no pick serves them again. -pub fn stopped_len() -> usize { - try_with_cpu(|cpu| cpu.stopped_len()).unwrap_or(0) -} - /// Every thread on this CPU the machine's stop banded. pub fn for_each_stopped(mut f: impl FnMut(TaskId)) -> bool { try_with_cpu(|cpu| { diff --git a/kernel/src/sched/idle_stack.rs b/kernel/src/sched/idle_stack.rs index 34365c56d74..3c0a41910b5 100644 --- a/kernel/src/sched/idle_stack.rs +++ b/kernel/src/sched/idle_stack.rs @@ -35,7 +35,7 @@ struct Arena { fn alloc_slot() -> u64 { let mut arena = ARENA.lock(); if arena.left < SLOT { - let page = crate::mm::pmm::alloc_page(crate::mm::pmm::Category::KernelHeap) + let page = crate::mm::pmm::alloc_page() .expect("idle stack: no physical page for one"); arena.next = page.direct_map().as_mut_ptr::() as u64; arena.left = crate::mm::PAGE_2M as usize; diff --git a/kernel/src/scheduler.rs b/kernel/src/scheduler.rs index fb95bf95a9b..b2b1e6affd4 100644 --- a/kernel/src/scheduler.rs +++ b/kernel/src/scheduler.rs @@ -22,7 +22,7 @@ use crate::sched::payload::{KShare, KernelLock, TaskHandle, ThreadSched}; use crate::sched::reap_gate::ReapGate; use crate::sched::futex; use crate::sync::Lock; -use crate::time::{Cadence, Deadline, Duration}; +use crate::time::Deadline; use crate::DirectMap; pub use crate::sched::driver::{ @@ -582,69 +582,3 @@ pub fn task_sched_state(sched: &ThreadSched) -> u8 { pub fn flush_current_stats(acct: &mut process::ProcessAccounting) { driver::with_current_acct(|a| crate::sched::payload::merge_accounting(a, acct)); } - -/// How often an idle CPU may report occupancy: not a deadline, so it never -/// wakes a CPU with nothing to run — turning it into one would be an audio -/// change. -const SNAPSHOT_INTERVAL: Cadence = Cadence::every( - Duration::from_secs(10), - "one clock read and one relaxed compare per idle trip, on a CPU already awake", -); - -/// When each CPU may next print its own line: per CPU, not global, so no -/// single CPU speaks for all of them. -static NEXT_HEALTH: [AtomicU64; MAX_CPUS] = [const { AtomicU64::new(0) }; MAX_CPUS]; - -/// How many times each CPU has passed through idle since boot. -static IDLE_TRIPS: [AtomicU64; MAX_CPUS] = [const { AtomicU64::new(0) }; MAX_CPUS]; - -/// A snapshot of this CPU's run queues, at most once per -/// [`SNAPSHOT_INTERVAL`], plus the machine's page pools on the same -/// cadence. Called from the idle loop on every trip; the cadence is wall -/// clock rather than per-trip because a CPU that declines to sleep loops at -/// memory speed. Not a heartbeat: a busy CPU prints nothing, so a gap here -/// is not evidence of a hang. -pub fn log_health() { - let now = crate::hw::now_ns(); - let cpu = percpu::cpu_id(); - let Some(next_health) = NEXT_HEALTH.get(cpu as usize) else { return }; - // Unconditional and every trip, unlike the print below. - let trips = IDLE_TRIPS - .get(cpu as usize) - .map_or(0, |t| t.fetch_add(1, Ordering::Relaxed) + 1); - if now >= next_health.load(Ordering::Relaxed) { - next_health.store(now + SNAPSHOT_INTERVAL.nanos(), Ordering::Relaxed); - let ready = driver::ready_len() + usize::from(percpu::current_tid().is_some()); - let parked = driver::parked_len(); - let dying = driver::dying_len(); - let stopped = driver::stopped_len(); - crate::log!( - "sched: cpu={} ready={} dying={} stopped={} parked={} current={:?} trips={}", - cpu, - ready, - dying, - stopped, - parked, - percpu::current_tid(), - trips, - ); - } - - static NEXT_PMM_DUMP: AtomicU64 = AtomicU64::new(0); - let next = NEXT_PMM_DUMP.load(Ordering::Relaxed); - if next == 0 { - NEXT_PMM_DUMP.store(now + SNAPSHOT_INTERVAL.nanos(), Ordering::Relaxed); - } else if now >= next - && NEXT_PMM_DUMP - .compare_exchange( - next, - now + SNAPSHOT_INTERVAL.nanos(), - Ordering::Relaxed, - Ordering::Relaxed, - ) - .is_ok() - { - crate::mm::pmm::dump_stats(); - } -} - diff --git a/kernel/src/syscall/vm.rs b/kernel/src/syscall/vm.rs index 1a414c8ebc8..c6450755b12 100644 --- a/kernel/src/syscall/vm.rs +++ b/kernel/src/syscall/vm.rs @@ -76,7 +76,7 @@ pub(super) fn sys_mmap(req_addr: u64, size: u64, prot: MmapProt, flags: MmapFlag // fault: `handle_page_fault` refuses to fill a `Mapped` region. None } else { - match process::PageAlloc::new(aligned, crate::mm::pmm::Category::Mmap) { + match process::PageAlloc::new(aligned) { Some(pages) => Some(pages), None => return SyscallError::ResourceExhausted.to_u64(), } @@ -426,7 +426,7 @@ fn tls_alloc_block(module_id: u64) -> Result { let tls_vaddr = match existing { Some(vaddr) => vaddr, None => { - let page_alloc = process::PageAlloc::new(tls_memsz.max(1), crate::mm::pmm::Category::Tls) + let page_alloc = process::PageAlloc::new(tls_memsz.max(1)) .ok_or(SyscallError::ResourceExhausted)?; // SAFETY: `page_alloc` is a fresh, unaliased allocation of at // least `tls_memsz.max(1)` bytes; `template.size()` comes from the diff --git a/tests/toyos-rust-tests/src/bin/counters_metal.rs b/tests/toyos-rust-tests/src/bin/counters_metal.rs index 00720c7fff4..4d023c89835 100644 --- a/tests/toyos-rust-tests/src/bin/counters_metal.rs +++ b/tests/toyos-rust-tests/src/bin/counters_metal.rs @@ -10,15 +10,9 @@ //! three are taken**: a printed line reaches the stick within the second, //! through the `/log` fileserver on that fileserver's CPU. //! -//! **`idle0` waits for the log to be quiet** ([`Log::settle`]): a job starts -//! while logkeeper is still writing the boot so far and the job's own launch -//! lines to the stick, and a second begun then measures that write. -//! -//! **And for a second the kernel's idle report cannot reach** ([`quiet`]): an -//! idle CPU prints `sched:`, and one of them `PMM:`, on its first idle trip -//! [`REPORT`] after its last, so a report is due at a time the log says, and -//! one overdue prints at whatever next wakes its CPU. The second starts only -//! where none falls due before it ends, wherever in a boot the job runs. +//! **`idle0` waits for the log to be quiet** ([`settle`]): a job starts while +//! logkeeper is still writing the boot so far and the job's own launch lines +//! to the stick, and a second begun then measures that write. //! //! **Then `loaded`: how late the round's kick reaches each CPU** while a thread //! per CPU spawns a program that exits at once, which is the load Linux's @@ -29,7 +23,6 @@ //! kicks. A round across which a CPU's SMI count moved is dropped, since an //! SMI stops every CPU, and so is one with a CPU stale. -use std::collections::BTreeMap; use std::process::Command; use std::sync::atomic::{AtomicBool, Ordering}; use std::time::{Duration, Instant}; @@ -39,7 +32,7 @@ use toyos::poller::{Poller, READABLE}; use toyos::syscap::SysCap; use toyos_abi::counters::{Counter, RawRecord, Record}; use toyos_abi::syscall::{self, SyscallError}; -use toyos_logstream::{program_line, record_ms, Lines}; +use toyos_logstream::{program_line, Lines}; /// The idle span: long enough that a CPU's busy fraction is its idle one and /// not the reads'. @@ -55,25 +48,9 @@ const SPIN: u64 = 4_000_000_000; /// (`toyos_tco::JOB_BOUND_MS`) the reads before it leave. const LOADED: Duration = Duration::from_secs(20); -/// How long [`quiet`] may take, a hang ceiling: a [`REPORT`] of waiting for -/// every report to fall due, and two of logkeeper's rounds at its write budget -/// (`userland/logkeeper/src/policy.rs`, 5 s). The job list's bound -/// (`toyos_tco::JOB_BOUND_MS`) holds it, the spin and [`LOADED`]. -const QUIET_BOUND: Duration = Duration::from_secs(20); - -/// The kernel's idle report period, `SNAPSHOT_INTERVAL` in -/// `kernel/src/scheduler.rs`: a CPU's next report is due this long after -/// the clock read its last one followed. -const REPORT: Duration = Duration::from_secs(10); - -/// How far a report's due time and the second's end are each held from the -/// other: a stamp follows the clock read its deadline was set from by the -/// formatting between them, and `idle1` follows [`IDLE`] by a wake and a read. -const CLEAR: Duration = Duration::from_millis(50); - -/// How long [`quiet`] keeps a thread on every CPU, so that each one wakes -/// and passes its idle loop, where an overdue report prints. -const WAKE: Duration = Duration::from_millis(20); +/// How long [`settle`] waits for each of its lines: two of logkeeper's rounds +/// at its write budget (`userland/logkeeper/src/policy.rs`, 5 s). +const SETTLE_BOUND: Duration = Duration::from_secs(10); /// What this binary's own children are asked to do: exit at once. const EXIT_AT_ONCE: &str = "exit-at-once"; @@ -176,146 +153,51 @@ fn print(phase: &str, read: &Read) { } } -/// What the log says of the kernel's idle report, read off its records. -#[derive(Default)] -struct Reports { - /// Each CPU's last `sched:` record, in milliseconds since boot. - last: BTreeMap, - /// Each CPU's first, `trips=1`: the earliest is the trip that set the - /// first `PMM:` deadline. - first: BTreeMap, - /// The last `PMM:` record. - pmm: Option, -} - -impl Reports { - fn see(&mut self, line: &str) { - let (Some(ms), Some((_, said))) = (record_ms(line), line.split_once("] ")) else { return }; - if let Some(rest) = said.strip_prefix("sched: cpu=") { - let cpu = rest.split(' ').next().and_then(|cpu| cpu.parse().ok()); - let cpu = cpu.unwrap_or_else(|| panic!("a `sched:` record names no cpu: {line:?}")); - self.last.insert(cpu, ms); - if rest.ends_with(" trips=1") { - self.first.insert(cpu, ms); - } - } else if said.starts_with("PMM: ") { - self.pmm = Some(ms); - } - } - - /// When, in nanoseconds since boot, each report may next print: every - /// CPU's, then the machine's `PMM:`, each [`CLEAR`] early. One the log - /// does not hold may print now. - fn due(&self, cpus: u64) -> Vec { - let after = |ms: Option| { - ms.map_or(0, |ms| (ms * 1_000_000 + REPORT.as_nanos() as u64).saturating_sub(CLEAR.as_nanos() as u64)) - }; - let first_trip = (self.first.len() as u64 == cpus).then(|| self.first.values().copied().min()).flatten(); - (0..cpus).map(|cpu| after(self.last.get(&cpu).copied())).chain([after(self.pmm.or(first_trip))]).collect() - } -} - -/// This boot's log as logkeeper serves it, from its first line. -struct Log { - pipe: toyos::Pipe, - poller: Poller, - lines: Lines, - chunk: Vec, - reports: Reports, - said: u32, -} - -impl Log { - fn open() -> Self { - let pipe = logkeeper_api::read().unwrap_or_else(|why| panic!("test-runner's `log` port: {why}")).pipe; - Self { pipe, poller: Poller::new(1), lines: Lines::new(), chunk: vec![0u8; 64 * 1024], reports: Reports::default(), said: 0 } - } - - /// Return once logkeeper has written, and made durable, everything - /// stamped before this call. - /// - /// A reader of the `log` port is handed each round only after it is on - /// the stick, so this prints a line and reads the log until that line - /// comes back. **Twice**: the round that writes the first may itself put a - /// record in the log — the stick's first sync is one — and the second - /// writes it. The `counters` row reds any line stamped inside the idle - /// second. - fn settle(&mut self, by: Instant) { - for _ in 0..2 { - self.said += 1; - let said = format!("counters_metal settle: the log holds line {}", self.said); - println!("{said}"); - let mut held = false; - while !held { - match self.pipe.read_nonblock(&mut self.chunk) { - Ok(0) => panic!("logkeeper closed the log before it held {said:?}"), - Ok(n) => { - let reports = &mut self.reports; - self.lines.push(&self.chunk[..n], |line, _| { - let line = std::str::from_utf8(line) - .unwrap_or_else(|e| panic!("logkeeper served a line that is not UTF-8 ({e}): {line:?}")); - reports.see(line); - held |= program_line(line).is_some_and(|line| line.text == said); - }) - } - Err(SyscallError::WouldBlock) => { - let left = by.checked_duration_since(Instant::now()).unwrap_or_else(|| { - panic!("the log did not hold {said:?} within {QUIET_BOUND:?} of the job's start") - }); - self.poller.watch(&self.pipe, READABLE, 0); - self.poller.wait(1, left.as_nanos() as u64, |_| {}); - } - Err(e) => panic!("the log's pipe refused a read: {e:?}"), +/// Return once logkeeper has written, and made durable, everything stamped +/// before this call. +/// +/// A reader of the `log` port is handed each round only after it is on the +/// stick, so this prints a line and reads the log until that line comes back. +/// **Twice**: the round that writes the first may itself put a record in the +/// log — the stick's first sync is one — and the second writes it. The +/// `counters` row reds any line stamped inside the idle second. +fn settle() { + let pipe = logkeeper_api::read().unwrap_or_else(|why| panic!("test-runner's `log` port: {why}")).pipe; + let poller = Poller::new(1); + let mut lines = Lines::new(); + let mut chunk = vec![0u8; 64 * 1024]; + for round in ["first", "second"] { + let said = format!("counters_metal settle: the log holds this {round} line"); + println!("{said}"); + let by = Instant::now() + SETTLE_BOUND; + let mut held = false; + while !held { + match pipe.read_nonblock(&mut chunk) { + Ok(0) => panic!("logkeeper closed the log before it held {said:?}"), + Ok(n) => lines.push(&chunk[..n], |line, _| { + let line = std::str::from_utf8(line) + .unwrap_or_else(|e| panic!("logkeeper served a line that is not UTF-8 ({e}): {line:?}")); + held |= program_line(line).is_some_and(|line| line.text == said); + }), + Err(SyscallError::WouldBlock) => { + let left = by.checked_duration_since(Instant::now()).unwrap_or_else(|| { + panic!("the log did not hold {said:?} within {SETTLE_BOUND:?}") + }); + poller.watch(&pipe, READABLE, 0); + poller.wait(1, left.as_nanos() as u64, |_| {}); } + Err(e) => panic!("the log's pipe refused a read: {e:?}"), } } } } -/// Return with the log written and no report of the kernel's due before -/// [`IDLE`] and [`CLEAR`] from now. -/// -/// Where one would be, this waits until every report is due and puts a thread -/// on every CPU, so each prints what it owes now and owes nothing for a -/// [`REPORT`] after. **A sleep, not a wait on an event**: a report falls due -/// on the clock alone and says so to nobody. -fn quiet() { - let by = Instant::now() + QUIET_BOUND; - let cpus = u64::from(syscall::cpu_count()); - let mut log = Log::open(); - loop { - log.settle(by); - let now = toyos_abi::clock::nanos_since_boot(); - let due = log.reports.due(cpus); - let first = *due.iter().min().expect("a machine has a cpu"); - let last = *due.iter().max().expect("a machine has a cpu"); - if first > now + (IDLE + CLEAR).as_nanos() as u64 { - return; - } - let wait = Duration::from_nanos(last.saturating_sub(now)) + 2 * CLEAR; - if Instant::now() + wait > by { - panic!("no idle second clear of the kernel's report within {QUIET_BOUND:?}: due at {due:?} ns, now {now} ns"); - } - std::thread::sleep(wait); - std::thread::scope(|s| { - for _ in 0..cpus { - s.spawn(|| { - let begun = Instant::now(); - while begun.elapsed() < WAKE { - std::hint::spin_loop(); - } - }); - } - }); - } -} - fn main() { if std::env::args().nth(1).as_deref() == Some(EXIT_AT_ONCE) { return; } let cap: SysCap = Endowments::get().take(SYSCAP_LABEL).expect("test-runner endows a capability"); - quiet(); + settle(); let idle0 = read(&cap); std::thread::sleep(IDLE); let idle1 = read(&cap);