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 deleted file mode 100644 index 605e3484a72..00000000000 --- a/issues/a-jobs-exit-record-landed-under-the-boots-last-word.md +++ /dev/null @@ -1,33 +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. - -## 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-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-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 286396216e3..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 @@ -13,8 +13,38 @@ 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; 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 `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. 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, +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. How many parts this boot wrote was +not read. ## 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..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 @@ -82,8 +82,20 @@ 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. + +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 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/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/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/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/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/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 8b6fcfd500c..b8a028933cc 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. -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); } 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 { @@ -91,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 46838f7a0e0..2ac9947151c 100644 --- a/kernel/src/arch/aarch64/trap.rs +++ b/kernel/src/arch/aarch64/trap.rs @@ -232,15 +232,11 @@ 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() { +/// 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 || UNCLAIMED_REPORTED.swap(count, Relaxed) == count { - 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 e88871ea50e..c371a8f3404 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,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 process exit, once per batch. -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), @@ -95,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 || REPORTED.swap(events, Ordering::Relaxed) == events { - return; - } struct Vectors([u64; 4]); impl core::fmt::Display for Vectors { fn fmt(&self, f: &mut core::fmt::Formatter<'_>) -> core::fmt::Result { @@ -110,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 75eda87bae9..902752dc763 100644 --- a/kernel/src/arch/x86_64/tlb.rs +++ b/kernel/src/arch/x86_64/tlb.rs @@ -26,21 +26,16 @@ 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 -/// `irq_census::log_census`: the conservation check reads deliveries first. -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()) { *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 { @@ -50,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 6e2f7607f21..1773e72539f 100644 --- a/kernel/src/block.rs +++ b/kernel/src/block.rs @@ -485,44 +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); - /// 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; - 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 @@ -536,67 +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) - } - - /// Prints the census once per batch of new events; called at process exit. - pub fn print_if_moved() { - 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 { - 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..8b757244e97 --- /dev/null +++ b/kernel/src/census.rs @@ -0,0 +1,51 @@ +//! 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. +/// +/// 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 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/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..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. @@ -232,7 +231,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 +240,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 +274,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 +283,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/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/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 41b6cc13449..66dec389b6e 100644 --- a/kernel/src/irq_census.rs +++ b/kernel/src/irq_census.rs @@ -126,14 +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. -/// A `mask-windows` kernel follows each with that CPU's `windows:` line. +/// 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)); - #[cfg(feature = "mask-windows")] - crate::windows::log_cpu(cpu); + say(format_args!("irq: cpu{cpu}{}", Fields(&counts))); } } diff --git a/kernel/src/loader/mod.rs b/kernel/src/loader/mod.rs index cfa90ffcbd2..04e22e8391a 100644 --- a/kernel/src/loader/mod.rs +++ b/kernel/src/loader/mod.rs @@ -6,6 +6,11 @@ //! //! 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=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)] @@ -448,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. @@ -468,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 { @@ -480,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, } } } @@ -544,22 +550,17 @@ 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(); - 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 { @@ -651,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), @@ -664,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, @@ -673,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 @@ -686,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); @@ -735,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); } @@ -821,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, @@ -829,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); } } @@ -851,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/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 25b1d43aeef..c2028de61ab 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 after `after`, +/// which is the newest one the stop found, newest first. +/// +/// **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 @@ -76,24 +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() { - struct Tail<'a> { - out: &'a mut dyn core::fmt::Write, - left: usize, - } +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 { // 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 + 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} ({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 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); + tail.0.close(); }); } @@ -263,49 +265,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 11cfcca47bc..0129cec1200 100644 --- a/kernel/src/process.rs +++ b/kernel/src/process.rs @@ -6,6 +6,23 @@ //! 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. +//! 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. +//! +//! 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; @@ -1031,12 +1048,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 `crate::census`'s, 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 +1094,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 +1109,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 +1195,12 @@ fn teardown(pid: Pid, tid: Tid, code: i32, mark: i32, process_data: &Arc ! { 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() { @@ -1278,7 +1309,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(); @@ -1294,12 +1325,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 9b752fb2af0..e18c15ef275 100644 --- a/kernel/src/syscall/machine.rs +++ b/kernel/src/syscall/machine.rs @@ -92,9 +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 final census: no process runs after this to report another. - crate::irq_census::log_census(); - crate::drivers::panic_console::log_census(); + // From here on nothing carries a record to a file: the seal below takes + // every one stamped after this one, the newest the stop found. + let stop_began = crate::log::read::newest_committed(); + // 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() { @@ -116,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 74f92ea5671..3d690dbb20d 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 +//! 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 @@ -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/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 cc7e62f99a2..b224ccb7970 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")), @@ -975,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 ) @@ -991,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: \ @@ -1019,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 f3148de4955..bf45c5a80a7 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 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`]). -//! -//! 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/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/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..0dbc256c2b4 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) } @@ -2772,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)", @@ -2995,7 +3008,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 +3074,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 +3089,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 +5142,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()); } 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() { 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};