Skip to content
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension


Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 0 additions & 1 deletion Cargo.lock

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
33 changes: 0 additions & 33 deletions issues/a-jobs-exit-record-landed-under-the-boots-last-word.md

This file was deleted.

40 changes: 19 additions & 21 deletions issues/a-processs-syscall-profile-is-one-threads.md
Original file line number Diff line number Diff line change
Expand Up @@ -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: <name> pid=N code=N cpu=Nms peak=… allocs=…
frees=… syscalls=N syscall_wall=Nms <number>=<count> …`) 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
Expand All @@ -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.
Original file line number Diff line number Diff line change
@@ -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: <path>: <error>`), 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: <path>: …`
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.
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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: <path> 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
Expand Down
Original file line number Diff line number Diff line change
@@ -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.
8 changes: 8 additions & 0 deletions issues/an-xhci-storm-starves-the-cpu-that-takes-it.md
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
36 changes: 25 additions & 11 deletions issues/every-interrupt-lands-on-the-boot-cpu.md
Original file line number Diff line number Diff line change
Expand Up @@ -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:[<off>], 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) |
|---|---|---|
Expand Down

This file was deleted.

Original file line number Diff line number Diff line change
@@ -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.
1 change: 0 additions & 1 deletion kernel/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -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" }
Expand Down
Loading
Loading