From f2b337afd5794f289ce8d1ed6d3b6ab473feeb6a Mon Sep 17 00:00:00 2001 From: japabu Date: Thu, 8 Oct 2026 17:58:57 +0200 Subject: [PATCH 1/4] A process writes two records, its spawn's and its exit's, and the machine's census is the stop's Every process exit wrote the machine's whole census into the log: one `irq: cpuN` line per CPU, `tlb:`, the unclaimed vectors and, after an fsync, the flush census, beside `syscalls:`, `memory:` and `exit:` records of its own. On the T14's eight CPUs that is 14 records and 1,989 bytes per process counting the three records its spawn writes, 1,288 of them the eight `irq:` lines (the `testcases` readback at 809c33c0c, 8,304 children of `counters_metal`'s `loaded` phase). That phase spawns about 21,900 children in 20 s, about 43 MB of log against sixteen one-megabyte files, and the boot's own middle was deleted with the rows whose lines sat there. On a quiet boot the census was still half the log: 2,520 `irq:` lines in `shared`'s 837,108 bytes. What a process's end says now is one record: `exit: pid=N code=N cpu=Nms peak=NMB allocs=N frees=N syscalls=N syscall_wall=Nms = ...`. The verdict leads, so a profile that fills the record cuts only itself. Nothing is dropped: the fields are what `syscalls:` and `memory:` carried. A reading of the whole machine belongs to no process. The stop already took the interrupt census (`syscall::machine`'s `quiesce`), and it now takes the shootdowns' issuer census, the unclaimed vectors and the flush census there too, once a boot. The `tlb:` line is said at zero as well: an eight-CPU AArch64 boot that issued no invalidation stopped without one, and a census whose shape depends on what the boot happened to do is not one a reader can hold to. Their once-per-batch statics go: one caller, once. The flush census leads because the sealed tail keeps the newest sixteen records and it is the one no judge reads. Who read what, and where each went: - `irq_census_conservation` (the T14's `testcases`) read the census out of the log file. The stop writes after `logkeeper` has stopped, so the judge now reads the black-box page the next loader pass prints, as the panel census is read. The saved readback's page carries all eight `irq:` lines. - `common::irqcensus::observe` and `summary`, the suite's per-run table of where interrupts landed, read every guest's exit census. The harness kills its guests, so none reaches a stop, and the table would read almost nothing: it is deleted, with `issues/the-irq-census-summary-takes-a-cpus-last-stamped-line-as-its-newest-read.md`, whose subject it was. `issues/every-interrupt-lands-on-the-boot-cpu.md` says what reads the census now and that its baseline was taken with the table. - A `mask-windows` kernel printed each CPU's `windows:` line under its census line, and both metal and QEMU judges read a report per exit. That kernel now reports at each process's end on its own (`windows::report`), and no census rides with it. The judge's pairing of census and windows lines is replaced by what is left to hold: every CPU is in every report. - `syscalls:`, `memory:` and the flush census had no judge. A spawn writes one record too. `ELF: ... relocations indexed` and `spawn: TLS ...` are deleted: no judge read them, and a line a spawn writes on its way is not what a spawn says. They were the landmark of `issues/a-t14-boot-wedges-after-a-jobs-exit-and-nothing-said-why.md`, which now says its window opens at the job's exit record and closes at the one `spawn:` record. The rule is the contract in `process.rs`'s header: two records per process, each charged to it, and no reading of the whole machine at either. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01RvnWQFcMuGqTHYhvSnTe8A --- ...processs-syscall-profile-is-one-threads.md | 40 ++-- ...ddle-and-the-rows-whose-lines-sat-there.md | 24 ++- ...-after-a-jobs-exit-and-nothing-said-why.md | 10 +- .../every-interrupt-lands-on-the-boot-cpu.md | 36 ++-- ...us-last-stamped-line-as-its-newest-read.md | 21 -- kernel/src/arch/aarch64/tlb.rs | 7 +- kernel/src/arch/aarch64/trap.rs | 4 +- kernel/src/arch/x86_64/idt/unclaimed.rs | 6 +- kernel/src/arch/x86_64/tlb.rs | 8 +- kernel/src/block.rs | 14 +- kernel/src/irq_census.rs | 4 +- kernel/src/loader/mod.rs | 12 +- kernel/src/process.rs | 100 ++++++---- kernel/src/syscall/machine.rs | 7 +- kernel/src/windows.rs | 24 ++- tests/checks.rs | 24 +-- tests/common/irqcensus.rs | 179 +++--------------- tests/common/qemu.rs | 5 - tests/toyos.rs | 28 ++- 19 files changed, 216 insertions(+), 337 deletions(-) delete mode 100644 issues/the-irq-census-summary-takes-a-cpus-last-stamped-line-as-its-newest-read.md diff --git a/issues/a-processs-syscall-profile-is-one-threads.md b/issues/a-processs-syscall-profile-is-one-threads.md index 51a60df657f..8e9a7673848 100644 --- a/issues/a-processs-syscall-profile-is-one-threads.md +++ b/issues/a-processs-syscall-profile-is-one-threads.md @@ -4,20 +4,21 @@ kind: defect opened: 2026-09-04 --- -# `syscalls: pid=N` is one thread's counts under a process's name - -`ThreadData` holds `syscall_counts`, `syscall_total` and `syscall_total_ns` -(`kernel/src/process.rs:565-575`), and `teardown_resources` reads them from the -one `thread_data_arc` its caller handed it and prints them as the process's -(`kernel/src/process.rs:932-942`). `release_process` hands it the *current* -thread's (`kernel/src/process.rs:1115`, `:1130`), so the line reports whichever -thread ended the process and silently drops every other thread's calls. Its own -doc comment says "for the main thread" (`kernel/src/process.rs:911`), which is -false on that path. - -**Reproduced** on the dev host, 2026-09-04, from two captures of the same guest -binary in one session. `exit_wait_storm`'s parent spawns 24 children, waits for -all of them and joins 24 threads; when its main thread exits last the line is +# The exit record's `syscalls=` is one thread's counts under a process's name + +`ThreadData` holds `syscall_counts`, `syscall_total` and `syscall_total_ns`, +and `teardown_resources` (`kernel/src/process.rs`) reads them from the one +thread's data `teardown` hands it, the main thread's, and they go out as the +process's: in its exit record (`exit: pid=N code=N cpu=Nms peak=… allocs=… +frees=… syscalls=N syscall_wall=Nms = …`) and in the +`ProcessStats` its exit publishes. Every other thread's calls are silently +dropped. + +**Reproduced** on the dev host, 2026-09-04, when the counts were a `syscalls: +pid=N` record of their own and were those of the thread that ended the process, +from two captures of the same guest binary in one session. `exit_wait_storm`'s +parent spawns 24 children, waits for all of them and joins 24 threads; when its +main thread exits last the line is ``` syscalls: pid=7 total=204 syscall_wall=516ms 0=1 6=1 8=2 10=24 25=24 40=25 41=24 50=24 63=26 72=1 73=2 91=1 99=1 102=24 108=24 @@ -33,14 +34,11 @@ syscalls: pid=7 total=14 syscall_wall=3093ms 0=12 49=1 72=1 wait and no join in the profile, and `syscall_wall` reading the watchdog's 3 s sleep as the process's syscall time. -**Why it matters beyond the label.** The line is the only per-syscall record -the machine emits, and `tests/toyos.rs`'s `check_syscall_cost` and -`check_exit_wait_storm` both judge a guest against it. Both happen to read a -single-threaded claim made by the main thread, so both are sound today — and -neither would notice the day the thread that ends the process is not the one -that made the calls. +**Why it matters beyond the label.** The profile is the only per-syscall +record the machine emits, and no judge reads it: nothing would notice a process +whose calls were made off its main thread. **Exit condition.** The counters are summed across the process's threads at -teardown, or the line names the thread it is about; the doc comment matches +teardown, or the record names the thread it is about; the doc comment matches whichever is chosen. A gate is a guest that makes its calls on one thread and exits from another, asserting the profile carries them. diff --git a/issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md b/issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md index 286396216e3..46bbf8589ef 100644 --- a/issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md +++ b/issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md @@ -13,8 +13,28 @@ start. A metal judge reads what came back, so a line a flooding boot wrote in its middle is a line the judge reports missing, and nothing in the harness says the readback has a hole. -`testcases` is such a boot: `test_rs_counters_metal` dumps every CPU's -counters and the boot writes about forty files. +`testcases` is such a boot, and the flood was the kernel's, not the job's: +`test_rs_counters_metal`'s `loaded` phase spawns a child per CPU in a loop for +twenty seconds, and the kernel wrote fourteen records for each. + +## What a child cost, and what it costs now + +The readback of `testcases` at `809c33c0c`, 16,645,533 bytes of which the +parts that survived hold 8,304 of those children: per child 1,989 bytes in 14 +records. Eight `irq: cpuN` lines, a census of the whole machine at every +process's end, were 1,288 of them; `syscalls:` 110, `memory:` 85, `exit:` 95, +`ELF:` 107 and the two `spawn:` records 304. + +A process's end now writes one record, its `exit:`, carrying what `syscalls:` +and `memory:` said, and the machine's census is taken once, where the machine +stops. A spawn writes one record too: `ELF: … relocations indexed` and +`spawn: TLS …` are gone, which no judge read. What remains per child is the +`spawn:` record and the `exit:` record. + +**Owed:** `testcases`' log bytes and parts on the T14 with that kernel. A +child that costs less to log is a child sooner done, so the phase may spawn +more of them than that boot did, whose last pid was 21,897, and bytes per child times that +count is not yet a measurement. ## Measured diff --git a/issues/a-t14-boot-wedges-after-a-jobs-exit-and-nothing-said-why.md b/issues/a-t14-boot-wedges-after-a-jobs-exit-and-nothing-said-why.md index 6f58723ac6e..5f56cdcf6a2 100644 --- a/issues/a-t14-boot-wedges-after-a-jobs-exit-and-nothing-said-why.md +++ b/issues/a-t14-boot-wedges-after-a-jobs-exit-and-nothing-said-why.md @@ -82,8 +82,16 @@ writes the reset register itself. Every metal image carries it without a hand and leaves the records `logd` never wrote, which is the one channel that crosses a reset without `logd`. +**The two records these boots stopped at are no longer written.** A spawn +writes one record, the `spawn: pid=…` that only the boots that came +back carry, so the next occurrence's landmark is that record's absence after +the job's `exit:`: the window opens at the job's exit and takes in the whole +spawn, the VFS-lock sites this file eliminated for run 19 among them. Nothing +the spawn writes on its way places a wedge inside it any more. + **Exit condition**: a `WEDGED` record off the stick naming what the machine was -doing after `spawn: TLS 1 modules`, and then whatever that names. +doing between a job's `exit:` record and the next `spawn:` record, and then +whatever that names. **The mechanism works and the instrument is not yet sharp enough.** T14 run 21 proved the deadline: a boot wedged on purpose ended itself at 120153 ms against diff --git a/issues/every-interrupt-lands-on-the-boot-cpu.md b/issues/every-interrupt-lands-on-the-boot-cpu.md index 37d7ed41f06..12c0f95b9fc 100644 --- a/issues/every-interrupt-lands-on-the-boot-cpu.md +++ b/issues/every-interrupt-lands-on-the-boot-cpu.md @@ -41,22 +41,36 @@ the machine's, and every device shares it. where `irq_ring` and `drain_irqs` go. 4. The instrument before the change: measure interrupt distribution and the boot CPU's share under the loaded suites, so the improvement is a number - against a number. **Done — see below.** + against a number. **The baseline below was taken; the suite's half of the + instrument is gone, see "What reads the census today".** -## Instrument, and the baseline (2026-08-22) +## What reads the census today `kernel/src/irq_census.rs` counts every delivery per CPU per source in `PerCpu`, one `add qword ptr gs:[], 1` for the source; a CPU's total is -their sum. `irq: cpuN timer=… kick=… …` is printed per CPU beside the -process-exit census, on `SYS_SHUTDOWN` and on the blocked-task dump; -`common::irqcensus` aggregates every guest's newest line into the suite's own -summary, so a CI shard's log carries the number without `--nocapture`. -`irq_census_conservation` gates the present-state fact. +their sum. `irq: cpuN timer=… kick=… …` is printed per CPU once a boot, where +the machine stops, and on the blocked-task dump. `irq_census_conservation` +gates the present-state fact on the T14, off the stop's census on the +black-box page, and prints cpu0's share of that boot. -A guest that boots and runs no program reaches no process exit and prints no -census, which is why the reporting counts are short of the boots. Both columns -are one run: an interrupt count is a function of timing, so the totals move -between runs and the *distribution* is what to compare. +The QEMU suite reads no census: the harness kills its guests, so none reaches +the stop. The summary that aggregated every guest's census over a run read the +lines each process exit printed, and went with them when a process's end +stopped taking a reading of the whole machine. + +**So this track has no instrument for the loaded suites today**, which is a +present weakness of it: the distribution under load, the number step 4 was +for, can be taken on no run. What is left is one boot's census on the T14. +The change that lands a placement policy brings a reading a killed guest can +give, and takes its own baseline with it before it changes anything. + +## The baseline (2026-08-22) + +Taken with that summary. A guest that boots and runs no program reached no +process exit and printed no census, which is why the reporting counts are short +of the boots. Both columns are one run: an interrupt count is a function of +timing, so the totals move between runs and the *distribution* is what to +compare. | | dev host, TCG, 12-wide | hosted CI, KVM, twelve shards (run 32585458505) | |---|---|---| diff --git a/issues/the-irq-census-summary-takes-a-cpus-last-stamped-line-as-its-newest-read.md b/issues/the-irq-census-summary-takes-a-cpus-last-stamped-line-as-its-newest-read.md deleted file mode 100644 index ce042317847..00000000000 --- a/issues/the-irq-census-summary-takes-a-cpus-last-stamped-line-as-its-newest-read.md +++ /dev/null @@ -1,21 +0,0 @@ ---- -status: open -kind: defect -opened: 2026-10-05 ---- - -# The irq census summary takes a CPU's last stamped line as its newest read - -`common::irqcensus::observe` (`tests/common/irqcensus.rs`) keeps, per guest -and CPU, the last `irq: cpuN` line the console carried, as if that line were -the CPU's newest read. It is not. A process exit reads the counters before -`log::emit` stamps its line, two exits on two CPUs run side by side, and the -shards are merged by stamp, so the line stamped last can carry the older -read. The suite's summary then counts that CPU short by what it took between -the two reads. The judge `irq_census` (`tests/toyos.rs`) folds each CPU's -lines with `Census::raise`, the largest count per source, for this reason. - -Owner: the harness, `observe` in `tests/common/irqcensus.rs`. - -**Exit:** `observe` folds each guest's CPU lines with `Census::raise`, and -`SEEN`'s doc no longer says the last line is the whole boot. diff --git a/kernel/src/arch/aarch64/tlb.rs b/kernel/src/arch/aarch64/tlb.rs index 8b6fcfd500c..643b89b2e99 100644 --- a/kernel/src/arch/aarch64/tlb.rs +++ b/kernel/src/arch/aarch64/tlb.rs @@ -16,8 +16,6 @@ use crate::invalidation::Origin; /// Issuer-side census, as x86-64's counts it; there is no receiver side. static ISSUED: [AtomicU64; Origin::COUNT] = [const { AtomicU64::new(0) }; Origin::COUNT]; -/// Total at the last print; process exit logs once per batch. -static REPORTED: AtomicU64 = AtomicU64::new(0); macro_rules! tlbi { ($op:literal, $operand:expr) => { @@ -72,16 +70,13 @@ pub fn poll() {} /// waiting for the machine's release. pub fn join() {} -/// One `tlb:` line when the counts moved, at process exit. +/// The boot's one `tlb:` line, at the machine's stop, said at zero too. pub fn log_census() { let mut counts = [0u64; Origin::COUNT]; for (slot, count) in ISSUED.iter().zip(counts.iter_mut()) { *count = slot.load(Ordering::Relaxed); } let total: u64 = counts.iter().sum(); - if total == 0 || REPORTED.swap(total, Ordering::Relaxed) == total { - return; - } struct Fields([u64; Origin::COUNT]); impl core::fmt::Display for Fields { fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result { diff --git a/kernel/src/arch/aarch64/trap.rs b/kernel/src/arch/aarch64/trap.rs index 46838f7a0e0..3868f1f7510 100644 --- a/kernel/src/arch/aarch64/trap.rs +++ b/kernel/src/arch/aarch64/trap.rs @@ -232,12 +232,10 @@ fn irq(frame: &Frame, from_el0: bool) -> bool { /// Interrupts no handler here claims, and the last one's INTID. static UNCLAIMED: AtomicU64 = AtomicU64::new(0); static LAST_UNCLAIMED: AtomicU32 = AtomicU32::new(0); -/// The count at the last report; process exit logs once per batch. -static UNCLAIMED_REPORTED: AtomicU64 = AtomicU64::new(0); pub(crate) fn log_unclaimed() { let count = UNCLAIMED.load(Relaxed); - if count == 0 || UNCLAIMED_REPORTED.swap(count, Relaxed) == count { + if count == 0 { return; } log!("irq: unclaimed interrupts={count}, the last INTID {}", LAST_UNCLAIMED.load(Relaxed)); diff --git a/kernel/src/arch/x86_64/idt/unclaimed.rs b/kernel/src/arch/x86_64/idt/unclaimed.rs index e88871ea50e..49c57397aa8 100644 --- a/kernel/src/arch/x86_64/idt/unclaimed.rs +++ b/kernel/src/arch/x86_64/idt/unclaimed.rs @@ -17,8 +17,6 @@ use crate::arch::apic; static TAKEN: [AtomicU64; 4] = [const { AtomicU64::new(0) }; 4]; /// Deliveries that set no ISR bit, so there is no vector to blame. static NO_ISR: AtomicU64 = AtomicU64::new(0); -/// Event count at the last print; process exit logs once per batch. -static REPORTED: AtomicU64 = AtomicU64::new(0); #[unsafe(naked)] pub(super) extern "sysv64" fn unclaimed_entry() { @@ -86,7 +84,7 @@ pub fn was_taken(vector: u8) -> bool { TAKEN[(vector >> 6) as usize].load(Ordering::Relaxed) & (1 << (vector & 63)) != 0 } -/// Logs which vectors the gate absorbed, at process exit, once per batch. +/// Logs which vectors the gate absorbed, at the machine's stop. pub fn log_vectors() { let words = [ TAKEN[0].load(Ordering::Relaxed), @@ -96,7 +94,7 @@ pub fn log_vectors() { ]; let no_isr = NO_ISR.load(Ordering::Relaxed); let events = words.iter().map(|w| w.count_ones() as u64).sum::() + no_isr; - if events == 0 || REPORTED.swap(events, Ordering::Relaxed) == events { + if events == 0 { return; } struct Vectors([u64; 4]); diff --git a/kernel/src/arch/x86_64/tlb.rs b/kernel/src/arch/x86_64/tlb.rs index 75eda87bae9..d0e88c06ca7 100644 --- a/kernel/src/arch/x86_64/tlb.rs +++ b/kernel/src/arch/x86_64/tlb.rs @@ -26,11 +26,10 @@ use crate::invalidation::Origin; static ISSUED: [AtomicU64; Origin::COUNT] = [const { AtomicU64::new(0) }; Origin::COUNT]; static WAIT_NS: AtomicU64 = AtomicU64::new(0); static MAX_NS: AtomicU64 = AtomicU64::new(0); -/// Total at the last print; process exit logs once per batch. -static REPORTED: AtomicU64 = AtomicU64::new(0); -/// One machine-wide `tlb:` line when the counts moved, at process exit after +/// The boot's one machine-wide `tlb:` line, at the machine's stop after /// `irq_census::log_census`: the conservation check reads deliveries first. +/// Said at zero too: the stop's census has one shape on every boot. pub fn log_census() { let mut counts = [0u64; Origin::COUNT]; let mut total = 0u64; @@ -38,9 +37,6 @@ pub fn log_census() { *count = slot.load(Ordering::Relaxed); total += *count; } - if total == 0 || REPORTED.swap(total, Ordering::Relaxed) == total { - return; - } struct Fields<'a>(&'a [u64; Origin::COUNT]); impl core::fmt::Display for Fields<'_> { fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result { diff --git a/kernel/src/block.rs b/kernel/src/block.rs index 6e2f7607f21..607d2dbc531 100644 --- a/kernel/src/block.rs +++ b/kernel/src/block.rs @@ -509,8 +509,6 @@ pub mod census { }; DEVICES]; static LATENCY: [AtomicU64; BUCKETS] = [const { AtomicU64::new(0) }; BUCKETS]; static MAX_NS: AtomicU64 = AtomicU64::new(0); - /// Last-reported event total; suppresses a repeat print when nothing new happened. - static REPORTED: AtomicU64 = AtomicU64::new(0); fn slot(device: DeviceId) -> &'static Slot { let key = device + 1; @@ -563,21 +561,15 @@ pub mod census { 1u64 << (BUCKETS - 1) } - /// Prints the census once per batch of new events; called at process exit. - pub fn print_if_moved() { + /// What the boot flushed before its stop, said once there: a line per + /// device that was flushed or refused, and the latency of them all. + pub fn log_census() { let mut counts = [0u64; BUCKETS]; let mut total = 0u64; for (bucket, count) in LATENCY.iter().zip(counts.iter_mut()) { *count = bucket.load(Ordering::Relaxed); total += *count; } - let mut events = total; - for slot in &SLOTS { - events += slot.expiries.load(Ordering::Relaxed); - } - if events == 0 || REPORTED.swap(events, Ordering::Relaxed) == events { - return; - } for slot in &SLOTS { let id = slot.id.load(Ordering::Relaxed); if id == 0 { diff --git a/kernel/src/irq_census.rs b/kernel/src/irq_census.rs index 41b6cc13449..b8d9dd3dbd9 100644 --- a/kernel/src/irq_census.rs +++ b/kernel/src/irq_census.rs @@ -127,13 +127,11 @@ pub fn taken_here() -> u64 { } /// Logs one `irq: cpuN =…` line per online CPU; counts are cumulative since boot. -/// A `mask-windows` kernel follows each with that CPU's `windows:` line. +/// The machine's reading, so the machine's to take: at its stop and in the blocked-task dump, never at one process's end. /// Allocates nothing, takes no lock, touches no device. pub fn log_census() { for cpu in 0..crate::smp::cpu_count() { let Some(counts) = read(cpu) else { continue }; crate::log!("irq: cpu{cpu}{}", Fields(&counts)); - #[cfg(feature = "mask-windows")] - crate::windows::log_cpu(cpu); } } diff --git a/kernel/src/loader/mod.rs b/kernel/src/loader/mod.rs index cfa90ffcbd2..23cf697ad67 100644 --- a/kernel/src/loader/mod.rs +++ b/kernel/src/loader/mod.rs @@ -6,6 +6,10 @@ //! //! Every number the file names is untrusted: a refusal is //! `SyscallError::{InvalidArgument, ResourceExhausted}`, never a panic. +//! +//! A spawn that lands writes one record, `spawn: pid=…`, once the +//! process is in the table and placed; a spawn that is refused writes one, +//! naming why. Nothing is said on the way (`crate::process`'s header). // `warn`, not `deny`: the rest of the kernel is not yet swept for undocumented unsafe blocks. #![warn(clippy::undocumented_unsafe_blocks)] @@ -552,14 +556,8 @@ pub fn spawn( } reloc_index.finalize(); - let reloc_index = if reloc_index.len() > 0 { - log!("ELF: {} relocations indexed (RELATIVE + GLOB_DAT + TPOFF)", reloc_index.len()); - Some(Arc::new(reloc_index)) - } else { - None - }; + let reloc_index = if reloc_index.len() > 0 { Some(Arc::new(reloc_index)) } else { None }; - log!("spawn: TLS {} modules, total_memsz={}", tls_modules.len(), tls.total_memsz()); let Some((tls_pages, thread_pointer, _)) = tls::TlsBlock::build(&tls_modules, tls).and_then(|b| b.publish(&child_pt)) else { diff --git a/kernel/src/process.rs b/kernel/src/process.rs index 11cfcca47bc..26f40b0b303 100644 --- a/kernel/src/process.rs +++ b/kernel/src/process.rs @@ -6,6 +6,16 @@ //! this table. //! //! `kernel::proclife` decides lifecycle transitions; this file only performs them. +//! +//! **What a process writes into the log is two records**: one where its spawn +//! lands (`crate::loader`) and one where it ends, `exit: pid=N code=N +//! cpu=Nms …`, the verdict first and then what that process itself consumed. +//! A record here is charged to the process it names. A reading of the whole +//! machine — the interrupt census, the shootdowns', the flushes' — is taken +//! once, where the machine stops (`syscall::machine`), and no process's start +//! or end repeats one: the log's volume is then a function of what ran, never +//! of how many CPUs watched it. A thread that ends before its process says so +//! in a rate-limited record of its own. use alloc::alloc::{alloc_zeroed, dealloc, Layout}; use alloc::string::String; @@ -1031,12 +1041,43 @@ pub fn spawn_thread( } -/// Frees an exiting process's resources (mappings, handles, ELF state). Returns (syscall_total, syscall_total_ns) for the main thread, for the accounting snapshot. +/// What a process's exit record says it consumed beside its CPU time: its memory, and its main thread's syscalls. +struct Consumed { + peak_memory: u64, + alloc_count: u64, + free_count: u64, + syscall_total: u64, + syscall_total_ns: u64, + syscall_counts: [u32; toyos_abi::syscall::SYSCALL_PROFILE_BINS], +} + +impl core::fmt::Display for Consumed { + fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result { + write!( + f, + "peak={}MB allocs={} frees={} syscalls={} syscall_wall={}ms", + self.peak_memory / (1024 * 1024), + self.alloc_count, + self.free_count, + self.syscall_total, + self.syscall_total_ns / 1_000_000, + )?; + for (number, &count) in self.syscall_counts.iter().enumerate() { + if count > 0 { + write!(f, " {number}={count}")?; + } + } + Ok(()) + } +} + +/// Frees an exiting process's resources (mappings, handles, ELF state), and answers what it consumed. +/// Says nothing of the machine: a reading of every CPU is the stop's (`syscall::machine`), never one process's end. fn teardown_resources( process_data_arc: &Arc>, thread_data_arc: &Arc>, pid: Pid, -) -> (u64, u64) { +) -> Consumed { // Never hold ThreadData + ProcessData at once. let (syscall_total, syscall_total_ns, syscall_counts) = { let mut tdata = thread_data_arc.lock(); @@ -1046,36 +1087,11 @@ fn teardown_resources( stats }; - let mut data = process_data_arc.lock(); - - if syscall_total > 0 { - use alloc::string::String; - use core::fmt::Write; - let mut profile = String::new(); - for (i, &count) in syscall_counts.iter().enumerate() { - if count > 0 { - let _ = write!(profile, " {}={}", i, count); - } - } - let wall_ms = syscall_total_ns / 1_000_000; - log!("syscalls: pid={pid} total={} syscall_wall={wall_ms}ms{profile}", syscall_total); - // Printed here, not at shutdown: process exit is the one recurring moment a running guest reaches (the harness kills QEMU). - if syscall_counts[toyos_abi::syscall::SYS_FSYNC as usize] > 0 { - crate::block::census::print_if_moved(); - } - } - - if data.peak_memory > 0 || data.alloc_count > 0 { - log!("memory: pid={pid} peak={}MB allocs={} frees={}", - data.peak_memory / (1024 * 1024), data.alloc_count, data.free_count); - } - - // Machine-wide, cumulative counters, printed here (not at shutdown) because process exit is the one recurring moment every boot reaches. - crate::irq_census::log_census(); - // After the irq lines: the tlb conservation check reads deliveries first, issues second. - crate::arch::tlb::log_census(); - crate::arch::trap::log_unclaimed(); + // Before the teardown below: a report spans its process up to here, and the next one this teardown. + #[cfg(feature = "mask-windows")] + crate::windows::report(); + let mut data = process_data_arc.lock(); ops::close_all(&mut data.handles); // Every thread has left, and none returns to Ring 3 to use them. crate::isa::process_ends(pid); @@ -1086,18 +1102,26 @@ fn teardown_resources( data.demand_pages.clear(); data.elf.reloc_index = None; - (syscall_total, syscall_total_ns) + Consumed { + peak_memory: data.peak_memory, + alloc_count: data.alloc_count, + free_count: data.free_count, + syscall_total, + syscall_total_ns, + syscall_counts, + } } -/// Table-side teardown bookkeeping: drop the image record and total the CPU time of every thread still in the table. +/// Table-side teardown bookkeeping: drop the image record, total the CPU time of every thread still in the table, and write the one record of the process's end. /// Caller must hold `PROCESS_TABLE`, be the last thread out and have freed the resources. -fn teardown_bookkeeping(table: &mut ProcessTable, process_pid: Pid, code: i32) -> u64 { +fn teardown_bookkeeping(table: &mut ProcessTable, process_pid: Pid, code: i32, consumed: &Consumed) -> u64 { let proc = table.get_mut(process_pid) .expect("teardown_bookkeeping: process not found"); proc.image = None; let cpu_ns: u64 = proc.threads.iter().map(|(_, t)| t.sched().map_or(0, scheduler::task_cpu_ns)).sum(); let name = proc.name_str(); - log!("exit: {name} pid={process_pid} code={code} cpu={}ms", cpu_ns / 1_000_000); + // The verdict first: a record past `MAX_RECORD_MESSAGE` loses its end. + log!("exit: {name} pid={process_pid} code={code} cpu={}ms {consumed}", cpu_ns / 1_000_000); cpu_ns } @@ -1164,12 +1188,12 @@ fn teardown(pid: Pid, tid: Tid, code: i32, mark: i32, process_data: &Arc Result { // `/system/bin/supervisor` had it flush before it asked for this stop. let (stopped, stopping) = crate::quiesce::stop(); crate::log::console::drain_for_the_stop(); - // The final census: no process runs after this to report another. + // The boot's one census of the machine, and its only owner: no process's + // end takes one. Oldest first is first cut from the sealed tail, so the + // flushes lead; the shootdowns' issues follow the deliveries they bound. + crate::block::census::log_census(); crate::irq_census::log_census(); + crate::arch::tlb::log_census(); + crate::arch::trap::log_unclaimed(); crate::drivers::panic_console::log_census(); // A shortfall is the budget spent, not the reset refused: it is said at // alert level, and the reset lands anyway. diff --git a/kernel/src/windows.rs b/kernel/src/windows.rs index 74f92ea5671..c546c797f50 100644 --- a/kernel/src/windows.rs +++ b/kernel/src/windows.rs @@ -1,6 +1,7 @@ //! Each CPU's [`kernel::sched::windows::Windows`], fed where this CPU's -//! interrupts and preempt count change, and printed beside the IRQ census as -//! `windows: cpuN irqs_off_ns=… preempt_off_ns=…` (`mask-windows` builds only). +//! interrupts and preempt count change, and printed at every process's end as +//! `windows: cpuN irqs_off_ns=… preempt_off_ns=…`, a line per CPU +//! (`mask-windows` builds only). //! //! Each architecture calls [`irqs_masked`] and [`irqs_unmasking`] from every //! instruction that changes whether it takes a maskable interrupt: its @@ -161,14 +162,17 @@ pub fn woken() { on(|w| w.woken(cpu::counter)); } -/// `cpu`'s line, taking its longest windows so the next report starts from none. -pub fn log_cpu(cpu: u32) { - let (irqs, preempt) = CPUS[cpu as usize].take(); - crate::log!( - "windows: cpu{cpu} irqs_off_ns={} preempt_off_ns={}", - crate::clock::nanos_of_ticks(irqs), - crate::clock::nanos_of_ticks(preempt), - ); +/// One report: every CPU's line in CPU order, each taking that CPU's longest +/// windows so the next report starts from none. +pub fn report() { + for cpu in 0..crate::smp::cpu_count() { + let (irqs, preempt) = CPUS[cpu as usize].take(); + crate::log!( + "windows: cpu{cpu} irqs_off_ns={} preempt_off_ns={}", + crate::clock::nanos_of_ticks(irqs), + crate::clock::nanos_of_ticks(preempt), + ); + } } /// The boot's first `SYS_EXIT`, with the preempt count its entry raised, diff --git a/tests/checks.rs b/tests/checks.rs index cc7e62f99a2..c1cd67a5eb3 100644 --- a/tests/checks.rs +++ b/tests/checks.rs @@ -410,16 +410,10 @@ mod checks { #[test] fn mask_windows_verdict() -> Result<(), String> { use common::irqcensus::{windows_under, Measured}; - let census = |cpu: u32| { - format!( - "[ 0.100 cpu0 kernel] irq: cpu{cpu} timer=0 kick=0 xhci=0 userdev=0 sound=0 i8042=0 \ - dmafault=0 hda=0 tlb=0 nmi=0 spurious=0 unclaimed=0\n" - ) - }; let windows = |cpu: u32, (irqs, preempt): (u64, u64)| { format!("[ 0.100 cpu0 kernel] windows: cpu{cpu} irqs_off_ns={irqs} preempt_off_ns={preempt}\n") }; - let report = |cpu0: (u64, u64), cpu1: (u64, u64)| [census(0), windows(0, cpu0), census(1), windows(1, cpu1)].concat(); + let report = |cpu0: (u64, u64), cpu1: (u64, u64)| [windows(0, cpu0), windows(1, cpu1)].concat(); let exit = |name: &str| format!("[ 0.100 cpu0 kernel] exit: {name} pid=9 code=0 cpu=1ms\n"); let held_ns = kernel::sched::windows::HELD_NS; let hold = format!("[ 0.100 cpu1 kernel] windows: held cpu1 ns={}\n", held_ns + 7); @@ -437,9 +431,9 @@ mod checks { Err(e) if e.contains(says) => Ok(()), Err(e) => Err(format!("{what} was refused for the wrong reason: {e}")), }; - unpaired("a census without its windows", &good.replace(&windows(0, (100, 100)), ""), "went out without")?; + unpaired("a report without one of its CPUs", &good.replace(&windows(0, (100, 100)), ""), "went out without")?; unpaired("a CPU that closed no window", &report((0, 7), (3, 4)), "closed no window")?; - unpaired("one CPU of two", &[census(0), windows(0, (5, 7))].concat(), "1 of 2")?; + unpaired("one CPU of two", &windows(0, (5, 7)), "1 of 2")?; unpaired("a field missing", &good.replace(" preempt_off_ns=100", ""), "fields")?; let read = windows_under(&good, 2, &exited)?; @@ -486,12 +480,10 @@ mod checks { Ok(()) } - /// [`irq_census`] over two exits stamped in the other order from their - /// reads. X, on cpu2, reads cpu1 and is held before it stamps; Y, on cpu3, - /// reads every CPU with one more `kick` on cpu1, stamps, loads the - /// issuer's 7 and is held before its swap. Two shootdowns later X stamps - /// cpu1, reads cpu2 and cpu3 at 9 deliveries and logs 9; Y's swap then - /// returns 9, so Y logs 7. + /// [`irq_census`] over two censuses, X's from cpu2 and Y's from cpu3, whose + /// lines are in no read order: a CPU's census is the largest count each + /// source reaches on any of its lines, and the largest issuer total bounds + /// every delivery. #[test] fn irq_census_verdict() -> Result<(), String> { let census = |at: &str, on: u32, cpu: u32, kick: u64, tlb: u64| { @@ -523,7 +515,7 @@ mod checks { y_issued.clone(), ] .concat(); - irq_census(&good).map_err(|e| format!("two exits stamped out of read order were refused: {e}"))?; + irq_census(&good).map_err(|e| format!("two censuses out of read order were refused: {e}"))?; let refused = |what: &str, capture: &str, says: &str| match irq_census(capture) { Ok(()) => Err(format!("{what} was accepted")), diff --git a/tests/common/irqcensus.rs b/tests/common/irqcensus.rs index f3148de4955..8d23f78cef0 100644 --- a/tests/common/irqcensus.rs +++ b/tests/common/irqcensus.rs @@ -1,23 +1,14 @@ //! The kernel's interrupt census, and the windows a `mask-windows` kernel -//! prints beside it, read back on the host. +//! reports, read back on the host. //! -//! The guest prints `irq: cpuN timer=… kick=… …` per online CPU whenever a -//! process exits, on `SYS_SHUTDOWN` and on the blocked-task dump -//! (`kernel/src/irq_census.rs`). The counters are cumulative since boot, so the +//! The kernel prints `irq: cpuN timer=… kick=… …` per online CPU when the +//! machine stops and in the blocked-task dump (`kernel/src/irq_census.rs`), +//! and at no process's end. The counters are cumulative since boot, so the //! largest count each source reaches on a CPU's lines is that boot's whole -//! census ([`Census::raise`]). -//! -//! Two readers, and they are why this is a module rather than a closure: -//! `irq_census_conservation` asks whether one boot's census is internally -//! consistent, and the suite's own summary asks where the machine's interrupts -//! landed across every guest a run booted. The second is the instrument the -//! `every-interrupt-lands-on-the-boot-cpu` track's later change is measured -//! against, so it has to be produced by an ordinary run rather than by -//! `--nocapture`: a number only a developer's terminal can produce is not a -//! baseline. +//! census ([`Census::raise`]). `irq_census_conservation` asks whether one +//! boot's census is internally consistent. use std::collections::BTreeMap; -use std::sync::Mutex; /// The census's source names, in the order `kernel/src/irq_census.rs` prints /// them. The kernel's `Source::NAMES` is the definition; this is the host's copy @@ -92,11 +83,11 @@ impl Census { /// Raise each source to its count in `read`, another line of this CPU. /// - /// **Lines are in stamp order, not read order.** A process exit reads the - /// counters before `log::emit` stamps its line, and two exits on two CPUs - /// run side by side, so a line stamped later can carry the earlier read. - /// The counters are monotonic, so the largest count per source is the - /// newest read whatever the order of the lines. + /// **Lines are in no read order.** The stop's census comes back on the + /// black-box page newest first, and a blocked-task dump reads the counters + /// before `log::emit` stamps its lines. The counters are monotonic, so the + /// largest count per source is the newest read whatever the order of the + /// lines. pub fn raise(&mut self, read: &Self) { for (most, count) in self.by_source.iter_mut().zip(read.by_source) { *most = (*most).max(count); @@ -110,8 +101,8 @@ impl Census { } /// One CPU's longest interrupts-off and preemption-off windows since the report -/// before, out of the line a `mask-windows` kernel prints beside that CPU's -/// census (`kernel/src/windows.rs`). +/// before, out of that CPU's line of a `mask-windows` kernel's report +/// (`kernel/src/windows.rs`). #[derive(Clone, Copy, Debug, PartialEq, Eq)] pub struct Windows { pub cpu: u32, @@ -156,31 +147,27 @@ fn held(line: &str) -> Option> { Some(parsed.ok_or_else(|| format!("unreadable held line {rest:?}"))) } -/// The judge of every `mask-windows` boot, and it judges no duration: each -/// census line has its CPU's windows line beside it, and each CPU closed both -/// kinds of window at some point of the boot. Answers each CPU's longest -/// windows over the whole capture. +/// The judge of every `mask-windows` boot, and it judges no duration: every +/// CPU that reported is in every report, and each closed both kinds of window +/// at some point of the boot. Answers each CPU's longest windows over the +/// whole capture. pub fn windows(capture: &str) -> Result, String> { - let mut censuses: BTreeMap = BTreeMap::new(); let mut reports: Vec = Vec::new(); for line in capture.lines() { - if let Some(census) = Census::parse(line) { - *censuses.entry(census.map_err(|why| format!("{why}\nline: {line}"))?.cpu).or_default() += 1; - } else if let Some(report) = Windows::parse(line) { + if let Some(report) = Windows::parse(line) { reports.push(report.map_err(|why| format!("{why}\nline: {line}"))?); } } - if censuses.is_empty() { - return Err(format!("no `irq: cpu` census in the capture:\n{capture}")); + if reports.is_empty() { + return Err(format!("no `windows: cpu` report in the capture:\n{capture}")); } - let mut beside: BTreeMap = BTreeMap::new(); + let mut lines: BTreeMap = BTreeMap::new(); for report in &reports { - *beside.entry(report.cpu).or_default() += 1; + *lines.entry(report.cpu).or_default() += 1; } - if beside != censuses { + if lines.values().min() != lines.values().max() { return Err(format!( - "census lines per cpu {censuses:?} and windows lines per cpu {beside:?}: a census \ - went out without its windows, or windows without their census" + "windows lines per cpu {lines:?}: a report went out without one of its CPUs" )); } let mut longest: BTreeMap = BTreeMap::new(); @@ -296,121 +283,3 @@ pub fn windows_under(capture: &str, cpus: u32, load_exited: &str) -> Result>> = Mutex::new(BTreeMap::new()); - -/// Offer one console line to the census. Called from every boot's reader thread, -/// on every line, so it does the cheapest possible thing first. -pub fn observe(seq: u32, line: &str) { - if !line.contains("irq: cpu") { - return; - } - let Some(Ok(census)) = Census::parse(line) else { - return; - }; - let mut seen = SEEN.lock().expect("census map poisoned"); - seen.entry(seq).or_default().insert(census.cpu, census); -} - -/// One guest's whole census. -struct Guest { - /// Interrupts on cpu0 as a fraction of the machine's. - boot_cpu_share: f64, - /// Interrupts on cpu0, so the run's pooled share is an exact ratio of two - /// integers rather than a mean of per-guest fractions. - on_boot_cpu: u64, - total: u64, - /// Per source, summed over every CPU, and the cpu0 part of it. - per_source: [(u64, u64); SOURCES.len()], - cpus: usize, -} - -fn guests() -> Vec { - let seen = SEEN.lock().expect("census map poisoned"); - seen.values() - .filter_map(|by_cpu| { - let total: u64 = by_cpu.values().map(Census::total).sum(); - if total == 0 { - return None; - } - let boot = by_cpu.get(&0).map_or(0, Census::total); - let mut per_source = [(0u64, 0u64); SOURCES.len()]; - for census in by_cpu.values() { - for (slot, count) in per_source.iter_mut().zip(census.by_source) { - slot.0 += count; - if census.cpu == 0 { - slot.1 += count; - } - } - } - Some(Guest { - boot_cpu_share: boot as f64 / total as f64, - on_boot_cpu: boot, - total, - per_source, - cpus: by_cpu.len(), - }) - }) - .collect() -} - -/// The order statistic at `q` of an already-sorted sample, nearest-rank. -fn quantile(sorted: &[f64], q: f64) -> f64 { - if sorted.is_empty() { - return f64::NAN; - } - let rank = ((sorted.len() as f64) * q).ceil() as usize; - sorted[rank.clamp(1, sorted.len()) - 1] -} - -/// What this run saw, as the suite's last word before its tally. -/// -/// Empty when no guest printed a census — a filtered run of boot-only tests is -/// exactly that, and a summary claiming a distribution it never measured would -/// be worse than none. -pub fn summary() -> String { - use std::fmt::Write; - let guests = guests(); - if guests.is_empty() { - return String::new(); - } - let mut shares: Vec = guests.iter().map(|g| g.boot_cpu_share).collect(); - shares.sort_by(|a, b| a.partial_cmp(b).expect("a share is never NaN")); - let total: u64 = guests.iter().map(|g| g.total).sum(); - let mut out = String::new(); - let on_boot_cpu: u64 = guests.iter().map(|g| g.on_boot_cpu).sum(); - let _ = writeln!( - out, - " --- irq census: {} guest(s) reported, {} interrupt(s), {on_boot_cpu} of them on cpu0 \ - ({:.1}%); per guest cpu0's share is median {:.1}% p90 {:.1}% max {:.1}%", - guests.len(), - total, - on_boot_cpu as f64 / total as f64 * 100.0, - quantile(&shares, 0.5) * 100.0, - quantile(&shares, 0.9) * 100.0, - shares[shares.len() - 1] * 100.0, - ); - for (i, name) in SOURCES.iter().enumerate() { - let all: u64 = guests.iter().map(|g| g.per_source[i].0).sum(); - if all == 0 { - continue; - } - let on_boot_cpu: u64 = guests.iter().map(|g| g.per_source[i].1).sum(); - let _ = writeln!( - out, - " {name:<9} {all:>9} ({:.1}% of all), {:.1}% of them on cpu0", - all as f64 / total as f64 * 100.0, - on_boot_cpu as f64 / all as f64 * 100.0, - ); - } - let widest = guests.iter().map(|g| g.cpus).max().unwrap_or(0); - let _ = writeln!(out, " widest guest reported {widest} cpu(s)"); - out -} diff --git a/tests/common/qemu.rs b/tests/common/qemu.rs index cb7a278d3c8..22ad5752d3e 100644 --- a/tests/common/qemu.rs +++ b/tests/common/qemu.rs @@ -2344,11 +2344,6 @@ fn publish_line( let Ok(line) = String::from_utf8(raw) else { return false }; full_log.push_str(&line); full_log.push('\n'); - // Here rather than in a caller's capture, because no caller holds every - // line: `boot_log` ends at the ready marker and a `TestResult` begins at - // `===TEST_START===`. The census is cumulative, so what the suite's summary - // wants is the last one of the boot, whichever of those windows it fell in. - super::irqcensus::observe(seq, &line); if VERBOSE.load(Ordering::Relaxed) { // The boot's own number, because `--nocapture` on a wide run is several // guests talking into one terminal and an unattributed line is worse diff --git a/tests/toyos.rs b/tests/toyos.rs index 6b3934f0f6d..c30c456ee58 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -350,14 +350,16 @@ const METAL: &[(&str, metal::Metal)] = &[ ), ( "irq_census_conservation", + // Off the page: the stop takes the boot's one census after + // `logkeeper` has stopped, so no file carries it. metal::Metal { arms: TESTCASES, - judge: |b| irq_census(b[0].kernel().text()), + judge: |b| irq_census(b[0].after_the_reset()?.text()), }, ), ( - // The windows on the machine that owes them: every CPU reported beside - // its census, and a held window read back. + // The windows on the machine that owes them: every CPU in every + // report, and a held window read back. "mask_windows", metal::Metal { arms: WINDOWSCASE, judge: |b| windows_on_metal(b[0]) }, ), @@ -1926,7 +1928,7 @@ fn virt_mask_windows(profile: qemu::Profile) -> Result<(), String> { }); let mut serial = virt_console(&qemu); judge_virt_job(&mut qemu, &mut serial, "unmap_touch", UNMAP_TOUCH_SAID)?; - // To the boot's last word, said after every census and its windows: the drain that took the job's end can stop between the two. + // To the boot's last word, said after every report: the drain that took the job's end can stop inside one. await_marker(&mut qemu, &mut serial, power::SHUTTING_DOWN, "the boot's last word")?; mask_windows(&serial, VIRT_CPUS) } @@ -2995,7 +2997,7 @@ fn irq_census(capture: &str) -> Result<(), String> { } if newest.is_empty() { return Err(format!( - "no `irq: cpu` census in the capture — a process exited and the kernel \ + "no `irq: cpu` census in the capture — the machine stopped and the kernel \ said nothing:\n{capture}" )); } @@ -3061,9 +3063,8 @@ fn irq_census(capture: &str) -> Result<(), String> { // must be within the issues a `tlb:` line counted — an excess // is a path shooting down uncounted. The lower bound is not // asserted: an issued IPI can be pending on an IF-clear target. - // The bound is the largest count: an exit reads its deliveries - // before the issuer's total, and whichever exit first swaps a - // total into `tlb::REPORTED` logs it. + // The bound is the largest count: the stop reads the deliveries + // before the issuer's total. let mut issued: Option = None; for line in capture.lines() { let Some(rest) = line.split("tlb: shootdowns=").nth(1) else { continue }; @@ -3077,8 +3078,8 @@ fn irq_census(capture: &str) -> Result<(), String> { } let Some(issued) = issued else { return Err(format!( - "no `tlb: shootdowns=` census in the capture — two process exits on a \ - 4-CPU guest and the issuer side said nothing:\n{capture}" + "no `tlb: shootdowns=` census in the capture — the machine stopped and \ + the issuer side said nothing:\n{capture}" )); }; for census in newest.values() { @@ -5130,12 +5131,7 @@ fn main() { kernels.len(), ); - // Where this run's interrupts landed, aggregated over every guest that - // said. `issues/every-interrupt-lands-on-the-boot-cpu.md`'s step 4: - // the number its later change is measured against, produced by an ordinary - // run rather than by `--nocapture`, so a CI run's own log carries it. - let census = common::irqcensus::summary(); let summary = tally.summary(total, suite_start.elapsed(), suite_start.suspended()); - census.lines().chain(summary.lines()).for_each(|line| eprintln!("{line}")); + summary.lines().for_each(|line| eprintln!("{line}")); run.exit(tally.exit_code()); } From c6269f8851bc595e9c40ad3154877a1eafd1ad29 Mon Sep 17 00:00:00 2001 From: japabu Date: Thu, 8 Oct 2026 20:44:16 +0200 Subject: [PATCH 2/4] The log contract is made true of every program, and a machine that dies takes the census too The review of f2b337afd found the header's contract false in five places. Each is closed by making the kernel do what the header says. A spawn writes one record for a dynamically linked program too. The loader and `crate::elf` under it wrote `dynamic: N exe symbols available`, `dynamic: loaded ` and, on every spawn and every library, `dlopen: cache hit`, `dlopen: cached`, `dlopen: base=`, `dlopen: applied N ... relocs`, and one record per unresolved symbol (`dynamic: unresolved exe symbol`, `dynamic: lib unresolved symbol`, `dtpmod:`/`tls: unresolved TLS symbol`), a count the file chooses and nothing bounded. All go. `elf::reloc`'s stated policy is that an unresolved symbol is untrusted input, never fatal, and faults only if used, so a spawn is not refused for one: each function answers how many it left and the spawn's record carries the sum as `unresolved=N`. `dlopen` shares those functions, so it says one record where it lands, `dlopen: pid=N unresolved=N`, in place of the lines they wrote for it. The `spawn:` record loses `tid=`, `dst=`, `base=`, `entry=` and `root=`: no judge or tool reads them, and two were one value on every record. Its timings stay; a slow spawn is read by them (`issues/a-t14-wedge-ran-the-deadline-out-and-sealed-nothing.md`). A thread's end writes nothing. Its record went through `log_limited!`, one static per site, so one process's thread ends suppressed another's: a limiter is not a strategy. The record, `log_limited!`, `Limited`, `LIMIT_BURST` and `LIMIT_WINDOW_NS` are deleted, and the kernel's dependency on `toyos-elide` with them. No judge read the record; no `threads=` is added, since the count at teardown is of threads still in the table, not of threads the process ran, and nothing reads it. The census is one module, `kernel/src/census.rs`, with one shape on every boot: `irq:` per CPU, `tlb:`, the unclaimed line (said at zero now), the panel. Each source hands its lines to a sink. The stop logs them; a panic, the hard-lockup seal and the deadline's seal write them into the record they seal, because a death seals from an NMI or an interrupt entry and may not log there. Every reading is a relaxed load of an atomic: no lock, no allocation, no device. The flush census is deleted with the counters only it read: nothing read it, and it had been placed to be the first thing cut. The stop seals its own records: every record from a stamp taken before the census, newest first, bounded by what a report may spend of the page, and saying how many older ones it dropped in the words a death's tail uses. The sixteen-record constant is gone, and with it the ordering of the census around it. A `mask-windows` kernel reports at the stop as well as at each process's end. The three death judges (`deadline_wedge_chain`, `usb_load_chain`, `hard_lockup_chain`) now require the census on the sealed page. Issues kept true: the retention issue takes the T14 reading at f2b337afd and says its margin is a factor; the wedge issue, the late-deadline issue and the xHCI storm issue say where their census comes from now; the issue about a thread's exit record after the last word says the record is gone and its question is not. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01RvnWQFcMuGqTHYhvSnTe8A --- Cargo.lock | 1 - ...eadline-fired-132859-ms-late-on-the-t14.md | 6 + ...record-landed-under-the-boots-last-word.md | 5 + ...ddle-and-the-rows-whose-lines-sat-there.md | 22 +-- ...-after-a-jobs-exit-and-nothing-said-why.md | 4 + ...hci-storm-starves-the-cpu-that-takes-it.md | 8 + kernel/Cargo.toml | 1 - kernel/src/arch/aarch64/tlb.rs | 6 +- kernel/src/arch/aarch64/trap.rs | 8 +- kernel/src/arch/x86_64/idt/mod.rs | 2 +- kernel/src/arch/x86_64/idt/unclaimed.rs | 10 +- kernel/src/arch/x86_64/tlb.rs | 11 +- kernel/src/blackbox.rs | 3 + kernel/src/block.rs | 94 +----------- kernel/src/census.rs | 45 ++++++ kernel/src/drivers/panic_console/mod.rs | 14 +- kernel/src/drivers/usb_storage.rs | 18 +-- kernel/src/elf/cache.rs | 19 +-- kernel/src/elf/mod.rs | 18 --- kernel/src/elf/reloc.rs | 144 ++++++++---------- kernel/src/irq_census.rs | 8 +- kernel/src/loader/mod.rs | 61 ++++---- kernel/src/log/mod.rs | 96 +++++------- kernel/src/main.rs | 1 + kernel/src/process.rs | 24 ++- kernel/src/sched/dump.rs | 2 +- kernel/src/syscall/machine.rs | 21 ++- kernel/src/syscall/vm.rs | 27 ++-- kernel/src/windows.rs | 6 +- tests/checks.rs | 16 +- tests/common/irqcensus.rs | 6 +- tests/common/power.rs | 14 ++ toyos-elide/src/limit.rs | 10 +- 33 files changed, 321 insertions(+), 410 deletions(-) create mode 100644 kernel/src/census.rs diff --git a/Cargo.lock b/Cargo.lock index 284d9e3eac5..1a7762a0317 100644 --- a/Cargo.lock +++ b/Cargo.lock @@ -3039,7 +3039,6 @@ dependencies = [ "toyos-cpuvuln", "toyos-dma", "toyos-elf", - "toyos-elide", "toyos-fat32", "toyos-gicv3", "toyos-gpt", diff --git a/issues/a-120000-ms-boot-deadline-fired-132859-ms-late-on-the-t14.md b/issues/a-120000-ms-boot-deadline-fired-132859-ms-late-on-the-t14.md index 61f99e88c3a..6879f92b629 100644 --- a/issues/a-120000-ms-boot-deadline-fired-132859-ms-late-on-the-t14.md +++ b/issues/a-120000-ms-boot-deadline-fired-132859-ms-late-on-the-t14.md @@ -104,6 +104,12 @@ could not be loaded, and the disk went offline at 5.556 s. A boot with no runner asks for no reboot; the deadline was the only bound left, and it fired 133 s late. +**That tail's census was two processes' ends, and a process's end takes none +now.** The next occurrence carries one census, the deadline's own: `expire` +seals the machine's census into the `WEDGED` record above the ring's tail +(`kernel/src/census.rs`), read at the moment the bound fired rather than at +whichever process last died before it. + ## The instrument that measures this already exists `src/metal.rs:1591-1597`'s `deadline_lateness_ms` computes exactly diff --git a/issues/a-jobs-exit-record-landed-under-the-boots-last-word.md b/issues/a-jobs-exit-record-landed-under-the-boots-last-word.md index 605e3484a72..4167e10f6bd 100644 --- a/issues/a-jobs-exit-record-landed-under-the-boots-last-word.md +++ b/issues/a-jobs-exit-record-landed-under-the-boots-last-word.md @@ -25,6 +25,11 @@ Not known: whether the job's exit is a transition the stop is meant to have seen before it writes the last word, or a record the stop should keep from the console once it has. +**The record is gone and the question is not.** A thread's end no longer +writes a record, so this line cannot reach the console after the last word; +whether a thread may still be leaving once the stop has said it is what the +deleted test asked, and nothing asks it now. + ## Exit condition A job's exit record either precedes the boot's last word or never reaches the diff --git a/issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md b/issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md index 46bbf8589ef..679e6f6a827 100644 --- a/issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md +++ b/issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md @@ -26,15 +26,19 @@ process's end, were 1,288 of them; `syscalls:` 110, `memory:` 85, `exit:` 95, `ELF:` 107 and the two `spawn:` records 304. A process's end now writes one record, its `exit:`, carrying what `syscalls:` -and `memory:` said, and the machine's census is taken once, where the machine -stops. A spawn writes one record too: `ELF: … relocations indexed` and -`spawn: TLS …` are gone, which no judge read. What remains per child is the -`spawn:` record and the `exit:` record. - -**Owed:** `testcases`' log bytes and parts on the T14 with that kernel. A -child that costs less to log is a child sooner done, so the phase may spawn -more of them than that boot did, whose last pid was 21,897, and bytes per child times that -count is not yet a measurement. +and `memory:` said; a spawn writes one, its `spawn:`; and the machine's census +is taken once, where the machine ends (`kernel/src/census.rs`). + +`testcases` on the T14 at `f2b337afd`, the first head with two records a +process: 8,730,435 bytes, no part deleted, 22,091 `spawn:` and 22,081 `exit: … +pid=` records, 390 bytes a child against 1,989. + +**The margin is a factor, not a bound.** 8.73 MB is 52% of the sixteen +megabytes kept, 98.7% of it still that one job's `spawn:` and `exit:` records, +and the phase spawns a child per CPU for twenty seconds: about 1.9 times the +children, a sixteen-CPU machine or a faster one, outlogs the retention again. +**The harness is as silent about a hole as it was**: nothing reds a readback +whose own boot deleted a part of its log. ## Measured diff --git a/issues/a-t14-boot-wedges-after-a-jobs-exit-and-nothing-said-why.md b/issues/a-t14-boot-wedges-after-a-jobs-exit-and-nothing-said-why.md index 5f56cdcf6a2..760bef657f4 100644 --- a/issues/a-t14-boot-wedges-after-a-jobs-exit-and-nothing-said-why.md +++ b/issues/a-t14-boot-wedges-after-a-jobs-exit-and-nothing-said-why.md @@ -89,6 +89,10 @@ the job's `exit:`: the window opens at the job's exit and takes in the whole spawn, the VFS-lock sites this file eliminated for run 19 among them. Nothing the spawn writes on its way places a wedge inside it any more. +The `WEDGED` record this file waits for carries the machine's census, sealed +by the deadline itself above the ring's tail (`kernel/src/census.rs`): every +CPU's interrupt counts and the shootdowns' at the moment the bound fired. + **Exit condition**: a `WEDGED` record off the stick naming what the machine was doing between a job's `exit:` record and the next `spawn:` record, and then whatever that names. diff --git a/issues/an-xhci-storm-starves-the-cpu-that-takes-it.md b/issues/an-xhci-storm-starves-the-cpu-that-takes-it.md index c1a979b2378..e7c1fc86298 100644 --- a/issues/an-xhci-storm-starves-the-cpu-that-takes-it.md +++ b/issues/an-xhci-storm-starves-the-cpu-that-takes-it.md @@ -33,6 +33,14 @@ again, and the cycle costs it the interrupt budget it needed for its own timer. That is a CPU making no progress while looking busy, and it is the state `crate::deadline`'s poll relies on *some* CPU escaping. +**Where the next reading comes from.** The census above was read out of the +log file, where each process's end had written one. No process's end writes +one now: the machine's census is taken where the machine ends, as records at +its stop and in the record its death seals (`kernel/src/census.rs`). A storm +that ends in the deadline or the lockup detector is read off the black-box +page; one the machine survives leaves no `irq:` line in the file until the +stop, and its rate over a stretch of the boot is not read by anything. + **What would fix it**: the interrupter's `IMAN.IE` masked when the poll declines the lock and cleared by whoever takes it — so a controller whose driver is busy raises one interrupt and not a hundred thousand — or an event-ring drain that diff --git a/kernel/Cargo.toml b/kernel/Cargo.toml index fbe1e56b174..102130680c1 100644 --- a/kernel/Cargo.toml +++ b/kernel/Cargo.toml @@ -483,7 +483,6 @@ toyos-abi = { path = "../toyos-abi" } bcachefs = { path = "../bcachefs", default-features = false } toyos-acpi = { path = "../toyos-acpi" } toyos-dma = { path = "dma" } -toyos-elide = { path = "../toyos-elide" } toyos-blackbox = { path = "../toyos-blackbox" } toyos-blockhold = { path = "../toyos-blockhold" } toyos-bootmap = { path = "../toyos-bootmap" } diff --git a/kernel/src/arch/aarch64/tlb.rs b/kernel/src/arch/aarch64/tlb.rs index 643b89b2e99..b8a028933cc 100644 --- a/kernel/src/arch/aarch64/tlb.rs +++ b/kernel/src/arch/aarch64/tlb.rs @@ -70,8 +70,8 @@ pub fn poll() {} /// waiting for the machine's release. pub fn join() {} -/// The boot's one `tlb:` line, at the machine's stop, said at zero too. -pub fn log_census() { +/// The `tlb:` line of `crate::census`, said at zero too. +pub fn census(say: &mut impl FnMut(core::fmt::Arguments<'_>)) { let mut counts = [0u64; Origin::COUNT]; for (slot, count) in ISSUED.iter().zip(counts.iter_mut()) { *count = slot.load(Ordering::Relaxed); @@ -86,7 +86,7 @@ pub fn log_census() { Ok(()) } } - crate::log!("tlb: broadcast invalidations={total}{}", Fields(counts)); + say(format_args!("tlb: broadcast invalidations={total}{}", Fields(counts))); } /// x86-64's measures an IPI round trip, and there is none here. diff --git a/kernel/src/arch/aarch64/trap.rs b/kernel/src/arch/aarch64/trap.rs index 3868f1f7510..2ac9947151c 100644 --- a/kernel/src/arch/aarch64/trap.rs +++ b/kernel/src/arch/aarch64/trap.rs @@ -233,12 +233,10 @@ fn irq(frame: &Frame, from_el0: bool) -> bool { static UNCLAIMED: AtomicU64 = AtomicU64::new(0); static LAST_UNCLAIMED: AtomicU32 = AtomicU32::new(0); -pub(crate) fn log_unclaimed() { +/// The unclaimed interrupts' line of `crate::census`, said at zero too. +pub(crate) fn unclaimed_census(say: &mut impl FnMut(core::fmt::Arguments<'_>)) { let count = UNCLAIMED.load(Relaxed); - if count == 0 { - return; - } - log!("irq: unclaimed interrupts={count}, the last INTID {}", LAST_UNCLAIMED.load(Relaxed)); + say(format_args!("irq: unclaimed interrupts={count}, the last INTID {}", LAST_UNCLAIMED.load(Relaxed))); } /// A synchronous exception from EL0: a syscall, a fault the demand pager may diff --git a/kernel/src/arch/x86_64/idt/mod.rs b/kernel/src/arch/x86_64/idt/mod.rs index 26d5f9c0f77..4194826b6ab 100644 --- a/kernel/src/arch/x86_64/idt/mod.rs +++ b/kernel/src/arch/x86_64/idt/mod.rs @@ -536,6 +536,6 @@ pub(crate) fn provoke_double_fault() -> ! { } } -pub(crate) use unclaimed::log_vectors as log_unclaimed; +pub(crate) use unclaimed::census as unclaimed_census; /// How much of the double-fault stack the crash report used, once the report is out. pub(crate) use super::percpu::ist1_report as report_fault_stack; diff --git a/kernel/src/arch/x86_64/idt/unclaimed.rs b/kernel/src/arch/x86_64/idt/unclaimed.rs index 49c57397aa8..c371a8f3404 100644 --- a/kernel/src/arch/x86_64/idt/unclaimed.rs +++ b/kernel/src/arch/x86_64/idt/unclaimed.rs @@ -84,8 +84,8 @@ pub fn was_taken(vector: u8) -> bool { TAKEN[(vector >> 6) as usize].load(Ordering::Relaxed) & (1 << (vector & 63)) != 0 } -/// Logs which vectors the gate absorbed, at the machine's stop. -pub fn log_vectors() { +/// Which vectors the gate absorbed, for `crate::census`: said when there are none too. +pub fn census(say: &mut impl FnMut(core::fmt::Arguments<'_>)) { let words = [ TAKEN[0].load(Ordering::Relaxed), TAKEN[1].load(Ordering::Relaxed), @@ -93,10 +93,6 @@ pub fn log_vectors() { TAKEN[3].load(Ordering::Relaxed), ]; let no_isr = NO_ISR.load(Ordering::Relaxed); - let events = words.iter().map(|w| w.count_ones() as u64).sum::() + no_isr; - if events == 0 { - return; - } struct Vectors([u64; 4]); impl core::fmt::Display for Vectors { fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result { @@ -108,7 +104,7 @@ pub fn log_vectors() { Ok(()) } } - crate::log!("irq: unclaimed vectors{} no-isr={no_isr}", Vectors(words)); + say(format_args!("irq: unclaimed vectors{} no-isr={no_isr}", Vectors(words))); } /// Raises a vector no row claims and verifies the gate counted, remembered, diff --git a/kernel/src/arch/x86_64/tlb.rs b/kernel/src/arch/x86_64/tlb.rs index d0e88c06ca7..902752dc763 100644 --- a/kernel/src/arch/x86_64/tlb.rs +++ b/kernel/src/arch/x86_64/tlb.rs @@ -27,10 +27,9 @@ static ISSUED: [AtomicU64; Origin::COUNT] = [const { AtomicU64::new(0) }; Origin static WAIT_NS: AtomicU64 = AtomicU64::new(0); static MAX_NS: AtomicU64 = AtomicU64::new(0); -/// The boot's one machine-wide `tlb:` line, at the machine's stop after -/// `irq_census::log_census`: the conservation check reads deliveries first. -/// Said at zero too: the stop's census has one shape on every boot. -pub fn log_census() { +/// The machine-wide `tlb:` line of `crate::census`, after the `irq:` lines: +/// the conservation check reads deliveries first. Said at zero too. +pub fn census(say: &mut impl FnMut(core::fmt::Arguments<'_>)) { let mut counts = [0u64; Origin::COUNT]; let mut total = 0u64; for (slot, count) in ISSUED.iter().zip(counts.iter_mut()) { @@ -46,12 +45,12 @@ pub fn log_census() { Ok(()) } } - crate::log!( + say(format_args!( "tlb: shootdowns={total} wait={}us max={}us{}", WAIT_NS.load(Ordering::Relaxed) / 1_000, MAX_NS.load(Ordering::Relaxed) / 1_000, Fields(&counts) - ); + )); } /// Spins between deadline checks; `nanos_since_boot`'s 128-bit divide is too diff --git a/kernel/src/blackbox.rs b/kernel/src/blackbox.rs index 53fae297daf..6f3913e06a1 100644 --- a/kernel/src/blackbox.rs +++ b/kernel/src/blackbox.rs @@ -96,6 +96,9 @@ pub fn record_panic(records: &[u8]) { // its tail alone is a report with the crash missing: the panel's newest // lines are the ones written after it. crate::panic::first_words(&mut report); + // The machine's census, which a death takes as a stop does: atomics + // alone, so it is inside this region's rules (`crate::census`). + let _ = core::fmt::Write::write_fmt(&mut report, format_args!("{}", crate::census::Sealed)); crate::log::recovery::seal_into(&mut report); report.tail(records, toyos_blackbox::RECORD_OPENS_WITH); report.seal(State::Panic, stamp, identity); diff --git a/kernel/src/block.rs b/kernel/src/block.rs index 607d2dbc531..1773e72539f 100644 --- a/kernel/src/block.rs +++ b/kernel/src/block.rs @@ -485,42 +485,9 @@ pub fn file_cache_pages() -> usize { (((total / 64) / PAGE_SIZE) as usize).clamp(2048, 65536) } -/// Flush-latency census backing the `OPERATION`/`DEADMAN` budgets. +/// What the storage drivers count for the machine. pub mod census { - use core::sync::atomic::{AtomicU32, AtomicU64, Ordering}; - - use super::DeviceId; - - /// Distinct devices the census can hold apart; extra devices alias into the last slot. - const DEVICES: usize = 4; - /// log2-µs latency buckets: bucket `i` holds flushes under `2^i` µs; the last holds everything from 2s up. - const BUCKETS: usize = 32; - - struct Slot { - /// The device id plus one, so zero means empty. - id: AtomicU32, - flushes: AtomicU64, - /// Operations refused on the caller's budget (`BlockError::BudgetExpired`). - expiries: AtomicU64, - } - - static SLOTS: [Slot; DEVICES] = [const { - Slot { id: AtomicU32::new(0), flushes: AtomicU64::new(0), expiries: AtomicU64::new(0) } - }; DEVICES]; - static LATENCY: [AtomicU64; BUCKETS] = [const { AtomicU64::new(0) }; BUCKETS]; - static MAX_NS: AtomicU64 = AtomicU64::new(0); - - fn slot(device: DeviceId) -> &'static Slot { - let key = device + 1; - for slot in &SLOTS { - match slot.id.compare_exchange(0, key, Ordering::Relaxed, Ordering::Relaxed) { - Ok(_) => return slot, - Err(held) if held == key => return slot, - Err(_) => {} - } - } - &SLOTS[DEVICES - 1] - } + use core::sync::atomic::{AtomicU64, Ordering}; /// Every command a storage driver has put to a disk, counted /// where each driver hands one to its transport: the one number that says a @@ -534,61 +501,4 @@ pub mod census { pub fn commands_issued() -> u64 { COMMANDS.load(Ordering::Relaxed) } - - /// One device flush completed (either way), taking `nanos` of wall clock. - pub fn flush_took(device: DeviceId, nanos: u64) { - slot(device).flushes.fetch_add(1, Ordering::Relaxed); - let micros = nanos / 1_000; - let bucket = (64 - u64::leading_zeros(micros | 1) as usize).min(BUCKETS - 1); - LATENCY[bucket].fetch_add(1, Ordering::Relaxed); - MAX_NS.fetch_max(nanos, Ordering::Relaxed); - } - - /// One operation on `device` was refused on the caller's budget. - pub fn budget_expired(device: DeviceId) { - slot(device).expiries.fetch_add(1, Ordering::Relaxed); - } - - /// Latency ceiling (µs) at or below which `want` percent of `total` samples fall. - fn percentile(counts: &[u64; BUCKETS], total: u64, want: u64) -> u64 { - let mut seen = 0u64; - for (i, &count) in counts.iter().enumerate() { - seen += count; - if seen * 100 >= total * want { - return 1u64 << i; - } - } - 1u64 << (BUCKETS - 1) - } - - /// What the boot flushed before its stop, said once there: a line per - /// device that was flushed or refused, and the latency of them all. - pub fn log_census() { - let mut counts = [0u64; BUCKETS]; - let mut total = 0u64; - for (bucket, count) in LATENCY.iter().zip(counts.iter_mut()) { - *count = bucket.load(Ordering::Relaxed); - total += *count; - } - for slot in &SLOTS { - let id = slot.id.load(Ordering::Relaxed); - if id == 0 { - continue; - } - crate::log!( - "flush-census: dev={} flushes={} expiries={}", - id - 1, - slot.flushes.load(Ordering::Relaxed), - slot.expiries.load(Ordering::Relaxed), - ); - } - if total > 0 { - crate::log!( - "flush-census: p50<={}us p99<={}us max={}us of {total} flushes", - percentile(&counts, total, 50), - percentile(&counts, total, 99), - MAX_NS.load(Ordering::Relaxed) / 1_000, - ); - } - } } diff --git a/kernel/src/census.rs b/kernel/src/census.rs new file mode 100644 index 00000000000..527b36bd736 --- /dev/null +++ b/kernel/src/census.rs @@ -0,0 +1,45 @@ +//! The machine's census: every reading of the whole machine this kernel +//! says, in one shape on every boot, taken once, where the machine ends. +//! +//! A machine ends at its stop or at its death, and both take it: the stop +//! logs it as records ([`log`]), and a panic, the hard-lockup detector and the +//! boot deadline write it into the record they seal ([`Sealed`]). No process's +//! start or end takes one (`crate::process`'s header). +//! +//! **Every reading here is a relaxed load of an atomic**: no lock, no +//! allocation, no device, nothing that can panic. A death seals from an NMI or +//! an interrupt entry, on a machine whose every lock may be held, and may not +//! log there either, since it can have interrupted the log's own commit: so +//! each source hands its lines to a sink, and the sink decides where they go. +//! A source added here keeps to that or does not go in. + +use core::fmt; + +/// Every line of the census, oldest reading first: the deliveries before the +/// shootdowns' issuer total that bounds them. +fn each(mut say: impl FnMut(fmt::Arguments<'_>)) { + crate::irq_census::census(&mut say); + crate::arch::tlb::census(&mut say); + crate::arch::trap::unclaimed_census(&mut say); + crate::drivers::panic_console::census(&mut say); +} + +/// The stop's: one record a line. +pub fn log() { + each(|line| crate::log!("{line}")); +} + +/// A death's: the same lines as text, for the record it seals. +pub struct Sealed; + +impl fmt::Display for Sealed { + fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { + let mut wrote = Ok(()); + each(|line| { + if wrote.is_ok() { + wrote = writeln!(f, "{line}"); + } + }); + wrote + } +} diff --git a/kernel/src/drivers/panic_console/mod.rs b/kernel/src/drivers/panic_console/mod.rs index 837761a7f55..ec0ae38983a 100644 --- a/kernel/src/drivers/panic_console/mod.rs +++ b/kernel/src/drivers/panic_console/mod.rs @@ -695,10 +695,10 @@ pub fn render() -> bool { /// that never reached the log file, which are the newest ones. pub fn seal_wedge(said: core::fmt::Arguments) { if PAINTING.swap(true, Ordering::SeqCst) { - crate::blackbox::record_wedge(format_args!("{said}{Census}\n"), &[]); + crate::blackbox::record_wedge(format_args!("{said}{}", crate::census::Sealed), &[]); return; } - crate::blackbox::record_wedge(format_args!("{said}{Census}\n"), live_tail().text); + crate::blackbox::record_wedge(format_args!("{said}{}", crate::census::Sealed), live_tail().text); } /// Keep the panel as it is until `bound` resets the machine: the panic path's @@ -1068,9 +1068,7 @@ static TICKS_MAX: AtomicU64 = AtomicU64::new(0); /// The head `src/bootlog.rs` reads the census by. const CENSUS: &str = "panel: paints="; -/// One line, written to the two channels a boot can end on: [`log_census`] for -/// a boot that hands the machine back, and [`seal_wedge`] for one a bound ends -/// with no `logkeeper` left to write a file. +/// The panel's line of `crate::census`. struct Census; impl core::fmt::Display for Census { @@ -1087,9 +1085,9 @@ impl core::fmt::Display for Census { } } -/// The panel's own row in the shutdown census, beside `irq:`. -pub fn log_census() { - log!("{Census}"); +/// The panel's own row in the machine's census. +pub fn census(say: &mut impl FnMut(core::fmt::Arguments<'_>)) { + say(format_args!("{Census}")); } /// Charge one paint to the census. diff --git a/kernel/src/drivers/usb_storage.rs b/kernel/src/drivers/usb_storage.rs index ce99fbaf50a..fb2a979dc61 100644 --- a/kernel/src/drivers/usb_storage.rs +++ b/kernel/src/drivers/usb_storage.rs @@ -55,16 +55,6 @@ struct UsbBlockDevice { losses: u64, } -impl UsbBlockDevice { - /// Every result must pass through here so budget refusals reach the census the slow-vs-failed policy reads. - fn noted(&self, done: BlockResult) -> BlockResult { - if done == Err(BlockError::BudgetExpired) { - block::census::budget_expired(self.id); - } - done - } -} - impl BlockDevice for UsbBlockDevice { fn device_id(&self) -> DeviceId { self.id @@ -81,7 +71,7 @@ impl BlockDevice for UsbBlockDevice { log!("usb-storage: read of {count} blocks at {lba} {} on disk {}", gave_up(done), self.index); } - self.noted(done) + done } fn write_blocks(&mut self, lba: u64, count: u32, buf: &[u8]) -> BlockResult { @@ -91,18 +81,16 @@ impl BlockDevice for UsbBlockDevice { log!("usb-storage: write of {count} blocks at {lba} {} on disk {}", gave_up(done), self.index); } - self.noted(done) + done } fn flush(&mut self) -> BlockResult { let _op = block::begin_operation(); - let began = crate::clock::now(); let done = xhci::storage_flush(self.index, &mut self.losses); - block::census::flush_took(self.id, (crate::clock::now() - began).nanos()); if done.is_err() { log!("usb-storage: cache flush {} on disk {}", gave_up(done), self.index); } - self.noted(done) + done } fn losses(&self) -> u64 { diff --git a/kernel/src/elf/cache.rs b/kernel/src/elf/cache.rs index 26cdcd53195..317c29f57f1 100644 --- a/kernel/src/elf/cache.rs +++ b/kernel/src/elf/cache.rs @@ -232,7 +232,7 @@ pub fn cache_loaded_lib( } // Under the lock that publishes: two concurrent loads must not both find room. let (held, entries) = (held_bytes(&cache), cache.len()); - let Some(after) = held.checked_add(alloc.size()).filter(|b| *b <= BUDGET_BYTES) else { + if held.checked_add(alloc.size()).is_none_or(|after| after > BUDGET_BYTES) { drop(cache); // Both allocations drop here, so the refusal gives back what the load took. log!( @@ -241,17 +241,12 @@ pub fn cache_loaded_lib( path, held.saturating_add(alloc.size()), entries + 1, BUDGET_BYTES ); return Err(SyscallError::ResourceExhausted); - }; + } cache.push(( String::from(path), CachedLib { alloc, snapshot, rw_offset, rw_size, relocs: relocs.clone(), id }, )); drop(cache); - log!( - "dlopen: cached {} with {} bind + {} tpoff64 + {} tpoff32 + {} dtpmod64 + {} dtpoff64 pre-scanned relocs, cache now {} of {} bytes", - path, relocs.bind.len(), relocs.tpoff64.len(), relocs.tpoff32.len(), - relocs.dtpmod64.len(), relocs.dtpoff64.len(), after, BUDGET_BYTES - ); Ok(snapshot.into_lib( LibMemory::Shared { @@ -280,7 +275,6 @@ pub fn try_clone_cached( // Base address stays the cache's: `RELATIVE` relocations need no fixup until spawn/dlopen assigns a user address. fn clone_from_cache(cached: &CachedLib) -> Option { - let t0 = crate::clock::nanos_since_boot(); 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. @@ -290,19 +284,10 @@ fn clone_from_cache(cached: &CachedLib) -> Option { core::ptr::copy_nonoverlapping(src, rw_alloc.ptr(), cached.rw_size); } - let t1 = crate::clock::nanos_since_boot(); let rw_delta = rw_alloc.ptr() as i64 - (cached.alloc.ptr() as i64 + cached.rw_offset as i64); let image = cached.snapshot.image; let phys_base = image.phys(); - log!( - "dlopen: cache hit (shared), base={:#x} {}MB total, {}MB private RW, copy={}ms", - phys_base, - image.size() / (1024 * 1024), - cached.rw_size / (1024 * 1024), - (t1 - t0) / 1_000_000 - ); - Some(cached.snapshot.into_lib( LibMemory::Shared { rw_alloc, diff --git a/kernel/src/elf/mod.rs b/kernel/src/elf/mod.rs index 6da1af0b3c1..98a1233f6e8 100644 --- a/kernel/src/elf/mod.rs +++ b/kernel/src/elf/mod.rs @@ -375,10 +375,8 @@ pub fn load_shared_lib( let rw_offset = rw_lo as usize & !(PAGE_2M as usize - 1); let rw_size = rw_end_aligned - rw_offset; - let t0 = crate::clock::nanos_since_boot(); let alloc = 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(); @@ -387,7 +385,6 @@ pub fn load_shared_lib( unsafe { image.zero(); } - let t2 = crate::clock::nanos_since_boot(); let module = ModuleImage { image, extent }; // In bounds only because `Layout` guarantees `filesz <= memsz`; the checked @@ -397,7 +394,6 @@ pub fn load_shared_lib( read_backing_into(backing, seg.file_offset(), dst) .map_err(|_| "a segment could not be read off the device")?; } - let t3 = crate::clock::nanos_since_boot(); let dyn_info = match layout.dynamic() { Some(dynamic) => { @@ -480,31 +476,17 @@ pub fn load_shared_lib( // Every entry is parsed here, and a refusal drops the image this pass has // written into: nothing but this function has seen it. let base_phys = image.phys(); - let mut reloc_count = 0u64; for raw in table_entries(&rela).chain(table_entries(&jmprel)) { let Some(r) = rela::parse(raw, &rules, symbols).map_err(|e| e.as_str())? else { continue }; if let toyos_elf::Op::Relative(target) = r.op() { // SAFETY: `module.slice(r.offset(), 8)?` bounds-checks the write // independently of the parse; `image` is still exclusively owned. unsafe { module.slice(r.offset(), 8)?.write::(0, base_phys + target.get()) }; - reloc_count += 1; } } let tls_template = layout.tls().map(|tls| module.at(tls.template())); - let t4 = crate::clock::nanos_since_boot(); - log!( - "dlopen: base={:#x} {}MB alloc={}ms zero={}ms copy={}ms reloc={}ms ({} relocs)", - base_phys, - load_size / (1024 * 1024), - (t1 - t0) / 1_000_000, - (t2 - t1) / 1_000_000, - (t3 - t2) / 1_000_000, - (t4 - t3) / 1_000_000, - reloc_count - ); - Ok(( LoadedLib { memory: LibMemory::Owned(alloc), diff --git a/kernel/src/elf/reloc.rs b/kernel/src/elf/reloc.rs index d3e50048638..3f5a7ff3e6e 100644 --- a/kernel/src/elf/reloc.rs +++ b/kernel/src/elf/reloc.rs @@ -6,9 +6,11 @@ //! written is derived from a parsed relocation — never read back out of the //! image — so what a slot holds before its write decides nothing. //! -//! Unresolved symbols are logged and left unresolved, never fatal: a `.so` -//! naming an undefined symbol is untrusted input, not a kernel bug, and the -//! process faults on the slot only if it later uses it. A resolved TLS +//! Unresolved symbols are left unresolved, never fatal: a `.so` naming an +//! undefined symbol is untrusted input, not a kernel bug, and the process +//! faults on the slot only if it later uses it. Each function answers how many +//! it left, and the spawn or `dlopen` it serves says the sum in its one record: +//! none is a record of its own, since a file chooses how many there are. A resolved TLS //! reference whose `S + A` leaves the defining module's segment is refused. use super::{relocated_symbol, CachedRelocs, LibMemory, LoadedLib, TlsModule, TlsModuleInfo}; @@ -94,38 +96,30 @@ pub fn rebase_relative_relocs(lib: &LoadedLib) { } /// Bind a `dlopen`ed module's `GLOB_DAT`/`JUMP_SLOT` slots to symbols the -/// process already has. -pub fn resolve_dlopen_relocs(lib: &LoadedLib, other_libs: &[LoadedLib]) { +/// process already has; answers how many it left unresolved. +pub fn resolve_dlopen_relocs(lib: &LoadedLib, other_libs: &[LoadedLib]) -> u64 { let symbols = lib.symbols(); - let mut resolved = 0u64; - let mut unresolved = 0u64; + let mut unresolved = 0; for (offset, sym) in lib.bind_entries() { let name = relocated_symbol(symbols, sym).name_in(symbols.strings()); match other_libs.iter().find_map(|other| other.resolve(name)) { - Some(addr) => { - // SAFETY: rela::tables_outside_window refused any image whose tables meet the window these writes land in. - unsafe { lib.write_at::(offset, addr.raw()) }; - resolved += 1; - } - None => { - if unresolved < 5 { - log!("dlopen: unresolved: {}", name); - } - unresolved += 1; - } + // SAFETY: rela::tables_outside_window refused any image whose tables meet the window these writes land in. + Some(addr) => unsafe { lib.write_at::(offset, addr.raw()) }, + None => unresolved += 1, } } - log!("dlopen: resolved {} relocs, {} unresolved", resolved, unresolved); + unresolved } /// Bind a startup library's `GLOB_DAT`/`JUMP_SLOT` slots, preferring the -/// executable's own exports. +/// executable's own exports; answers how many it left unresolved. pub fn resolve_lib_bind_relocs( lib: &LoadedLib, exe_sym_map: &alloc::collections::BTreeMap<&str, UserAddr>, libs: &[LoadedLib], -) { +) -> u64 { let symbols = lib.symbols(); + let mut unresolved = 0; for (offset, sym) in lib.bind_entries() { let name = relocated_symbol(symbols, sym).name_in(symbols.strings()); let resolved = exe_sym_map @@ -135,13 +129,15 @@ pub fn resolve_lib_bind_relocs( match resolved { // SAFETY: rela::tables_outside_window refused any image whose tables meet the window these writes land in. Some(addr) => unsafe { lib.write_at::(offset, addr.raw()) }, - None => log!("dynamic: lib unresolved symbol: {}", name), + None => unresolved += 1, } } + unresolved } /// Apply `R_X86_64_TPOFF64` and `R_X86_64_TPOFF32`: the initial-exec TLS -/// model, a fixed offset from the thread pointer. +/// model, a fixed offset from the thread pointer. Answers how many references +/// name a symbol no module defines; each is written as zero. /// /// Every value is resolved before the first is written, so a refused module is /// left as it was found. @@ -150,7 +146,7 @@ pub fn apply_tpoff_relocs( lib_base_offset: usize, tls: toyos_elf::tls::Static, tls_info: &TlsModuleInfo, -) -> Result<(), RelocError> { +) -> Result { let tpoff64 = |op| match op { Op::Tpoff64(t) => Some(t), _ => None, @@ -164,30 +160,23 @@ pub fn apply_tpoff_relocs( tpoff(r)?; } for (_, r) in lib.entries(tpoff32, |c| &c.tpoff32) { - tpoff32_value(tpoff(r)?)?; + tpoff32_value(tpoff(r)?.unwrap_or(0))?; } - let mut count64 = 0u64; + let mut unresolved = 0; for (offset, r) in lib.entries(tpoff64, |c| &c.tpoff64) { let value = tpoff(r)?; + unresolved += u64::from(value.is_none()); // SAFETY: see write_at's `# Safety`. - unsafe { lib.write_at::(offset, value) }; - count64 += 1; + unsafe { lib.write_at::(offset, value.unwrap_or(0)) }; } - let mut count32 = 0u64; for (offset, r) in lib.entries(tpoff32, |c| &c.tpoff32) { - let value = tpoff32_value(tpoff(r)?)?; + let value = tpoff(r)?; + unresolved += u64::from(value.is_none()); // SAFETY: see write_at's `# Safety`. - unsafe { lib.write_at::(offset, value) }; - count32 += 1; - } - if count64 > 0 || count32 > 0 { - log!( - "dlopen: applied {} TPOFF64 + {} TPOFF32 relocs (base_offset={}, total_memsz={})", - count64, count32, lib_base_offset, tls.total_memsz() - ); + unsafe { lib.write_at::(offset, tpoff32_value(value.unwrap_or(0))?) }; } - Ok(()) + Ok(unresolved) } /// A `TPOFF32`'s field is 32 bits the instruction sign-extends; a value outside @@ -197,23 +186,24 @@ pub fn tpoff32_value(tpoff: i64) -> Result { } /// Apply `R_X86_64_DTPMOD64`: the general-dynamic TLS model's module id. -pub fn apply_dtpmod_relocs(lib: &LoadedLib, module_id: u64, tls_info: &TlsModuleInfo) { - let mut count = 0u64; +/// Answers how many name a symbol no module defines; each is given this +/// module's own id. +pub fn apply_dtpmod_relocs(lib: &LoadedLib, module_id: u64, tls_info: &TlsModuleInfo) -> u64 { + let mut unresolved = 0; for (offset, sym) in lib.dtpmod_entries() { let mid = resolve_dtpmod(lib, sym, module_id, tls_info); + unresolved += u64::from(mid.is_none()); // SAFETY: see write_at's `# Safety`. - unsafe { lib.write_at::(offset, mid) }; - count += 1; - } - if count > 0 { - log!("dlopen: applied {} DTPMOD64 relocs (module_id={})", count, module_id); + unsafe { lib.write_at::(offset, mid.unwrap_or(module_id)) }; } + unresolved } /// Apply `R_X86_64_DTPOFF64`: the general-dynamic TLS model's offset within the /// defining module's block. Every value is resolved before the first is -/// written, so a refused module is left as it was found. -pub fn apply_dtpoff_relocs(lib: &LoadedLib, tls_info: &TlsModuleInfo) -> Result<(), RelocError> { +/// written, so a refused module is left as it was found. Answers how many name +/// a symbol no module defines; each is written as zero. +pub fn apply_dtpoff_relocs(lib: &LoadedLib, tls_info: &TlsModuleInfo) -> Result { let dtpoff = |op| match op { Op::DtpOff64(t) => Some(t), _ => None, @@ -222,17 +212,14 @@ pub fn apply_dtpoff_relocs(lib: &LoadedLib, tls_info: &TlsModuleInfo) -> Result< for (_, r) in lib.entries(dtpoff, |c| &c.dtpoff64) { resolve(r)?; } - let mut count = 0u64; + let mut unresolved = 0; for (offset, r) in lib.entries(dtpoff, |c| &c.dtpoff64) { - let value = resolve(r)?.map_or(0, |(_, at)| at.get()); + let value = resolve(r)?; + unresolved += u64::from(value.is_none()); // SAFETY: see write_at's `# Safety`. - unsafe { lib.write_at::(offset, value) }; - count += 1; - } - if count > 0 { - log!("dlopen: applied {} DTPOFF64 relocs", count); + unsafe { lib.write_at::(offset, value.map_or(0, |(_, at)| at.get())) }; } - Ok(()) + Ok(unresolved) } /// The module in `tls_info` that defines `name`, its `PT_TLS`, and the symbol @@ -255,27 +242,22 @@ pub fn defining_module<'a>(name: &str, tls_info: &'a TlsModuleInfo) -> Option<(& None } -fn resolve_dtpmod(lib: &LoadedLib, sym: Option, self_module_id: u64, tls_info: &TlsModuleInfo) -> u64 { - let Some(sym) = sym else { return self_module_id }; +/// The module id one `DTPMOD64` names, or `None` for a symbol no module defines. +fn resolve_dtpmod(lib: &LoadedLib, sym: Option, self_module_id: u64, tls_info: &TlsModuleInfo) -> Option { + let Some(sym) = sym else { return Some(self_module_id) }; let symbols = lib.symbols(); let named = relocated_symbol(symbols, sym); if named.is_defined() { - return self_module_id; + return Some(self_module_id); } let name = named.name_in(symbols.strings()); - match defining_module(name, tls_info) { - Some((module, _, _)) => module.module_id, - None => { - log!("dtpmod: unresolved TLS symbol: {}", name); - self_module_id - } - } + defining_module(name, tls_info).map(|(module, _, _)| module.module_id) } /// `S + A` for one TLS reference, and the static-block offset of the module it /// lies in: the referencing module's own (`own_base_offset`, `own_tls`), or -/// the module defining the symbol. `None` is a symbol no module defines, which -/// is logged; a sum outside the defining module's segment refuses the module. +/// the module defining the symbol. `None` is a symbol no module defines; a sum +/// outside the defining module's segment refuses the module. fn resolve_tls_ref( r: TlsRef, own_base_offset: usize, @@ -294,19 +276,14 @@ fn resolve_tls_ref( return Ok(Some((own_base_offset, at))); } let name = sym.name_in(symbols.strings()); - match defining_module(name, tls_info) { - Some((module, segment, defined)) => { - let at = defined.tls_offset(s.addend(), segment).ok_or(RelocError::TlsOutsideSegment)?; - Ok(Some((module.base_offset, at))) - } - None => { - log!("tls: unresolved TLS symbol: {}", name); - Ok(None) - } - } + let Some((module, segment, defined)) = defining_module(name, tls_info) else { + return Ok(None); + }; + let at = defined.tls_offset(s.addend(), segment).ok_or(RelocError::TlsOutsideSegment)?; + Ok(Some((module.base_offset, at))) } -/// `S + A - tp` for one initial-exec reference, or `0` for a symbol no module defines. +/// `S + A - tp` for one initial-exec reference, or `None` for a symbol no module defines. pub fn compute_tpoff( r: TlsRef, own_base_offset: usize, @@ -314,9 +291,8 @@ pub fn compute_tpoff( symbols: SymTab<'_>, tls: toyos_elf::tls::Static, tls_info: &TlsModuleInfo, -) -> Result { - match resolve_tls_ref(r, own_base_offset, own_tls, symbols, tls_info)? { - Some((base_offset, at)) => tls.tpoff(base_offset, at).ok_or(RelocError::TpoffOverflows), - None => Ok(0), - } +) -> Result, RelocError> { + resolve_tls_ref(r, own_base_offset, own_tls, symbols, tls_info)? + .map(|(base_offset, at)| tls.tpoff(base_offset, at).ok_or(RelocError::TpoffOverflows)) + .transpose() } diff --git a/kernel/src/irq_census.rs b/kernel/src/irq_census.rs index b8d9dd3dbd9..66dec389b6e 100644 --- a/kernel/src/irq_census.rs +++ b/kernel/src/irq_census.rs @@ -126,12 +126,12 @@ pub fn taken_here() -> u64 { sum_bar_nmi(&percpu::irq_counts_here()) } -/// Logs one `irq: cpuN =…` line per online CPU; counts are cumulative since boot. -/// The machine's reading, so the machine's to take: at its stop and in the blocked-task dump, never at one process's end. +/// One `irq: cpuN =…` line per online CPU; counts are cumulative since boot. +/// The machine's reading, so the machine's to take: `crate::census`'s, and the blocked-task dump's, never one process's end. /// Allocates nothing, takes no lock, touches no device. -pub fn log_census() { +pub fn census(say: &mut impl FnMut(fmt::Arguments<'_>)) { for cpu in 0..crate::smp::cpu_count() { let Some(counts) = read(cpu) else { continue }; - crate::log!("irq: cpu{cpu}{}", Fields(&counts)); + say(format_args!("irq: cpu{cpu}{}", Fields(&counts))); } } diff --git a/kernel/src/loader/mod.rs b/kernel/src/loader/mod.rs index 23cf697ad67..04e22e8391a 100644 --- a/kernel/src/loader/mod.rs +++ b/kernel/src/loader/mod.rs @@ -7,9 +7,10 @@ //! Every number the file names is untrusted: a refusal is //! `SyscallError::{InvalidArgument, ResourceExhausted}`, never a panic. //! -//! A spawn that lands writes one record, `spawn: pid=…`, once the -//! process is in the table and placed; a spawn that is refused writes one, -//! naming why. Nothing is said on the way (`crate::process`'s header). +//! A spawn that lands writes one record, `spawn: pid=N unresolved=N +//! (…ms)`, once the process is in the table and placed; a spawn that is +//! refused writes one, naming why. Nothing is said on the way, by this file or +//! by `crate::elf` under it (`crate::process`'s header). // `warn`, not `deny`: the rest of the kernel is not yet swept for undocumented unsafe blocks. #![warn(clippy::undocumented_unsafe_blocks)] @@ -452,6 +453,8 @@ pub fn spawn( } } + // References no module defines. The file chooses how many, so they are a count in the spawn's record and never a record each. + let mut unresolved = 0u64; if !loaded_libs.libs.is_empty() { // A PIE without `--export-dynamic` exports nothing through `.dynsym`; // read `.symtab` only when that lookup came back empty. @@ -472,9 +475,8 @@ pub fn spawn( log!("spawn: {}: {}", path, refused.as_str()); SyscallError::InvalidArgument })?; - log!("dynamic: {} exe symbols available to libraries", exe_sym_map.len()); for lib in &loaded_libs.libs { - elf::resolve_lib_bind_relocs(lib, &exe_sym_map, &loaded_libs.libs); + unresolved += elf::resolve_lib_bind_relocs(lib, &exe_sym_map, &loaded_libs.libs); } for &(r_offset, r_sym) in &exe.relas.glob_dat { @@ -484,7 +486,7 @@ pub fn spawn( let name = elf::relocated_symbol(exe.symbols(), r_sym).name_in(&exe.dynstr); match loaded_libs.libs.iter().find_map(|lib| lib.resolve(name)) { Some(addr) => reloc_index.add_u64(r_offset, addr.raw()), - None => log!("dynamic: unresolved exe symbol: {}", name), + None => unresolved += 1, } } } @@ -548,11 +550,12 @@ pub fn spawn( return Err(SyscallError::ResourceExhausted.into()); }; - if let Err(refused) = apply_tls_relocs(&exe, &layout, &loaded_libs.libs, &tls_modules, tls, - &mut reloc_index) - { - log!("spawn: {}: {}", path, refused.as_str()); - return Err(SyscallError::InvalidArgument.into()); + match apply_tls_relocs(&exe, &layout, &loaded_libs.libs, &tls_modules, tls, &mut reloc_index) { + Ok(more) => unresolved += more, + Err(refused) => { + log!("spawn: {}: {}", path, refused.as_str()); + return Err(SyscallError::InvalidArgument.into()); + } } reloc_index.finalize(); @@ -649,7 +652,7 @@ pub fn spawn( crate::process::debug_kill_marked_place(parent); let mut guard = PROCESS_TABLE.lock(); - let ((tid, dst), retire) = admission.land(guard.as_mut().unwrap(), |table, node| { + let ((), retire) = admission.land(guard.as_mut().unwrap(), |table, node| { table.insert(ProcessEntry::new( Arc::clone(&object), start::make_name(name), @@ -662,7 +665,7 @@ pub fn spawn( let tid = table.get(pid).unwrap().main_tid(); // Placed while still holding the table lock: kill_process claims teardown // under it, so a retire sweep can never see the pid before its thread is scheduled. - let (sched, dst) = scheduler::enqueue_new( + let (sched, _placed) = scheduler::enqueue_new( scheduler::TaskId(pid, tid), ks_alloc, ks_sp, @@ -671,7 +674,6 @@ pub fn spawn( Some(image), ); table.get_mut(pid).unwrap().threads_mut().get_mut(tid).unwrap().set_sched(sched); - (tid, dst) }); drop(guard); // Its parent was claimed while it was built, and its walk has passed: the @@ -684,8 +686,8 @@ pub fn spawn( crate::process::debug_hold_marked_spawn(parent, &object); let t3 = crate::clock::nanos_since_boot(); - log!("spawn: {} pid={} tid={} dst={} base={:#x} entry={:#x} root={:#x} (layout={}ms relocs={}ms deps={}ms tls={}ms total={}ms)", - path, pid, tid, dst.0, base, entry.addr(), child_pt.lock().root().phys(), + log!("spawn: {} pid={} unresolved={} (layout={}ms relocs={}ms deps={}ms tls={}ms total={}ms)", + path, pid, unresolved, (t1 - t0) / 1_000_000, (t2 - t1) / 1_000_000, (t_deps - t2) / 1_000_000, (t_tls - t_deps) / 1_000_000, (t3 - t0) / 1_000_000); @@ -733,8 +735,6 @@ fn load_needed_libs(exe: &ExeTables, path: &str, from_image: bool) -> Result Result { - let t_load1 = crate::clock::nanos_since_boot(); - log!("dynamic: loaded {} base={:#x} ({} syms, {}ms)", - lib_name, lib.phys_base, lib.symbols().count(), (t_load1 - t_load0) / 1_000_000); out.libs.push(elf::cache_loaded_lib(&lib_path, id, lib, rw_offset, rw_size)?); out.paths.push(lib_path); } @@ -819,7 +816,8 @@ fn map_libs( /// Apply the TLS relocations of every startup library, and index the executable's. /// /// Libraries' land directly; the executable's go into the relocation index -/// because its pages do not exist yet. +/// because its pages do not exist yet. Answers how many references name a +/// symbol no module defines. fn apply_tls_relocs( exe: &ExeTables, layout: &Layout, @@ -827,18 +825,19 @@ fn apply_tls_relocs( tls_modules: &[elf::TlsModule], tls: toyos_elf::tls::Static, reloc_index: &mut elf::RelocationIndex, -) -> Result<(), RelocError> { +) -> Result { let tls_info = elf::TlsModuleInfo { libs: loaded_libs, modules: tls_modules }; + let mut unresolved = 0; for lib in loaded_libs { // Matched by template pointer, unique per lib; a lib without TLS matches nothing. let module = tls_modules.iter().find(|m| m.template == lib.tls_template); let base_offset = module.map_or(0, |m| m.base_offset); // Initial-exec: references to TLS in the static block. - elf::apply_tpoff_relocs(lib, base_offset, tls, &tls_info)?; + unresolved += elf::apply_tpoff_relocs(lib, base_offset, tls, &tls_info)?; // General-dynamic: this lib's own TLS, reached through the DTV. if let Some(m) = module { - elf::apply_dtpoff_relocs(lib, &tls_info)?; - elf::apply_dtpmod_relocs(lib, m.module_id, &tls_info); + unresolved += elf::apply_dtpoff_relocs(lib, &tls_info)?; + unresolved += elf::apply_dtpmod_relocs(lib, m.module_id, &tls_info); } } @@ -849,12 +848,16 @@ fn apply_tls_relocs( let exe_tpoff = |r| elf::compute_tpoff(r, exe_base_offset, layout.tls(), exe.symbols(), tls, &tls_info); for &(r_offset, r) in &exe.relas.tpoff64 { - reloc_index.add_u64(r_offset, exe_tpoff(r)? as u64); + let value = exe_tpoff(r)?; + unresolved += u64::from(value.is_none()); + reloc_index.add_u64(r_offset, value.unwrap_or(0) as u64); } for &(r_offset, r) in &exe.relas.tpoff32 { - reloc_index.add_i32(r_offset, elf::tpoff32_value(exe_tpoff(r)?)?); + let value = exe_tpoff(r)?; + unresolved += u64::from(value.is_none()); + reloc_index.add_i32(r_offset, elf::tpoff32_value(value.unwrap_or(0))?); } - Ok(()) + Ok(unresolved) } /// The one program the kernel starts. `src/build.rs` puts this binary in every diff --git a/kernel/src/log/mod.rs b/kernel/src/log/mod.rs index 25b1d43aeef..6471ff70fb1 100644 --- a/kernel/src/log/mod.rs +++ b/kernel/src/log/mod.rs @@ -57,16 +57,19 @@ pub fn shard_for(cpu: u32) -> &'static Shard { } } -/// The newest records the stop's account carries whole. The page's account -/// reserve is what bounds it: a tail that spent the reserve would leave the -/// reset's own account under it nowhere to go. -const TAIL_RECORDS: usize = 16; - /// The head the tail is sealed under, read back by `src/bootlog.rs`. const TAIL_HEAD: &str = "log: this boot's newest records follow, newest first"; -/// Seal the newest of this boot's records onto the black box, the one channel -/// a boot's own tail has once the stop has begun. +/// Seal the stop's own records onto the black box, the one channel a boot's +/// tail has once the stop has begun: every record stamped at `from` or after, +/// newest first. +/// +/// **Bounded by the page and by nothing else.** The records may spend what a +/// report may ([`toyos_blackbox::REPORT_BYTES`]), which leaves the reset's own +/// account its reserve; the oldest that do not fit are counted and the count +/// is said last, in the words a death's tail says it +/// ([`toyos_blackbox::DROPPED_OPENS_WITH`]). How many records a stop writes is +/// the machine's to decide, by its CPUs and its disks. /// /// **The kernel does not wait for `/system/bin/logkeeper`, so it does not know what /// reached `/log`.** `/system/bin/supervisor` has `logkeeper` flush before it asks for the @@ -76,24 +79,45 @@ const TAIL_HEAD: &str = "log: this boot's newest records follow, newest first"; /// /// Called from the quiesce path under [`crate::blackbox::record_done`], where /// the page already carries this boot's seal and every lock is still ordinary. -pub fn seal_tail() { +pub fn seal_tail(from: LogStamp) { + use core::fmt::Write as _; + /// How long a line is, without writing it. + struct Length(usize); + impl core::fmt::Write for Length { + fn write_str(&mut self, s: &str) -> core::fmt::Result { + self.0 += s.len(); + Ok(()) + } + } struct Tail<'a> { out: &'a mut dyn core::fmt::Write, left: usize, + dropped: u64, } impl read::RecordSink for Tail<'_> { fn put(&mut self, record: &LogRecord) -> bool { + let mut line = Length(0); + let _ = writeln!(line, "log-tail: {record}"); + // Once one is dropped every older one is: a tail with a hole in it reads as whole. + if self.dropped > 0 || line.0 > self.left { + self.dropped += 1; + return true; + } + self.left -= line.0; // No prefix of its own: the loader that prints this page puts one // on every line it reads back. let _ = writeln!(self.out, "log-tail: {record}"); - self.left -= 1; - self.left > 0 + true } } crate::blackbox::append(|out| { - let _ = writeln!(out, "{TAIL_HEAD} ({TAIL_RECORDS})"); - let mut tail = Tail { out, left: TAIL_RECORDS }; - read::snapshot_committed(LogStamp::ZERO, read::newest_committed(), &mut tail); + let _ = writeln!(out, "{TAIL_HEAD}"); + let left = toyos_blackbox::REPORT_BYTES - TAIL_HEAD.len() - 1 - toyos_blackbox::DROPPED_LINE_BYTES; + let mut tail = Tail { out, left, dropped: 0 }; + read::snapshot_committed(from, read::newest_committed(), &mut tail); + if tail.dropped > 0 { + let _ = writeln!(tail.out, "{}{}", toyos_blackbox::DROPPED_OPENS_WITH, tail.dropped); + } }); } @@ -263,49 +287,3 @@ macro_rules! boot_phase { $crate::deadline::reached($crate::deadline::index_of($name)); }}; } - -/// Records one site may say in [`LIMIT_WINDOW_NS`] before the rest of the -/// window's are counted instead ([`log_limited!`]). -pub const LIMIT_BURST: u64 = 16; -pub const LIMIT_WINDOW_NS: u64 = 1_000_000_000; - -/// `log!` for a site a program can drive at any rate: past [`LIMIT_BURST`] -/// records a second the site's records are counted, the last one said before -/// that says so, and the next one said carries the count -/// (`toyos_elide::limit`). -#[macro_export] -macro_rules! log_limited { - ($($arg:tt)*) => {{ - static LIMIT: toyos_elide::limit::Limit = - toyos_elide::limit::Limit::new($crate::log::LIMIT_BURST, $crate::log::LIMIT_WINDOW_NS); - match LIMIT.admit($crate::clock::nanos_since_boot()) { - toyos_elide::limit::Admit::Suppress => {} - toyos_elide::limit::Admit::Say { suppressed, last } => $crate::log::emit( - $crate::log::Severity::Info, - format_args!( - "{}{}", - format_args!($($arg)*), - $crate::log::Limited { suppressed, last }, - ), - ), - } - }}; -} - -/// What a limited site's record adds to its line: nothing, or what the limit did. -pub struct Limited { - pub suppressed: u64, - pub last: bool, -} - -impl core::fmt::Display for Limited { - fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result { - if self.suppressed > 0 { - write!(f, " (after {} like it suppressed)", self.suppressed)?; - } - if self.last { - write!(f, " (the rest like it this second are suppressed)")?; - } - Ok(()) - } -} diff --git a/kernel/src/main.rs b/kernel/src/main.rs index 5edbe022899..1b835cdca24 100644 --- a/kernel/src/main.rs +++ b/kernel/src/main.rs @@ -72,6 +72,7 @@ mod hw; mod iommu; mod preempt; mod counters; +mod census; mod irq_census; #[cfg(feature = "mask-windows")] mod windows; diff --git a/kernel/src/process.rs b/kernel/src/process.rs index 26f40b0b303..535b1895677 100644 --- a/kernel/src/process.rs +++ b/kernel/src/process.rs @@ -10,12 +10,12 @@ //! **What a process writes into the log is two records**: one where its spawn //! lands (`crate::loader`) and one where it ends, `exit: pid=N code=N //! cpu=Nms …`, the verdict first and then what that process itself consumed. -//! A record here is charged to the process it names. A reading of the whole -//! machine — the interrupt census, the shootdowns', the flushes' — is taken -//! once, where the machine stops (`syscall::machine`), and no process's start -//! or end repeats one: the log's volume is then a function of what ran, never -//! of how many CPUs watched it. A thread that ends before its process says so -//! in a rate-limited record of its own. +//! Each is written every time and charged to the process it names: nothing +//! here is rate-limited, and a thread's end writes nothing. A reading of the +//! whole machine is `crate::census`'s, taken once, where the machine ends, by +//! its stop or by its death, and no process's start or end repeats one: the +//! log's volume is then a function of what ran, never of how many CPUs +//! watched it. use alloc::alloc::{alloc_zeroed, dealloc, Layout}; use alloc::string::String; @@ -1072,7 +1072,7 @@ impl core::fmt::Display for Consumed { } /// Frees an exiting process's resources (mappings, handles, ELF state), and answers what it consumed. -/// Says nothing of the machine: a reading of every CPU is the stop's (`syscall::machine`), never one process's end. +/// Says nothing of the machine: a reading of every CPU is `crate::census`'s, never one process's end. fn teardown_resources( process_data_arc: &Arc>, thread_data_arc: &Arc>, @@ -1285,7 +1285,7 @@ pub fn thread_exit(code: i32) -> ! { proclife::ThreadExit::Sibling { post } => post, }; - release_thread(process_pid, tid, code); + release_thread(tid); leave(Some(code)); // Whoever joined this thread armed on it; post before the exit pass — after it this thread never runs again. if let Some(handle) = crate::sched::driver::current_handle() { @@ -1302,7 +1302,7 @@ pub fn thread_exit(code: i32) -> ! { } /// A child thread's own mappings, released before it leaves; returns rather than diverging for [`leave`]'s reason. -fn release_thread(process_pid: Pid, tid: Tid, code: i32) { +fn release_thread(tid: Tid) { let addr_space = current_address_space(); crate::mm::paging::activate_kernel(); @@ -1318,12 +1318,6 @@ fn release_thread(process_pid: Pid, tid: Tid, code: i32) { }; // After the block: dropping waits for every other CPU, and the page-fault handler takes this same lock. drop(released); - - let guard = PROCESS_TABLE.lock(); - let proc = guard.as_ref().unwrap().get(process_pid).expect("release_thread: a thread's process is not in the table"); - let cpu_ms = proc.threads.get(tid).and_then(|t| t.sched()).map_or(0, scheduler::task_cpu_ns) / 1_000_000; - let name = proc.name_str(); - crate::log_limited!("exit: {name} tid={tid} code={code} cpu={cpu_ms}ms"); } /// A thread's scheduler record, cloned out of the table so wake/retire never hold the table lock while they post. diff --git a/kernel/src/sched/dump.rs b/kernel/src/sched/dump.rs index 80467d06868..fec28bd7cc4 100644 --- a/kernel/src/sched/dump.rs +++ b/kernel/src/sched/dump.rs @@ -561,7 +561,7 @@ fn walk_threads(deadline: u64, mut f: impl FnMut(crate::process::ThreadCensus<'_ fn summary(cpus: usize, silent: u32, c: Census) { let answered = cpus - silent as usize; // Needs nothing from the CPU it describes: the counters are `PerCpu`'s own, read by a sibling. - crate::irq_census::log_census(); + crate::irq_census::census(&mut |line| log!("{line}")); // Each count is written before the word it counts, so the gate parses by word, not position. if !c.read { log!("== census: the process table is held; no thread census this dump"); diff --git a/kernel/src/syscall/machine.rs b/kernel/src/syscall/machine.rs index 3b52da38a74..2b5ba15a9ba 100644 --- a/kernel/src/syscall/machine.rs +++ b/kernel/src/syscall/machine.rs @@ -92,14 +92,13 @@ fn quiesce(last: &str) -> Result { // `/system/bin/supervisor` had it flush before it asked for this stop. let (stopped, stopping) = crate::quiesce::stop(); crate::log::console::drain_for_the_stop(); - // The boot's one census of the machine, and its only owner: no process's - // end takes one. Oldest first is first cut from the sealed tail, so the - // flushes lead; the shootdowns' issues follow the deliveries they bound. - crate::block::census::log_census(); - crate::irq_census::log_census(); - crate::arch::tlb::log_census(); - crate::arch::trap::log_unclaimed(); - crate::drivers::panic_console::log_census(); + // From here on nothing carries a record to a file: the seal below takes + // every one written after this stamp. + let stop_began = crate::log::read::newest_committed(); + // The machine's census, which no process's start or end takes. + crate::census::log(); + #[cfg(feature = "mask-windows")] + crate::windows::report(); // A shortfall is the budget spent, not the reset refused: it is said at // alert level, and the reset lands anyway. if stopped.stopped_the_machine() { @@ -121,10 +120,10 @@ fn quiesce(last: &str) -> Result { // report a kernel that vanished. The reset's own account is appended under // it. crate::blackbox::record_done(); - // Under that seal, because it extends it: the boot's newest records, the - // stop's own and the last word among them. Nothing wrote them to `/log`, + // Under that seal, because it extends it: the stop's own records, the + // census and the last word among them. Nothing wrote them to `/log`, // and on a machine with no serial port this is their only reader. - crate::log::seal_tail(); + crate::log::seal_tail(stop_began); // Whether or not the volume got them: a stick this boot's transport broke // on is a stick the next host may not be able to read the log off. crate::blackbox::append_recovery(); diff --git a/kernel/src/syscall/vm.rs b/kernel/src/syscall/vm.rs index 9d9e34126b5..0bf019709ba 100644 --- a/kernel/src/syscall/vm.rs +++ b/kernel/src/syscall/vm.rs @@ -321,9 +321,11 @@ pub(super) fn sys_dlopen(ctx: &crate::user_ptr::SyscallContext, path: &str, init let lib_tls = lib.tls().and_then(toyos_elf::TlsSegment::occupied); let data_arc = process::process_data(); + // References no module defines: a count in this load's one record, as a spawn's are. + let mut unresolved; let init_info = { let data = data_arc.lock(); - crate::elf::resolve_dlopen_relocs(&lib, &data.elf.loaded_libs); + unresolved = crate::elf::resolve_dlopen_relocs(&lib, &data.elf.loaded_libs); // Every TLS value is resolved here, before the point of no return: a // reference that leaves its module's segment refuses the whole load, @@ -332,17 +334,21 @@ pub(super) fn sys_dlopen(ctx: &crate::user_ptr::SyscallContext, path: &str, init libs: &data.elf.loaded_libs, modules: &data.elf.tls_modules, }; - let refused = if data.elf.tls.total_memsz() > 0 { - crate::elf::apply_tpoff_relocs(&lib, 0, data.elf.tls, &tls_info).err() + let initial_exec = if data.elf.tls.total_memsz() > 0 { + crate::elf::apply_tpoff_relocs(&lib, 0, data.elf.tls, &tls_info) } else { - None + Ok(0) }; - let refused = refused.or_else(|| { - lib_tls.and_then(|_| crate::elf::apply_dtpoff_relocs(&lib, &tls_info).err()) + let general_dynamic = initial_exec.and_then(|left| match lib_tls { + Some(_) => crate::elf::apply_dtpoff_relocs(&lib, &tls_info).map(|more| left + more), + None => Ok(left), }); - if let Some(refused) = refused { - log!("dlopen: {}: {}", resolved, refused.as_str()); - return SyscallError::InvalidArgument.to_u64(); + match general_dynamic { + Ok(left) => unresolved += left, + Err(refused) => { + log!("dlopen: {}: {}", resolved, refused.as_str()); + return SyscallError::InvalidArgument.to_u64(); + } } // init_info layout: [init_array address, init_array count]. @@ -392,7 +398,7 @@ pub(super) fn sys_dlopen(ctx: &crate::user_ptr::SyscallContext, path: &str, init libs: &data.elf.loaded_libs, modules: &data.elf.tls_modules, }; - crate::elf::apply_dtpmod_relocs(&lib, module_id, &tls_info); + unresolved += crate::elf::apply_dtpmod_relocs(&lib, module_id, &tls_info); data.elf.tls_modules.push(crate::elf::TlsModule { template: lib.tls_template, memsz: lib_tls.memsz() as usize, @@ -401,6 +407,7 @@ pub(super) fn sys_dlopen(ctx: &crate::user_ptr::SyscallContext, path: &str, init is_static: false, }); } + log!("dlopen: {} pid={} unresolved={}", resolved, process::current_process(), unresolved); data.elf.lib_paths.push(resolved); data.elf.loaded_libs.push(lib); idx as u64 diff --git a/kernel/src/windows.rs b/kernel/src/windows.rs index c546c797f50..3d690dbb20d 100644 --- a/kernel/src/windows.rs +++ b/kernel/src/windows.rs @@ -1,7 +1,7 @@ //! Each CPU's [`kernel::sched::windows::Windows`], fed where this CPU's -//! interrupts and preempt count change, and printed at every process's end as -//! `windows: cpuN irqs_off_ns=… preempt_off_ns=…`, a line per CPU -//! (`mask-windows` builds only). +//! interrupts and preempt count change, and printed at every process's end +//! and at the machine's stop as `windows: cpuN irqs_off_ns=… preempt_off_ns=…`, +//! a line per CPU (`mask-windows` builds only). //! //! Each architecture calls [`irqs_masked`] and [`irqs_unmasking`] from every //! instruction that changes whether it takes a maskable interrupt: its diff --git a/tests/checks.rs b/tests/checks.rs index c1cd67a5eb3..271752d60b5 100644 --- a/tests/checks.rs +++ b/tests/checks.rs @@ -983,19 +983,27 @@ mod checks { assert_eq!(judge(&[&readback("jobcase", &done(rebooted), jobcase)]), Ok(())); assert!(judge(&[&readback("jobcase", &done(stopped), jobcase)]).is_err()); - let wedged = |tail: &str| { + // What the seal itself writes of the machine, above the ring's tail. + let census = "| irq: cpu0 timer=9 kick=2 xhci=1729 userdev=0 sound=0 i8042=0 dmafault=0 hda=0 tlb=0 \ + nmi=0 spurious=0 unclaimed=0\n\ + | tlb: shootdowns=4 wait=12us max=3us dlopen=0 pcid=0 mmio=0 unmap=4 pipe=0 staged=0 \ + bench=0\n\ + | irq: unclaimed vectors no-isr=0\n\ + | panel: paints=9 px=2896256 us=5688 max_us=1285\n"; + let sealed = |census: &str, tail: &str| { format!( "{HANDOFF}{}\nToyOS Bootloader 1.0\n\ Previous boot's panic: the last boot read WEDGED, so a bound of its own ended it \ and this chain ends here\n\ | the boot deadline expired: a bound of 120000 ms, reached at 120061 ms, with this \ machine in `complete`. Where each CPU's timer last found the kernel:\n\ - | The tail of the log ring follows ... which is what nothing was draining.\n\ + | The tail of the log ring follows ... which is what nothing was draining.\n{census}\ | usb-quiesce: no barrier was taken, so this reset is not the shutdown's\n{tail}\ Loader log: the last boot is accounted for, so this pass resets the machine\n", bootlog::SEPARATOR ) }; + let wedged = |tail: &str| sealed(census, tail); let kernel = "[2026-09-29 10:33:28 0.000 cpu0 kernel] panic console: armed 1920x1080 \ stride=1920 format=1 at 0x4000000000, write-combining\n"; let staged = "| [ 1.509 cpu1 kernel] wedge: staged, and only the boot deadline ends this machine: \ @@ -1011,6 +1019,10 @@ mod checks { let wedge = format!("{staged}{}{}{inside}", awake(1), awake(0)); assert_eq!(judge(&[&readback("deadlinewedge", &wedged(&wedge), kernel)]), Ok(())); assert!(judge(&[&readback("deadlinewedge", &wedged(""), kernel)]).is_err()); + // A death that sealed no census of the machine, and one that sealed all but the shootdowns'. + assert!(judge(&[&readback("deadlinewedge", &sealed("", &wedge), kernel)]).is_err()); + let no_tlb: String = census.split_inclusive('\n').filter(|line| !line.contains("tlb: ")).collect(); + assert!(judge(&[&readback("deadlinewedge", &sealed(&no_tlb, &wedge), kernel)]).is_err()); // The staging CPU arrived deaf: the gate masked the syscall's body, and // the others' awake lines say nothing of it. let gated = format!("{staged}{deaf}{}{inside}", awake(0)); diff --git a/tests/common/irqcensus.rs b/tests/common/irqcensus.rs index 8d23f78cef0..bf45c5a80a7 100644 --- a/tests/common/irqcensus.rs +++ b/tests/common/irqcensus.rs @@ -1,9 +1,9 @@ //! The kernel's interrupt census, and the windows a `mask-windows` kernel //! reports, read back on the host. //! -//! The kernel prints `irq: cpuN timer=… kick=… …` per online CPU when the -//! machine stops and in the blocked-task dump (`kernel/src/irq_census.rs`), -//! and at no process's end. The counters are cumulative since boot, so the +//! The kernel says `irq: cpuN timer=… kick=… …` per online CPU where the +//! machine ends, as records at its stop and in the record its death seals +//! (`kernel/src/census.rs`), and in the blocked-task dump; at no process's end. The counters are cumulative since boot, so the //! largest count each source reaches on a CPU's lines is that boot's whole //! census ([`Census::raise`]). `irq_census_conservation` asks whether one //! boot's census is internally consistent. diff --git a/tests/common/power.rs b/tests/common/power.rs index 8eed7cf96b0..7ba2ad8060e 100644 --- a/tests/common/power.rs +++ b/tests/common/power.rs @@ -305,6 +305,17 @@ fn the_tail_is_the_stops(after: &serial::Serial) -> Result<(), String> { Ok(()) } +/// A machine that died took its census as one that stops does: the record its +/// death sealed carries every line of `kernel/src/census.rs`, written by the +/// seal itself, since no process's end leaves one in the ring for a tail to +/// carry. +fn death_took_the_census(after: &serial::Serial) -> Result<(), String> { + for line in ["irq: cpu0 ", "tlb: shootdowns=", "irq: unclaimed vectors", bootlog::PANEL_CENSUS] { + after.must_say_after(bootlog::PREVIOUS_PANIC, line)?; + } + Ok(()) +} + /// The metal half of the load arm: a T14 boot that never stopped writing, ended /// by the boot deadline with its controller mid-transfer, and the stick still /// there afterwards. @@ -316,6 +327,7 @@ fn the_tail_is_the_stops(after: &serial::Serial) -> Result<(), String> { /// under this arm's name, so this judge names the bound it demands. pub fn usb_load_chain(after: &serial::Serial) -> Result<(), String> { after.must_say(bootlog::PREVIOUS_PANIC)?; + death_took_the_census(after)?; after.must_say_after(bootlog::PREVIOUS_PANIC, bootlog::DEADLINE_EXPIRED)?; // The sweep starts inside the stop, after the supervisor had the file made whole, so // its records cross only in the page's tail. @@ -364,6 +376,7 @@ fn record_cpu<'a>(line: &'a str, needle: &str) -> Option<&'a str> { /// is the one channel that carries a copy of it across the reset. pub fn deadline_wedge_chain(after: &serial::Serial) -> Result<(), String> { after.must_say(bootlog::PREVIOUS_PANIC)?; + death_took_the_census(after)?; let said = after.must_say_after(bootlog::PREVIOUS_PANIC, bootlog::DEADLINE_EXPIRED)?.to_string(); // The control: the machine reached the staged wedge, and then never reached // the reset it was one statement away from. @@ -420,6 +433,7 @@ pub fn hard_lockup_chain( says_nothing_of(kernel, "CPUID states no architectural performance counter")?; after.must_say(bootlog::PREVIOUS_PANIC)?; + death_took_the_census(after)?; let said = after.must_say_after(bootlog::PREVIOUS_PANIC, bootlog::LOCKED_UP)?.to_string(); let stuck = after.must_say_after(bootlog::PREVIOUS_PANIC, "spinning on the lock at 0x")?; sp_is_a_kernel_stack(stuck)?; diff --git a/toyos-elide/src/limit.rs b/toyos-elide/src/limit.rs index a3d26f01b6a..be29da28486 100644 --- a/toyos-elide/src/limit.rs +++ b/toyos-elide/src/limit.rs @@ -2,17 +2,15 @@ //! record after a suppression says about it. //! //! **A storm from one site is a storm in the log, and the log is shared.** A -//! thread-churn loop makes one `exit:` record per thread; a program printing in -//! a loop fills its ring and then the volume. Past [`Limit`]'s burst in a +//! program printing in a loop fills its ring and then the volume. Past [`Limit`]'s burst in a //! window a site's records are suppressed and counted, and the next record it //! is allowed carries the count, so nothing goes silently: the last record a //! site says before suppressing says so, and the first it says after it says //! how many. //! -//! Atomic, so the kernel's call sites — any CPU, any context `log!` runs in — -//! share one per site with no lock; one reader-thread caller uses it the same -//! way. The counts are exact; which of two racing records is the one a window -//! admits last is not. +//! Atomic, so callers on any thread share one per site with no lock. The +//! counts are exact; which of two racing records is the one a window admits +//! last is not. use core::sync::atomic::{AtomicU64, Ordering::Relaxed}; From 31958d800a49493d0e64ec2f49e58f782629b717 Mon Sep 17 00:00:00 2001 From: japabu Date: Thu, 8 Oct 2026 21:01:32 +0200 Subject: [PATCH 3/4] The retention issue takes the T14 reading at c6269f885 Read off the readback of `testcases`: 7,562,577 bytes whole, 22,178 spawn and 22,168 exit records, 336 bytes a process, and the margin as the factor it is. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01RvnWQFcMuGqTHYhvSnTe8A --- ...ddle-and-the-rows-whose-lines-sat-there.md | 20 +++++++++++-------- 1 file changed, 12 insertions(+), 8 deletions(-) diff --git a/issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md b/issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md index 679e6f6a827..bdfdf8a5c21 100644 --- a/issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md +++ b/issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md @@ -29,16 +29,20 @@ A process's end now writes one record, its `exit:`, carrying what `syscalls:` and `memory:` said; a spawn writes one, its `spawn:`; and the machine's census is taken once, where the machine ends (`kernel/src/census.rs`). -`testcases` on the T14 at `f2b337afd`, the first head with two records a -process: 8,730,435 bytes, no part deleted, 22,091 `spawn:` and 22,081 `exit: … -pid=` records, 390 bytes a child against 1,989. - -**The margin is a factor, not a bound.** 8.73 MB is 52% of the sixteen -megabytes kept, 98.7% of it still that one job's `spawn:` and `exit:` records, -and the phase spawns a child per CPU for twenty seconds: about 1.9 times the +`testcases` on the T14 at `c6269f885`: `kernel.log` is 7,562,577 bytes and +whole, with no `was deleted` line. It holds 22,178 `spawn:` records of 163 +bytes and 22,168 `exit: … pid=` records of 173, 336 bytes a process against +1,989, and no `irq: cpu`, thread-exit, `dynamic:`, `dlopen:` or suppression +line. The stop's fifteen records came back on the black-box page, none +dropped, the census among them. + +**The margin is a factor, not a bound.** 7.56 MB is 45% of the sixteen +megabytes kept, 98.5% of it still that one job's `spawn:` and `exit:` records, +and the phase spawns a child per CPU for twenty seconds: about 2.2 times the children, a sixteen-CPU machine or a faster one, outlogs the retention again. **The harness is as silent about a hole as it was**: nothing reds a readback -whose own boot deleted a part of its log. +whose own boot deleted a part of its log. How many parts this boot wrote was +not read. ## Measured From ffe11fedc8c7dd43b4e223657b540dce477815d4 Mon Sep 17 00:00:00 2001 From: japabu Date: Thu, 8 Oct 2026 21:20:09 +0200 Subject: [PATCH 4/4] The panic seal's census is read, the tail's accounting is host-tested, and the load says nothing on the way MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Review round 2 of #776. The panic's census had no reader. `screen_fatal_halt_composited` already reads the PANIC page out of the halted guest; it now requires a line that begins `irq: cpu0 ` and one that begins `tlb: shootdowns=`, anchored at the line's start because the ring's tail under the census can carry a blocked-task dump's stamped `irq: cpu0`. The stop's tail kept its accounting in the kernel, where the arm that drops ran on no machine. It is `toyos_blackbox::Whole` now, beside `Report::tail`: a line goes in whole or not at all, the first that does not fit drops itself and every later one, and the count's line comes off the room first. Three host tests reach the dropping arm, the exact fit and the reserve. The kernel keeps the sink. A death's census was bounded by `MAX_CPUS = 8` and nothing said so; written through `Report::write` it would have been cut mid-line, silently, ahead of the ring's tail. It goes through the same `Whole` within `toyos_blackbox::CENSUS_BYTES`, a quarter of the box as the recovery section's share is, and says what it dropped. A `const` assertion was the other choice and was not taken: the worst case of four lines in two architectures' formats (the unclaimed line alone can name 256 vectors) is a hand-kept sum, where the budget is one accounting already under test. The tail's range was `from..=to` with `from` the newest record before the stop, so the tail opened with a record that was not the stop's (on the T14, the spawn of `/system/bin/reboot`). `seal_tail` takes that stamp as `after` and reads from the nanosecond past it. Three records were written on the way of a load, against the loader's header: - `dlopen: prescan … not caching` is deleted. The library still loads; the sibling arm that leaves one uncached, no memory for its window, never said so; nothing read the line. - `ELF: .symtab … no symbol map` is deleted. Its consequence is already in the spawn's one record: an executable that exports nothing leaves what a library wanted of it in `unresolved=`. - `ELF: {counts} refused` is deleted: it was a second record on a refused spawn, whose one record already names the reason. `kernel/src/process.rs`'s header names the two records written at a process's end that are not the process's: a device function's ports going back (`crate::isa`, the pair of its bind record, bounded by the ISA table and absent for a process that held none, so not a field of every `exit:`), and a fault's report, which is several records and cannot ride one. Records: the two fixtures drop the `(16)` no kernel writes; the retention issue says fourteen of the fifteen records were the stop's; the exit-record issue is renamed to what survives of it, with an owner and an exit; refusal records per call and `toyos-elide`'s one-user `limit` are filed. Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01RvnWQFcMuGqTHYhvSnTe8A --- ...record-landed-under-the-boots-last-word.md | 38 ----- ...-per-call-and-nothing-bounds-the-caller.md | 52 ++++++ ...ddle-and-the-rows-whose-lines-sat-there.md | 6 +- ...-last-word-and-no-record-can-say-so-now.md | 43 +++++ ...as-one-user-and-lives-in-a-shared-crate.md | 25 +++ kernel/src/census.rs | 20 ++- kernel/src/elf/cache.rs | 1 - kernel/src/elf/index.rs | 5 +- kernel/src/loader/symbols.rs | 20 +-- kernel/src/log/mod.rs | 52 ++---- kernel/src/process.rs | 7 + kernel/src/syscall/machine.rs | 2 +- src/metaldevices.rs | 2 +- tests/checks.rs | 2 +- tests/toyos.rs | 11 ++ toyos-blackbox/src/lib.rs | 153 ++++++++++++++++-- 16 files changed, 323 insertions(+), 116 deletions(-) delete mode 100644 issues/a-jobs-exit-record-landed-under-the-boots-last-word.md create mode 100644 issues/a-refused-syscall-writes-a-log-record-per-call-and-nothing-bounds-the-caller.md create mode 100644 issues/a-thread-ended-after-the-boots-last-word-and-no-record-can-say-so-now.md create mode 100644 issues/toyos-elides-limit-has-one-user-and-lives-in-a-shared-crate.md diff --git a/issues/a-jobs-exit-record-landed-under-the-boots-last-word.md b/issues/a-jobs-exit-record-landed-under-the-boots-last-word.md deleted file mode 100644 index 4167e10f6bd..00000000000 --- a/issues/a-jobs-exit-record-landed-under-the-boots-last-word.md +++ /dev/null @@ -1,38 +0,0 @@ ---- -status: open -kind: defect -opened: 2026-09-25 ---- - -# A job's exit record landed under the boot's last word - -`quiesce_wakes_on_the_last_park` (`tests/common/power.rs`'s `stopped_boot`) -was red twice in one fast-tier run on PR #492, once beside other guests and -once alone, with the dev host also running another worktree's suite: - -``` -1 line(s) reached the console after the boot's last word: - [kernel 2.546 cpu0 tid=2] exit: test_rs_quiesce_last tid=2 code=0 cpu=2014ms -``` - -(`2.468` on the rerun.) Three runs alone right after, on the same tree, were -green. The round under test changed no kernel, init, test-runner or -`tests/quiescelastcase` file, so the record was the kernel's own: the job that -parked last exited, and its `exit:` record reached the console after -`Rebooting.`. - -Not known: whether the job's exit is a transition the stop is meant to have -seen before it writes the last word, or a record the stop should keep from -the console once it has. - -**The record is gone and the question is not.** A thread's end no longer -writes a record, so this line cannot reach the console after the last word; -whether a thread may still be leaving once the stop has said it is what the -deleted test asked, and nothing asks it now. - -## Exit condition - -A job's exit record either precedes the boot's last word or never reaches the -console after it, and the test is green under a loaded host. - -`quiesce_wakes_on_the_last_park` is deleted; `issues/quiesce-wakes-on-the-last-park-gave-up-on-one-thread-beside-the-held-one.md` records the commit that restores it. diff --git a/issues/a-refused-syscall-writes-a-log-record-per-call-and-nothing-bounds-the-caller.md b/issues/a-refused-syscall-writes-a-log-record-per-call-and-nothing-bounds-the-caller.md new file mode 100644 index 00000000000..d70b69d357f --- /dev/null +++ b/issues/a-refused-syscall-writes-a-log-record-per-call-and-nothing-bounds-the-caller.md @@ -0,0 +1,52 @@ +--- +status: open +kind: defect +opened: 2026-10-08 +--- + +# A refused syscall writes a log record per call, and nothing bounds the caller + +A refusal the kernel answers with an error is also a kernel log record, once +per call, at every one of these sites, and the caller chooses how often: + +- `sys_dlopen` (`kernel/src/syscall/vm.rs`): a path that does not open + (`dlopen: : `), a cached image whose file changed, an image + `elf::load_shared_lib` refuses, no virtual address space left, and a TLS + reference that leaves its module's segment; +- `elf::cache_loaded_lib` (`kernel/src/elf/cache.rs`): a load that would take + the shared-object cache past its budget; +- a refused spawn (`kernel/src/loader/mod.rs`): every `spawn: : …` + record, one for each reason a file can be refused. + +`dlopen` of a missing path in a loop, or a spawn of a file that is not an +executable, is a record per syscall from any program, into a log every +program shares: `logkeeper` keeps sixteen megabytes of a boot +(`issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md`), +and what a storm of these pushes out is the middle of everybody else's. + +`kernel/src/loader/mod.rs`'s header states the refusal's record as the +contract, and `kernel/src/process.rs`'s that nothing a process writes is +rate-limited. The kernel holds no limiter: its one user, a thread's end, was +deleted with the record it limited. `logkeeper` limits what a program writes +through its own ring (`userland/logkeeper/src/origin.rs`), and these are the +kernel's records, which that limit does not reach. + +Not measured: no test loops a refused call and reads what the log grew by. +The sites are older than the contract that now names them. + +Owner: the syscall layer, `kernel/src/syscall/`, with the loader's header. + +## Exit condition + +The log's volume from refusals does not grow with how often a program asks. +One of two shapes, decided by which a reader of a failed boot needs: + +- a refusal the caller is told by its error is not also a record: the error + names the reason, and the program that cares says it in its own ring, under + `logkeeper`'s limit; or +- the kernel counts a process's refusals and says the count once, in that + process's `exit:` record. + +Either way the two headers say which, and a guest test has one process make a +refused `dlopen` and a refused spawn a thousand times each and finds the +number of kernel records that name it the same as after one. diff --git a/issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md b/issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md index bdfdf8a5c21..1c9bb775b02 100644 --- a/issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md +++ b/issues/a-t14-boot-that-outlogs-its-retention-loses-its-middle-and-the-rows-whose-lines-sat-there.md @@ -33,8 +33,10 @@ is taken once, where the machine ends (`kernel/src/census.rs`). whole, with no `was deleted` line. It holds 22,178 `spawn:` records of 163 bytes and 22,168 `exit: … pid=` records of 173, 336 bytes a process against 1,989, and no `irq: cpu`, thread-exit, `dynamic:`, `dlopen:` or suppression -line. The stop's fifteen records came back on the black-box page, none -dropped, the census among them. +line. Fifteen records came back on the black-box page, none dropped: the +stop's fourteen, the census among them, and the newest record before the +stop, the spawn of `/system/bin/reboot`, which the seal's range took in at +that head and takes in no longer. **The margin is a factor, not a bound.** 7.56 MB is 45% of the sixteen megabytes kept, 98.5% of it still that one job's `spawn:` and `exit:` records, diff --git a/issues/a-thread-ended-after-the-boots-last-word-and-no-record-can-say-so-now.md b/issues/a-thread-ended-after-the-boots-last-word-and-no-record-can-say-so-now.md new file mode 100644 index 00000000000..d92da660a0d --- /dev/null +++ b/issues/a-thread-ended-after-the-boots-last-word-and-no-record-can-say-so-now.md @@ -0,0 +1,43 @@ +--- +status: open +kind: defect +opened: 2026-09-25 +--- + +# A thread ended after the boot's last word, and no record can say so now + +`quiesce_wakes_on_the_last_park` (`tests/common/power.rs`'s `stopped_boot`) +was red twice in one fast-tier run on PR #492, once beside other guests and +once alone, with the dev host also running another worktree's suite: + +``` +1 line(s) reached the console after the boot's last word: + [kernel 2.546 cpu0 tid=2] exit: test_rs_quiesce_last tid=2 code=0 cpu=2014ms +``` + +(`2.468` on the rerun.) Three runs alone right after, on the same tree, were +green. The round under test changed no kernel, init, test-runner or +`tests/quiescelastcase` file, so the record was the kernel's own: the thread +the job parked last ended, and the record of its end reached the console +after `Rebooting.`. + +**The record that showed it is deleted, and what it showed is not answered.** +A thread's end writes nothing now (`kernel/src/process.rs`'s header), so that +line cannot follow the last word again and no boot can show this. The sighting +does not say which of two things happened: the thread ran its exit after the +stop had counted it stopped, or it ended before the last word and its record +was committed behind it. The first is a thread running kernel code on a +machine the stop has declared still; the stop's `stop:` record carries counts +taken at its last sweep and nothing later. + +Owner: the stop path, `kernel/src/quiesce.rs`. + +## Exit condition + +- The stop says how many threads ended between its `stop:` record and the + reset, in a record the next loader pass prints, and `stopped_boot` reds on + one that is not zero. +- `quiesce_wakes_on_the_last_park`, deleted with the commits + `issues/quiesce-wakes-on-the-last-park-gave-up-on-one-thread-beside-the-held-one.md` + names, is back and green beside other guests on a loaded host with that + check in it. diff --git a/issues/toyos-elides-limit-has-one-user-and-lives-in-a-shared-crate.md b/issues/toyos-elides-limit-has-one-user-and-lives-in-a-shared-crate.md new file mode 100644 index 00000000000..bd1761cb2d2 --- /dev/null +++ b/issues/toyos-elides-limit-has-one-user-and-lives-in-a-shared-crate.md @@ -0,0 +1,25 @@ +--- +status: open +kind: defect +opened: 2026-10-08 +--- + +# `toyos-elide`'s `limit` has one user and lives in a shared crate + +`toyos-elide/src/limit.rs` (`Limit`, `Admit`) is used by +`userland/logkeeper/src/origin.rs` and by nothing else: the kernel's +`log_limited!`, its other user, is deleted with the thread-exit record it +limited. The crate is shared for `Elided`, which `toyos-symbols` uses; what +one program alone uses belongs in that program's package +(`.claude/agents/reviewer.md`, "Fit"). + +Not moved where it was found: PR #773 is open over `userland/logkeeper/src`, +and the module moves into the tree that leaves. + +Owner: `userland/logkeeper`. + +## Exit condition + +Once #773 has landed: `limit.rs` is a module of `userland/logkeeper` with its +host tests, `toyos-elide` holds `Elided` and what serves it, its header and +`description` say so, and `rg 'toyos_elide::limit'` finds nothing. diff --git a/kernel/src/census.rs b/kernel/src/census.rs index 527b36bd736..8b757244e97 100644 --- a/kernel/src/census.rs +++ b/kernel/src/census.rs @@ -30,16 +30,22 @@ pub fn log() { } /// A death's: the same lines as text, for the record it seals. +/// +/// Within [`toyos_blackbox::CENSUS_BYTES`], because the record is one page and +/// the lines grow with `MAX_CPUS`: a line that does not fit is dropped whole +/// with every one after it, and the count is said under the ones kept +/// ([`toyos_blackbox::Whole`]). pub struct Sealed; impl fmt::Display for Sealed { fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result { - let mut wrote = Ok(()); - each(|line| { - if wrote.is_ok() { - wrote = writeln!(f, "{line}"); - } - }); - wrote + let mut lines = toyos_blackbox::Whole::within( + f, + toyos_blackbox::CENSUS_BYTES, + toyos_blackbox::CENSUS_DROPPED_OPENS_WITH, + ); + each(|line| lines.put(line)); + lines.close(); + Ok(()) } } diff --git a/kernel/src/elf/cache.rs b/kernel/src/elf/cache.rs index 317c29f57f1..cf5a7fa632b 100644 --- a/kernel/src/elf/cache.rs +++ b/kernel/src/elf/cache.rs @@ -46,7 +46,6 @@ fn prescan_relocs(lib: &LoadedLib) -> Option { let kept = [RelocKind::GlobDat, RelocKind::Tpoff64, RelocKind::Tpoff32, RelocKind::DtpMod64, RelocKind::DtpOff64]; if counts.max_of(&kept).checked_mul(widest).is_none_or(|b| b > MAX_HEAP_ALLOC) { - log!("dlopen: prescan {:?} will not fit one allocation, not caching", counts); return None; } // Capacities are reserved exactly from `counts`; growing them could allocate past the bound just checked. diff --git a/kernel/src/elf/index.rs b/kernel/src/elf/index.rs index 3172aa721eb..78dfe16cf20 100644 --- a/kernel/src/elf/index.rs +++ b/kernel/src/elf/index.rs @@ -72,10 +72,7 @@ pub fn parse_rela_entries( .chain(RelaTable::new(jmprel_data, crate::arch::ELF_MACHINE).iter()) }; let counts = RelaCounts::of(entries()); - let reserve = counts - .for_executable(WIDEST, MAX_HEAP_ALLOC) - .inspect_err(|_| log!("ELF: {:?} refused", counts)) - .map_err(Refused::Counts)?; + let reserve = counts.for_executable(WIDEST, MAX_HEAP_ALLOC).map_err(Refused::Counts)?; let mut out = ParsedRelaEntries { relative: Vec::with_capacity(reserve.relative), glob_dat: Vec::with_capacity(reserve.bind), diff --git a/kernel/src/loader/symbols.rs b/kernel/src/loader/symbols.rs index 9d1411fd927..1205453d9bd 100644 --- a/kernel/src/loader/symbols.rs +++ b/kernel/src/loader/symbols.rs @@ -55,21 +55,15 @@ fn map<'a>( } /// `.symtab` and its `.strtab`, read whole — the fallback for a PIE that -/// exports nothing through `.dynsym`. +/// exports nothing through `.dynsym`. `None` is an executable with no such +/// tables, or tables past one kernel allocation: it then exports nothing, and +/// what a library wanted of it is in the spawn's `unresolved=`. pub fn read_symtab(backing: &dyn FileBacking, layout: &Layout) -> Option<(Vec, Vec)> { let table = layout.section_headers()?; let shdrs = super::read_file_range(backing, table.file_offset, table.byte_len()); let (syms, strs) = SectionTable::new(&shdrs).symbols(SHT_SYMTAB)?; - - let (Some(sym_data), Some(str_data)) = ( - read_elf_table(backing, syms.offset, syms.size as usize), - read_elf_table(backing, strs.offset, strs.size as usize), - ) else { - log!( - "ELF: .symtab {} / .strtab {} exceed one kernel allocation, no symbol map", - syms.size, strs.size - ); - return None; - }; - Some((sym_data, str_data)) + Some(( + read_elf_table(backing, syms.offset, syms.size as usize)?, + read_elf_table(backing, strs.offset, strs.size as usize)?, + )) } diff --git a/kernel/src/log/mod.rs b/kernel/src/log/mod.rs index 6471ff70fb1..c2028de61ab 100644 --- a/kernel/src/log/mod.rs +++ b/kernel/src/log/mod.rs @@ -61,15 +61,15 @@ pub fn shard_for(cpu: u32) -> &'static Shard { const TAIL_HEAD: &str = "log: this boot's newest records follow, newest first"; /// Seal the stop's own records onto the black box, the one channel a boot's -/// tail has once the stop has begun: every record stamped at `from` or after, -/// newest first. +/// tail has once the stop has begun: every record stamped after `after`, +/// which is the newest one the stop found, newest first. /// -/// **Bounded by the page and by nothing else.** The records may spend what a -/// report may ([`toyos_blackbox::REPORT_BYTES`]), which leaves the reset's own -/// account its reserve; the oldest that do not fit are counted and the count -/// is said last, in the words a death's tail says it -/// ([`toyos_blackbox::DROPPED_OPENS_WITH`]). How many records a stop writes is -/// the machine's to decide, by its CPUs and its disks. +/// **Bounded by the page and by nothing else.** The head and the records may +/// spend what a report may ([`toyos_blackbox::REPORT_BYTES`]), which leaves +/// the reset's own account its reserve; [`toyos_blackbox::Whole`] keeps the +/// newest that fit, counts the rest and says the count last, in the words a +/// death's tail says it ([`toyos_blackbox::DROPPED_OPENS_WITH`]). How many +/// records a stop writes is the machine's to decide, by its CPUs and its disks. /// /// **The kernel does not wait for `/system/bin/logkeeper`, so it does not know what /// reached `/log`.** `/system/bin/supervisor` has `logkeeper` flush before it asks for the @@ -79,45 +79,23 @@ const TAIL_HEAD: &str = "log: this boot's newest records follow, newest first"; /// /// Called from the quiesce path under [`crate::blackbox::record_done`], where /// the page already carries this boot's seal and every lock is still ordinary. -pub fn seal_tail(from: LogStamp) { - use core::fmt::Write as _; - /// How long a line is, without writing it. - struct Length(usize); - impl core::fmt::Write for Length { - fn write_str(&mut self, s: &str) -> core::fmt::Result { - self.0 += s.len(); - Ok(()) - } - } - struct Tail<'a> { - out: &'a mut dyn core::fmt::Write, - left: usize, - dropped: u64, - } +pub fn seal_tail(after: LogStamp) { + struct Tail<'a>(toyos_blackbox::Whole<'static, &'a mut dyn core::fmt::Write>); impl read::RecordSink for Tail<'_> { fn put(&mut self, record: &LogRecord) -> bool { - let mut line = Length(0); - let _ = writeln!(line, "log-tail: {record}"); - // Once one is dropped every older one is: a tail with a hole in it reads as whole. - if self.dropped > 0 || line.0 > self.left { - self.dropped += 1; - return true; - } - self.left -= line.0; // No prefix of its own: the loader that prints this page puts one // on every line it reads back. - let _ = writeln!(self.out, "log-tail: {record}"); + self.0.put(format_args!("log-tail: {record}")); true } } + let from = LogStamp::since_zero(after.nanos().saturating_add(1)); crate::blackbox::append(|out| { let _ = writeln!(out, "{TAIL_HEAD}"); - let left = toyos_blackbox::REPORT_BYTES - TAIL_HEAD.len() - 1 - toyos_blackbox::DROPPED_LINE_BYTES; - let mut tail = Tail { out, left, dropped: 0 }; + let room = toyos_blackbox::REPORT_BYTES - TAIL_HEAD.len() - 1; + let mut tail = Tail(toyos_blackbox::Whole::within(out, room, toyos_blackbox::DROPPED_OPENS_WITH)); read::snapshot_committed(from, read::newest_committed(), &mut tail); - if tail.dropped > 0 { - let _ = writeln!(tail.out, "{}{}", toyos_blackbox::DROPPED_OPENS_WITH, tail.dropped); - } + tail.0.close(); }); } diff --git a/kernel/src/process.rs b/kernel/src/process.rs index 535b1895677..0129cec1200 100644 --- a/kernel/src/process.rs +++ b/kernel/src/process.rs @@ -16,6 +16,13 @@ //! its stop or by its death, and no process's start or end repeats one: the //! log's volume is then a function of what ran, never of how many CPUs //! watched it. +//! +//! Two records written where a process ends are another owner's and are +//! charged to it, not to the process: a device function whose ports the +//! process held says they went back (`crate::isa::process_ends`, the pair of +//! the record its claim wrote when it bound them), and a fault that ends a +//! process writes the fault's report ([`dump_crash_diagnostics`]), which is +//! several records because it is a crash and not an end. use alloc::alloc::{alloc_zeroed, dealloc, Layout}; use alloc::string::String; diff --git a/kernel/src/syscall/machine.rs b/kernel/src/syscall/machine.rs index 2b5ba15a9ba..e18c15ef275 100644 --- a/kernel/src/syscall/machine.rs +++ b/kernel/src/syscall/machine.rs @@ -93,7 +93,7 @@ fn quiesce(last: &str) -> Result { let (stopped, stopping) = crate::quiesce::stop(); crate::log::console::drain_for_the_stop(); // From here on nothing carries a record to a file: the seal below takes - // every one written after this stamp. + // every one stamped after this one, the newest the stop found. let stop_began = crate::log::read::newest_committed(); // The machine's census, which no process's start or end takes. crate::census::log(); diff --git a/src/metaldevices.rs b/src/metaldevices.rs index 9c9e85cf4c5..41d5a905639 100644 --- a/src/metaldevices.rs +++ b/src/metaldevices.rs @@ -103,7 +103,7 @@ mod tests { "ToyOS Bootloader 1.0\n\ Black box: the last boot read DONE, so it handed the machine back on purpose and this \ chain ends here\n\ - | log: this boot's newest records follow, newest first (16)\n\ + | log: this boot's newest records follow, newest first\n\ | log-tail: [ 3.960 cpu0 kernel] Rebooting.\n\ | log-tail: [ 3.955 cpu0 kernel] usb-quiesce: disk 0 SYNCHRONIZE CACHE ok\n\ | usb-quiesce: no Bulk-Only command was open, so this reset cuts none\n\ diff --git a/tests/checks.rs b/tests/checks.rs index 271752d60b5..b224ccb7970 100644 --- a/tests/checks.rs +++ b/tests/checks.rs @@ -967,7 +967,7 @@ mod checks { "{HANDOFF}{}\nToyOS Bootloader 1.0\n\ Black box: the last boot read DONE, so it handed the machine back on purpose and \ this chain ends here\n\ - | log: this boot's newest records follow, newest first (16)\n{tail}\ + | log: this boot's newest records follow, newest first\n{tail}\ Loader log: the last boot is accounted for, so this pass resets the machine\n", bootlog::SEPARATOR ) diff --git a/tests/toyos.rs b/tests/toyos.rs index c30c456ee58..0dbc256c2b4 100644 --- a/tests/toyos.rs +++ b/tests/toyos.rs @@ -2774,6 +2774,17 @@ fn run_screen_test(name: &str, profile: qemu::Profile, test_config: &Path) -> Re if sealed.contains(MARKER) { "carries" } else { "lacks" }, )); } + // The death's own census, which the seal writes as lines of its + // own. Anchored at the line's start: the ring's tail under it can + // carry a blocked-task dump's `irq: cpu0`, behind a record's stamp. + for owed in ["irq: cpu0 ", "tlb: shootdowns="] { + if !sealed.lines().any(|line| line.starts_with(owed)) { + return Err(format!( + "the panic's sealed record has no line that begins {owed:?}, so this \ + death took no census of the machine\n{sealed}" + )); + } + } drop(qemu); eprintln!( " [panic] the fatal report is on the panel and sealed in the black box ({} bytes)", diff --git a/toyos-blackbox/src/lib.rs b/toyos-blackbox/src/lib.rs index d879879f7b7..312a46c4b45 100644 --- a/toyos-blackbox/src/lib.rs +++ b/toyos-blackbox/src/lib.rs @@ -214,7 +214,80 @@ pub const DROPPED_OPENS_WITH: &str = "older records dropped to fit this page: "; /// against the true count, because the count depends on the cut and the cut /// would then depend on the count — and a few unused bytes of a page are worth /// less than a fixed point nobody can check. -pub const DROPPED_LINE_BYTES: usize = DROPPED_OPENS_WITH.len() + 20 + 1; +pub const DROPPED_LINE_BYTES: usize = counted_line_bytes(DROPPED_OPENS_WITH); + +/// The widest a line that ends in a count can be: `says`, every digit a `u64` +/// can have, and its newline. +const fn counted_line_bytes(says: &str) -> usize { + says.len() + 20 + 1 +} + +/// How long `line` is, without writing it. +fn bytes_of(line: core::fmt::Arguments<'_>) -> usize { + struct Count(usize); + impl core::fmt::Write for Count { + fn write_str(&mut self, s: &str) -> core::fmt::Result { + self.0 = self.0.saturating_add(s.len()); + Ok(()) + } + } + let mut count = Count(0); + let _ = core::fmt::write(&mut count, line); + count.0 +} + +/// Lines that arrive one at a time, kept whole within a room, **and a count of +/// the ones that were not kept**. +/// +/// What [`Report::tail`] is for bytes already rendered, for a writer that has +/// only a walk: the stop's own records, newest first, and a death's census. +/// A line goes in whole or not at all. **Once one is dropped every later one +/// is**, because a section with a hole in it reads as whole. [`Self::close`] +/// then says how many on `says`' line, whose widest form came off the room +/// before the first line did, so saying it is never what runs the room over. +pub struct Whole<'s, W: core::fmt::Write> { + out: W, + says: &'s str, + left: usize, + dropped: u64, +} + +impl<'s, W: core::fmt::Write> Whole<'s, W> { + /// `room` bytes of `out` for the lines and for the line that counts the + /// dropped ones, which opens with `says`. + pub fn within(out: W, room: usize, says: &'s str) -> Self { + Self { out, says, left: room.saturating_sub(counted_line_bytes(says)), dropped: 0 } + } + + /// One line, without its newline. + pub fn put(&mut self, line: core::fmt::Arguments<'_>) { + let bytes = bytes_of(line).saturating_add(1); + if self.dropped > 0 || bytes > self.left { + self.dropped = self.dropped.saturating_add(1); + return; + } + self.left -= bytes; + let _ = self.out.write_fmt(format_args!("{line}\n")); + } + + /// Say how many lines were dropped, under the ones kept; nothing where + /// none was. + pub fn close(mut self) { + if self.dropped > 0 { + let _ = self.out.write_fmt(format_args!("{}{}\n", self.says, self.dropped)); + } + } +} + +/// The most a death's census may spend of the record it is sealed into: a +/// quarter of the box, as [`RECOVERY_BYTES`] is, so that what a kernel built +/// for more CPUs says of them comes off the census and never off the crash +/// above it or the ring's tail below. +pub const CENSUS_BYTES: usize = 4096; + +/// What a census that did not fit [`CENSUS_BYTES`] says under the lines it +/// kept, with the count of the ones it dropped after it. +pub const CENSUS_DROPPED_OPENS_WITH: &str = "census: lines dropped to fit this record: "; /// How many records begin in `bytes`, by the same rule [`Report::tail`] cuts on. fn records_in(bytes: &[u8], opens_a_record: &[u8]) -> u64 { @@ -481,16 +554,7 @@ pub fn says_a_break(message: &str) -> bool { /// What one record's line costs in the section. fn recovery_line_bytes(line: &impl core::fmt::Display) -> usize { - struct Count(usize); - impl core::fmt::Write for Count { - fn write_str(&mut self, s: &str) -> core::fmt::Result { - self.0 = self.0.saturating_add(s.len()); - Ok(()) - } - } - let mut count = Count(0); - let _ = core::fmt::write(&mut count, format_args!("{RECOVERY_OPENS_WITH}{line}\n")); - count.0 + bytes_of(format_args!("{RECOVERY_OPENS_WITH}{line}\n")) } /// The first of the section's two walks over the log ring, **newest record @@ -1037,6 +1101,73 @@ mod tests { assert_eq!(dropped, records[..records.len() - kept.len()].lines().count()); } + /// What [`Whole`] leaves of `lines` in `room` bytes: the lines it kept, and + /// the count it said under them. + fn whole(room: usize, lines: &[&str]) -> (std::string::String, Option) { + let mut out = std::string::String::new(); + let mut kept = Whole::within(&mut out, room, DROPPED_OPENS_WITH); + for line in lines { + kept.put(format_args!("{line}")); + } + kept.close(); + match out.find(DROPPED_OPENS_WITH) { + Some(at) => { + let said = out[at + DROPPED_OPENS_WITH.len()..].trim_end_matches('\n'); + let dropped = said.parse().expect("the line that counts ends in the count"); + (out[..at].into(), Some(dropped)) + } + None => (out, None), + } + } + + /// The room is the lines' own bytes and the count's reserve: a room that + /// holds exactly both keeps every line and says nothing, and one byte less + /// drops the last. + #[test] + fn lines_that_fit_their_room_are_kept_and_nothing_is_said() { + let lines = ["irq: cpu0 timer=9", "irq: cpu1 timer=4", "tlb: shootdowns=4"]; + let bytes: usize = lines.iter().map(|line| line.len() + 1).sum(); + let exact = bytes + DROPPED_LINE_BYTES; + assert_eq!(whole(exact, &lines), (format!("{}\n", lines.join("\n")), None)); + assert_eq!(whole(exact - 1, &lines), (format!("{}\n", lines[..2].join("\n")), Some(1))); + } + + /// A line that does not fit takes every later one with it, one that would + /// have fitted included: what is kept is a prefix of the walk and the + /// count is of everything after it. + #[test] + fn the_first_line_that_does_not_fit_drops_itself_and_every_later_one() { + let wide = "x".repeat(200); + let lines = ["the newest", wide.as_str(), "short", "shorter"]; + let room = DROPPED_LINE_BYTES + lines[0].len() + 1 + 100; + assert_eq!(whole(room, &lines), ("the newest\n".into(), Some(3))); + // The same walk with the wide line last keeps the three before it. + let lines = ["the newest", "short", "shorter", wide.as_str()]; + assert_eq!(whole(room, &lines), ("the newest\nshort\nshorter\n".into(), Some(1))); + } + + /// Whatever the room, the lines kept and the line that counts the rest + /// stay inside it, and every line is either kept or counted. + #[test] + fn the_line_that_counts_the_dropped_fits_the_room_it_was_given() { + let lines: std::vec::Vec = + (0..400).map(|i| format!("log-tail: [ 1.{i:03} cpu0 kernel] record {i}")).collect(); + let lines: std::vec::Vec<&str> = lines.iter().map(|line| line.as_str()).collect(); + for room in DROPPED_LINE_BYTES..DROPPED_LINE_BYTES + 2048 { + let mut out = std::string::String::new(); + let mut kept = Whole::within(&mut out, room, DROPPED_OPENS_WITH); + for line in &lines { + kept.put(format_args!("{line}")); + } + kept.close(); + assert!(out.len() <= room, "a room of {room} bytes was run to {}", out.len()); + let (kept, dropped) = whole(room, &lines); + let dropped = dropped.expect("400 records do not fit two kilobytes") as usize; + assert_eq!(kept.lines().count() + dropped, lines.len()); + assert!(lines.join("\n").starts_with(kept.trim_end_matches('\n'))); + } + } + /// A report that fits says nothing about a cut, because there was none. #[test] fn a_report_that_fits_carries_no_drop_line() {