fastfetch reported 3 seconds of uptime after 15 real ones, `time` claimed
3.12s for a 20-second command, and ping's one-second interval was closer to
six. One cause, not three: `ticks` was advancing at ~14.5 Hz instead of 100.
It was not the timer. virtio-gpu-pci shares IRQ 11 with the e1000 and
registered no interrupt handler at all. PCI INTx is level-triggered, so the
device held the line asserted, the kernel signalled EOI, and it fired again
immediately -- 72,000 interrupts a second, 83% of CPU0, starving the tick.
The e1000's handler read ICR as zero half a million times, correctly
answering "not mine", which is what made it look like a network-free problem.
Reading virtio's ISR byte clears it and drops the line. That is the fix.
irq_dispatch now measures each line's rate against the TSC -- not ticks,
which is the first casualty of a storm -- and names the attached handlers
once above 20000/s. It reproduces the original fault as a single line.
Found along the way, and fixed because they were real:
- lapicinit loaded TICR with xv6's uncalibrated 10000000, whose own comment
admitted it was never measured. calibrate_timers() now measures the LAPIC
and the TSC against the 8254 PIT. (It came back at 999.9 MHz, so this was
not the bug -- but the next machine is not obliged to be 1 GHz.)
- microdelay() was an empty function body. Every microdelay(1000) in the
xHCI reset path and the USB hub power-on sequence returned instantly.
- HZ is a constant in param.h now, not the literal 100 written out at a
dozen ticks-to-seconds conversions. USER_HZ is separate and deliberately
does not follow it: musl answers sysconf(_SC_CLK_TCK) with 100 always, so
times() and /proc/stat scale at the syscall boundary the way Linux does.
- TIOCGWINSZ answered a hardcoded 24x80. gfx_cols()/gfx_rows() have known
the real geometry all along; at 1024x768 the console is 128x48, so every
program that lays out a screen was formatting for the wrong one.
- TCFLSH fell through to the catch-all `return 0`, claiming to discard
input without discarding any.
uptime now advances 5.01 seconds per 5 real seconds. schfs-check passes.
Full investigation, including the two wrong hypotheses and the measurement
flaw that protected them, in docs/history/kernel.md section 13.
Co-Authored-By: Claude Opus 5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01VQ7Qx8E1q1M1bbCq8QLHS2
906 lines
49 KiB
Markdown
906 lines
49 KiB
Markdown
# Kernel history
|
|
|
|
Bugs that were expensive to find and whose causes are not visible from the code
|
|
that fixed them, plus a few subsystem write-ups that have nowhere better to live.
|
|
|
|
**Every entry here is a thing that looked like a different problem than it was.**
|
|
What each subsystem *is* today is [../architecture/](../architecture/); this is
|
|
only how it got that way.
|
|
|
|
| | |
|
|
|---|---|
|
|
| [1](#1-fixed-boot-didnt-reliably-reach-a-working-shell) | Boot did not reliably reach a working shell — ten bugs behind one symptom |
|
|
| [2](#2-naming-standardization) · [3](#3-coreutils) | Naming, and where the userland comes from. Not bugs. |
|
|
| [4](#4-two-stage-bootloader--psogm-splash) | The two-stage BIOS bootloader. **Since removed** — kept for the bugs. |
|
|
| [5](#5-at-syscalls-ignoredrejected-real-dirfds) | `*at()` ignored real dirfds, and `ls -l` hung |
|
|
| [6](#6-boot-speed) | Boot speed, in the loader |
|
|
| [7](#7-at-syscalls-real-signal-delivery-and-mksh-job-control) | Real signal delivery, and mksh's job control |
|
|
| [7b](#7b-the-loader-jumped-into-the-framebuffer-and-executed-pixels) | The loader jumped into the framebuffer and executed pixels |
|
|
| [8](#8-two-abi-assumptions-that-only-gcc-was-keeping-true) | Two ABI assumptions only GCC was keeping true |
|
|
| [9](#9-the-boot-looked-like-a-hobby-os-and-two-things-were-why) | The boot looked like a hobby OS |
|
|
| [10](#10-a-full-screen-program-typed-the-whole-session-into-the-shell) | A full-screen program typed the session into the shell |
|
|
| [11](#11-ps-and-top-and-why-they-never-worked) | `ps` and `top`, and why they never worked |
|
|
| [12](#12-a-test-program-crashed-at-random-and-had-been-typing-its-own-launch-command) | A program crashed at random, typing its own launch command |
|
|
|
|
The SMP bring-up bugs are not here — they are summarised in
|
|
[../architecture/boot.md](../architecture/boot.md#4-smp), because the lesson
|
|
(`__thread` is wrong for per-CPU data) is load-bearing on the current code
|
|
rather than merely historical.
|
|
|
|
> **Where the old design plan went.** Sections 1-6 of this file used to hold a
|
|
> "Segregated Kernel" design: a Ring 0 Alpha / Ring 0 Beta split with driver
|
|
> modules isolated by CR3 switching, from an `IDEA.txt` that no longer exists.
|
|
> None of it was ever implemented, and it is superseded by
|
|
> [../plan/schapi.md](../plan/schapi.md) — a macOS-shaped system answers driver isolation with
|
|
> userspace drivers and a personality boundary, not a bespoke in-kernel ring
|
|
> split. It also referenced a Zig toolchain that is now clang/LLVM. Removed
|
|
> rather than left to be mistaken for a plan.
|
|
|
|
---
|
|
|
|
## 1. Fixed: boot didn't reliably reach a working shell
|
|
|
|
Investigated 2026-07-05, before phase 1 started (predates this design, not
|
|
caused by it). Originally manifested as `ksh` (mksh) crashing on every
|
|
launch, apparently inside musl's mallocng allocator (`get_meta`,
|
|
`src/malloc/mallocng/meta.h`, deliberately executing `hlt` on detecting
|
|
"corrupted" heap metadata — a `trap 13` GPF at a fixed rip). It wasn't a
|
|
musl bug. Six real kernel bugs were found and fixed across three
|
|
investigation passes, and mksh boots and runs cleanly with all of them in
|
|
place — the calloc assertion was a symptom of real memory/pointer-handling
|
|
bugs downstream in the kernel, not anything musl or mallocng did wrong.
|
|
|
|
Fixed:
|
|
- `copyuvm()` (`kernel/arch/x86_64/vm.c`, used by `fork()`) never copied
|
|
`mmap()`-backed `proc->vma[]` regions into the child — only `[0, sz)`.
|
|
Fixed via new `copy_vma_range()`, called from `fork()` (`kernel/proc/proc.c`).
|
|
- `kmem.freelist` (`kernel/core/kalloc.c`) could get corrupted by a wild
|
|
write elsewhere and would silently hand back a bad pointer, panicking far
|
|
from the actual cause. Added a canary check (`check_run()`) at the top of
|
|
both `kalloc()`/`kfree()` so corruption panics immediately at the point
|
|
it's touched, with a clear message.
|
|
- No TLB invalidation existed anywhere except the full `lcr3` reload on
|
|
context switch — `mappages()`/`vm_unmap_range()` never called `invlpg`.
|
|
Fixed by adding `invlpg()` (`include/x86.h`) to both functions.
|
|
- **`MSR_STAR` was misconfigured** (`syscallinit()`, `kernel/arch/x86_64/vm.c`):
|
|
`SYSRETQ` computes the returned `cs`/`ss` as `STAR[63:48]+16`/`+8`, which
|
|
requires the *compat* 32-bit code selector (`SEG_UCODE32`) in that field —
|
|
the kernel was putting the real 64-bit `USER_CS` there instead. Every
|
|
`sysretq` silently loaded an invalid `cs` (`0x3b`, pointing at the TSS
|
|
descriptor)/`ss` pair; QEMU's TCG doesn't validate segment descriptors on
|
|
`SYSRET`, so this went unnoticed until a hardware interrupt forced a
|
|
strictly-validated `IRETQ` with that bogus `cs` still loaded, which
|
|
correctly `#GP`'d.
|
|
- `sys_mmap`'s non-`MAP_FIXED` path (`kernel/sys/sys_mem.c`) assigned a fixed
|
|
8MB virtual-address window per `vma[]` slot regardless of the requested
|
|
length. A single allocation over 8MB (e.g. `realloc()` growth past that
|
|
size) mapped straight into a neighboring live mapping and hit
|
|
`mappages()`'s `panic("remap")`. Replaced with a real bump allocator
|
|
(`proc->mmap_next`, `include/proc.h`), so every mapping gets its own
|
|
disjoint, exactly-sized range regardless of size.
|
|
- **`uva2ka()`** (`kernel/arch/x86_64/vm.c`) returned only the page-aligned
|
|
base address of a user pointer's page, silently dropping the in-page byte
|
|
offset. Direct callers (`sys_ioctl`'s `TIOCGPGRP`/`TCGETS`, `sys_getcwd`,
|
|
signal masks, `times()`, `sysinfo()`, ...) read/wrote near the wrong
|
|
address whenever the pointer wasn't page-aligned — i.e. almost always.
|
|
Fixed at the source so every caller benefits.
|
|
- **`fetchint`/`fetchaddr`/`fetchstr`/`argptr`** (`kernel/sys/syscall.c`)
|
|
rejected any address `>= proc->sz`, wrongly assuming every valid user
|
|
pointer lives in the heap. Stack addresses and `mmap()`'d buffers (used
|
|
constantly by real programs, e.g. path-resolution buffers) live above
|
|
`proc->sz` and were being rejected outright. Fixed to rely solely on
|
|
`uva2ka()`'s page-table validation.
|
|
|
|
Bringing in toybox (see "Coreutils" below) surfaced four more, all fixed:
|
|
- Linux syscall 58 (`vfork`) wasn't in the syscall-ABI translation table at
|
|
all (`kernel/sys/linux_abi.c`) — every external command spawn from a
|
|
program that prefers `vfork()` over `fork()` failed outright. Mapped to
|
|
the existing `fork()` (a fully correct, if slightly slower, substitute).
|
|
- `sys_stat`/`fstat`/`fstatat` (`kernel/sys/sys_fs.c`) filled in SchOS's
|
|
own native `struct stat` layout regardless of the caller — musl/toybox
|
|
parse a fixed Linux ABI byte layout instead, so `st_mode` was garbage and
|
|
tools like `ls` couldn't tell files from directories, or executables from
|
|
non-executables. Added `struct linux_stat` + `stati_linux()`, gated on
|
|
Linux-ABI mode (`proc->syscall_map`).
|
|
- `sys_open`/`sys_openat` required `omode == O_RDONLY` *exactly* to open a
|
|
directory, but `opendir()`-style calls legitimately OR in `O_DIRECTORY`/
|
|
`O_CLOEXEC` alongside it. Fixed to check just the access-mode bits
|
|
(`O_ACCMODE`, added to `include/fcntl.h`).
|
|
- `sys_getdents64` read one `struct dirent` (16 bytes) at a time — a full
|
|
`bmap()`+`bread()` per slot. Directories here are hash-indexed (see
|
|
`tree_search()`/`tree_expand()` below), so a directory with a few dozen
|
|
real entries can have a size in the hundreds of KB, nearly all empty
|
|
slots — this made listing such a directory look hung (it wasn't a
|
|
deadlock, just thousands of redundant single-slot disk reads). Rewrote it
|
|
to read a full block at a time and resolve each entry's type via
|
|
`iget(inum)` (exported from `fs.c`, it was `static`) instead of
|
|
re-searching the whole directory by name with `dirlookup()` for every
|
|
entry. That rewrite's first version introduced a **new** self-deadlock:
|
|
the "." entry's inode number equals the directory's own, and `iget()`
|
|
correctly hands back the *same, already-locked* `struct inode*` — calling
|
|
`ilock()` on it again sleeps forever on a lock the process already holds.
|
|
Fixed by special-casing `xde->inum == ip->inum` (we already know it's a
|
|
directory, no need to re-lock at all).
|
|
|
|
A synthetic stress test (interleaved malloc/free, realloc growth crossing
|
|
`MMAP_THRESHOLD`, calloc, large allocations) runs to completion with zero
|
|
crashes, and mksh now boots straight to an interactive prompt, runs external
|
|
programs, pipes, and `ls`/`mkdir`/`grep` without issue.
|
|
|
|
## 2. Naming standardization
|
|
|
|
SchOS standardizes on exactly one name per role, regardless of the
|
|
underlying implementation: the shell is always installed and exec'd as
|
|
`/bin/sh` (currently mksh, built from `ports/mksh/`), and PID 1 is always
|
|
`/bin/init`. `cmd/init/main.c`'s exec loop only ever tries `/bin/sh` — no
|
|
ksh/mksh/dash/zsh/other-name fallbacks. dash was tried first
|
|
(BSD-licensed, minimal) while the boot crash above was still open, then
|
|
replaced with mksh once the underlying kernel bugs were fixed and dash's
|
|
lack of interactive features (history, completion, line editing) made it
|
|
feel unusably bare for day-to-day use; the dash port's source tree was left in
|
|
place rather than deleted, in case it's useful again (e.g. as a `/bin/sh`
|
|
POSIX-strict target distinct from an interactive login shell).
|
|
|
|
## 3. Coreutils
|
|
|
|
`ports/toybox/` (0BSD-licensed, https://landley.net/toybox/) provides `ls`,
|
|
`cat`, `cp`, `mv`, `rm`, `mkdir`, `grep`, `sed`, `find`, `chmod`, `date`,
|
|
`sort`, and more — see the `APPLETS` list in `ports/toybox/Makefile`. It builds
|
|
as a single multicall binary; `tools/mkfs.c` doesn't understand symlinks or
|
|
hardlink dedup, so `ports/toybox/Makefile`'s `install` target copies the built
|
|
binary once per applet name into `sysroot/bin/` rather than symlinking
|
|
(costs disk space per applet — currently ~44MB total — instead of one
|
|
shared inode, but needed no mkfs changes).
|
|
|
|
## 4. Two-stage bootloader + PSOGM splash
|
|
|
|
> **This describes the BIOS loader, which no longer exists** — see
|
|
> [`boot/README.md`](../../boot/README.md) for why it was removed and what
|
|
> replaced it. The section is kept because four of the bugs in it are about
|
|
> things that are still true: extended scancodes, register hand-off across a
|
|
> mode switch, and layout constants that several artifacts must agree on.
|
|
|
|
`boot/` used to be a single BIOS boot sector doing everything (VBE mode
|
|
set, A20, GDT, protected-mode switch, multiboot kernel scan/load) — silent,
|
|
and packed to within 4 bytes of the hard 510-byte MBR limit, so there was
|
|
no room to add so much as a print statement.
|
|
|
|
Split into two stages, the standard way real bootloaders solve this:
|
|
|
|
- **Stage 1** (`boot/bios/bootasm.S`, still the literal MBR sector, still
|
|
≤510 bytes) does exactly one thing: raw IDE PIO (LBA28) reads
|
|
`STAGE2_SECTORS` (16) sectors starting at disk sector 1 into memory at
|
|
`0x7E00`, then jumps there. Nothing else fits, nothing else is needed.
|
|
(Caught a real bug writing this: `outb $0x1F7,%al`-style immediates
|
|
silently truncate to 8 bits — ports 0x1F2-0x1F7 are all > 0xFF and need
|
|
the `%dx` register form, or you're hitting the wrong I/O port entirely.)
|
|
- **Stage 2** (`boot/bios/stage2.S` + `boot/bios/stage2main.c`, loaded at `0x7E00`,
|
|
occupies disk sectors 1-16) does everything stage 1 used to skip straight
|
|
to, plus a boot banner (BIOS teletype, real mode, before the VBE mode
|
|
switch — note this only reaches the video device, not serial, so it
|
|
won't show up in a `-serial file:...`-captured log), a splash screen, a
|
|
real-time loading bar, and an F8 boot menu (all described below). Not
|
|
size-constrained the same way as stage 1 — `tools/padstage2.pl` zero-pads
|
|
it out to a fixed `STAGE2_SECTORS*512` (8192) bytes so the kernel's
|
|
on-disk starting sector stays predictable regardless of stage2's actual
|
|
compiled size, and errors out (like `tools/sign.pl` does for stage 1) if
|
|
it ever grows past that budget instead of silently corrupting the layout.
|
|
|
|
The kernel now starts at disk sector 17 instead of 1 (`schos.img`'s `dd
|
|
... seek=17` in the root `Makefile`, and the equivalent `+(1+STAGE2_SECTORS)`
|
|
in `stage2main.c`'s `readseg()` — all three places that encode
|
|
`STAGE2_SECTORS` have to agree, or the kernel won't be found on disk at
|
|
all). `boot/bootmain.c` no longer exists; its logic was split between
|
|
`stage2.S` (real-mode/protected-mode setup) and `stage2main.c` (splash +
|
|
the unchanged multiboot-header-scan-and-load logic).
|
|
|
|
The VBE mode info block itself lives at `0x30000`, not the classic
|
|
single-stage bootloader's `0x9000` — stage2's own code now runs from
|
|
`0x7E00` up to nearly `0x9000` once the boot-menu/progress-bar logic is
|
|
included, and a block at `0x9000` gets partially overwritten by stage2's
|
|
own tail end (found this the hard way: the kernel's `LFB:` cprintf started
|
|
reporting a different wrong value on every boot, because it was reading
|
|
whatever stage2 code/data now happened to occupy that address).
|
|
`kernel/dev/vga.c`'s `vga_init()` has to agree on `0x30000` too, since it
|
|
independently re-reads mode fields from the same block.
|
|
|
|
Splash/progress bar/boot menu rendering is a small standalone pixel
|
|
renderer in `stage2main.c` (not the kernel's `vga.c` — paging isn't set up
|
|
yet, so the LFB physical address from the VBE block is used as a plain
|
|
pointer) reusing the kernel's own font data (`include/font.h`) directly.
|
|
It fills the framebuffer with PSOGM's purple (matching
|
|
`kernel/core/console.c`'s panic screen) and draws "SCHOS" centered, then:
|
|
|
|
- **Real-time loading bar**: `readsect()` (in `stage2main.c`, not the
|
|
kernel) calls `progress_tick()` after every 512-byte disk read, updating
|
|
an actual pixel-filled bar against the real total byte count — first a
|
|
small one while scanning for the multiboot header, then a second,
|
|
properly-sized one once the header's found and the true kernel size is
|
|
known, labeled "Loading kernel...". Not simulated/timed — it reflects
|
|
real bytes read off disk.
|
|
- **F8 boot menu**: `wait_for_f8()` busy-polls the keyboard controller
|
|
(`inb(0x64)`/`inb(0x60)`, raw scancodes — real-mode BIOS keyboard calls
|
|
aren't available once we're in protected mode) for about a second after
|
|
the splash appears. F8 (scancode `0x42`) drops into `boot_menu()`: three
|
|
options (boot normal, boot verbose, reboot to firmware setup) navigated
|
|
with up/down arrows and Enter, plus a "detected drives" panel from
|
|
`ata_present()` — a standard floating-bus presence check (select the
|
|
drive, write a pattern to two registers, read it back) on the primary
|
|
IDE channel's master/slave (the only channel this project ever actually
|
|
puts drives on; QEMU's IDE emulation answers the same test
|
|
"successfully" on the unpopulated secondary channel too, so that channel
|
|
isn't shown — it'd just be confidently wrong). "Reboot to firmware
|
|
setup" pulses the keyboard controller's reset line
|
|
(`outb(0x64, 0xFE)`, same technique as `kernel/sys/sys_proc.c`'s
|
|
`sys_reboot()`); a real bootloader can't jump into BIOS/UEFI setup
|
|
directly, so this is the closest honest equivalent — it gives the user
|
|
a fresh POST during which their firmware's own setup-menu key works.
|
|
- **Verbose boot**: picking "Boot SchOS (verbose)" writes a flag byte to
|
|
`BOOT_VERBOSE_FLAG_ADDR` (`VBE_INFO_ADDR + 0x100`, i.e. just past the VBE
|
|
block) before jumping to the kernel. `kernel/core/main.c`'s `kmain()`
|
|
reads it into a global `boot_verbose` as its very first action and, if
|
|
set, prints a line after every subsystem init call
|
|
(`uartearlyinit`, `kinit1`, ..., `sinit`) — real per-step boot logging,
|
|
not a canned message.
|
|
|
|
Two bugs worth remembering if this code gets touched again:
|
|
|
|
- **Keyboard extended-scancode handling**: `0xE0` (the prefix byte for
|
|
arrow keys and friends) also has bit 7 set, the same bit used to detect
|
|
key-*release* ("break") codes. A naive "skip anything with bit 7 set,
|
|
then check for 0xE0" loop skips the 0xE0 byte itself before ever testing
|
|
for it, so extended keys silently never register. The 0xE0 check has to
|
|
come before the break-code check, not after.
|
|
- **The kernel entry call is not a real C function call.** Both the
|
|
original single-stage `bootmain()` and the new `stage2main()` do
|
|
`((void(*)(uint32))entry)(fbaddr)` — normal cdecl, which pushes `fbaddr`
|
|
on the stack. But `kernel/arch/x86_64/entry.S`'s `mboot_entry` reads its
|
|
framebuffer argument out of **EAX** (a multiboot-style raw-register
|
|
handoff, then `mov %eax,%ebp` / `mov %ebp,%ebx` / `mov %rbx,%rdi` carries
|
|
it through the 32→64-bit transition into `kmain()`'s first argument).
|
|
The cdecl call never puts anything in EAX — it "worked" for years purely
|
|
because simple bootmain.c code happened, as a side effect of its own
|
|
codegen, to leave the right value sitting in EAX right up until the
|
|
`call` instruction. Adding the splash/menu/progress-bar code changed
|
|
that codegen and broke it silently: the kernel booted fine and reported
|
|
a plausible-looking but wrong `LFB:` address (garbage left over in EAX
|
|
from unrelated prior code, different on every boot). Fixed by pinning
|
|
the argument down explicitly with `asm volatile("jmp *%0" : : "r"(entry),
|
|
"a"(fbaddr))` instead of hoping the compiler's register allocation
|
|
cooperates. If this code moves around again, re-verify with a screendump
|
|
taken *immediately* before the jump compared against the kernel's own
|
|
`LFB:` log line — they silently diverging is exactly this bug.
|
|
|
|
## 5. `*at()` syscalls ignored/rejected real dirfds
|
|
|
|
`ls -l`/`ls -lR` (and, by the same code path, `find`/`du`/anything using
|
|
toybox's `lib/dirtree.c`) would hang on `ls -l` and either hang or silently
|
|
misbehave on recursive listings. Root cause: `kernel/sys/sys_fs.c`'s
|
|
`*at()` syscalls (`openat`, `fstatat`, `unlinkat`, `renameat`, `linkat`,
|
|
`symlinkat`, `mkdirat`, `mknodat`, `readlinkat`, `faccessat`) only handled
|
|
two cases for their `dirfd` argument — `AT_FDCWD` (resolve relative to
|
|
`proc->cwd`) or an absolute path (resolve from root, ignoring `dirfd`
|
|
entirely). A **real** dirfd with a **relative** path — e.g.
|
|
`fstatat(open("/bin", O_RDONLY), "ls", &st, ...)`, the standard, efficient
|
|
way any directory-tree walker avoids rebuilding full path strings for every
|
|
entry — was either rejected outright (`fstatat`, `unlinkat`, ...) or
|
|
silently ignored in favor of `proc->cwd` (`openat`, which never checked at
|
|
all — worse than rejecting, since it can silently resolve the *wrong*
|
|
file if cwd happens to contain a same-named entry).
|
|
|
|
Fixed by adding a real dirfd-relative path resolver: `kernel/fs/fs.c`'s
|
|
`namex()` was refactored into `namex_from(struct inode *start, ...)`,
|
|
parameterizing what used to be a hardcoded `idup(proc->cwd)`, with two new
|
|
exported entry points, `nameifrom()`/`nameiparentfrom()`. `sys_fs.c` gained
|
|
`at_dir(dirfd)` (resolves `AT_FDCWD` or a real fd to a starting inode) and
|
|
`at_namei()`/`at_nameiparent()` built on top of it, plus a `createat()`
|
|
(parameterizing `create()`'s hardcoded `nameiparent()` call the same way).
|
|
Every `*at()` syscall now uses these instead of its own inline
|
|
absolute-path/`AT_FDCWD`-only check.
|
|
|
|
**Known follow-on issue, not yet root-caused**: heavy `ls`/`ls -lR` use
|
|
across many commands in one long-running shell session can eventually make
|
|
a *later*, unrelated directory hang (reproduced with `ls -lR /var` after
|
|
~10 prior commands in the same session; the identical command succeeds
|
|
immediately on a fresh boot). Not an inode-table or file-table exhaustion
|
|
— both `iget()` and `filealloc()` fail cleanly (panic / return 0
|
|
respectively) when full, and neither fired. Smells like a lock or
|
|
reference-count leak somewhere in the *at() paths above, or in toybox's
|
|
own fd handling, that only manifests after enough accumulated opens/closes.
|
|
Next step: instrument `itable`/`ftable` occupancy counts and watch them
|
|
across a long `ls`-heavy session to see what's actually climbing.
|
|
|
|
## 6. Boot speed
|
|
|
|
Two cheap, real wins in `boot/bios/stage2main.c`, no functional changes:
|
|
|
|
- `progress_tick()` (called once per 512-byte disk sector) used to trigger
|
|
a full progress-bar redraw — border plus fill, a few thousand pixel
|
|
writes — on *every* sector. For the ~330KB kernel image that's ~650 full
|
|
redraws (the multiboot-header-scan phase adds another ~32) for a bar
|
|
that only has 101 visually distinct states (0-100%). Split into
|
|
`progress_border()` (drawn once, in `progress_start()`, since the border
|
|
never changes) and `progress_fill()`, and `progress_tick()` now skips the
|
|
redraw entirely unless the percentage actually changed. This was the
|
|
single biggest chunk of the bootloader's own wall-clock time.
|
|
- `fill_rect()` (the full-screen splash fill, 480,000 pixels at 800x600,
|
|
run at least twice per boot) used to call `draw_pixel()` per pixel, which
|
|
recomputes `g_fb + y*stride + x*4` from scratch every time. Now computes
|
|
each row's base pointer once and indexes into it.
|
|
- The F8 boot-menu wait was shortened from ~1s (`5000000` busy-loop
|
|
iterations) to ~0.6s (`3000000`) — flat overhead on every boot whether
|
|
or not the menu is wanted, so it's the most direct lever available
|
|
without giving up the feature entirely.
|
|
|
|
## 7. `*at()` syscalls, real signal delivery, and mksh job control
|
|
|
|
> **Resolved since this was written.** Process groups and sessions are real
|
|
> (`pgid`/`sid` in `struct proc`, `setpgid`/`setsid`/`getpgid`/`getsid`, and
|
|
> signal delivery to a whole group), which was the first of the three suspects
|
|
> listed at the end. mksh's job control works. The investigation is kept in full
|
|
> because the signal-delivery mechanism described below is still exactly how the
|
|
> kernel does it, and because the reasoning about *why SIGCHLD was left enabled
|
|
> while broken* is the transferable part.
|
|
|
|
`ls -l`/`ls -la` hanging outright turned out to be the same root cause
|
|
described in §5 above (dirfd-relative path resolution) — fixed
|
|
and verified extensively (plain `ls`, `ls -l`, `ls -la`, `ls -lR`, piped
|
|
output, all confirmed working repeatedly).
|
|
|
|
A *second*, deeper issue was found investigating a follow-up report
|
|
(`cd` with no `HOME` set, then `cd var`, then `ls` hanging): mksh's
|
|
interactive job control (`ports/mksh (mksh R59c source): jobs.c`) blocks in
|
|
`sigsuspend()` waiting for `SIGCHLD`, expecting its own handler
|
|
(`j_sigchld()`) to run, reap the child via `waitpid(-1, &status, WNOHANG)`,
|
|
and update its internal job-state tracking. This kernel had **no real
|
|
signal delivery at all** — `sys_rt_sigaction()` was a no-op stub, so no
|
|
handler was ever invoked for anything, and `sigsuspend()` just slept out
|
|
one tick and returned `-EINTR` unconditionally. mksh's wait loop had no
|
|
way to ever learn the child had exited, hanging forever.
|
|
|
|
Real signal delivery was implemented from scratch:
|
|
- `struct proc` (`include/proc.h`) gained `sig_handler[32]`/
|
|
`sig_restorer[32]` (populated by `sys_rt_sigaction()`,
|
|
`kernel/sys/sys_sig.c`), `saved_sigtf` (stashed pre-signal trapframe),
|
|
and `in_signal` (re-entrancy guard). `allocproc()` zeroes these for a
|
|
freshly claimed ptable slot (they weren't before — a reused slot
|
|
silently inherited a previous, unrelated process's handler addresses,
|
|
which crashed the *next* process to occupy that slot the moment
|
|
anything tried to delivver a signal to it). `fork()` copies handler/
|
|
restorer/mask from parent to child (POSIX semantics) but not pending
|
|
signals.
|
|
- `kernel/proc/proc.c`'s `exit()` sets `SIGCHLD` pending on the parent.
|
|
- `kernel/sys/syscall.c`'s `syscall()` calls `deliver_signals(tf)` in its
|
|
tail, right before returning to user mode: if there's a pending,
|
|
unblocked signal with a registered handler, it redirects the trapframe
|
|
to jump to the handler (`rdi`=signal number per SysV ABI, `rip`=handler)
|
|
instead of resuming the interrupted code, having first stashed the
|
|
original trapframe in `proc->saved_sigtf`.
|
|
- The return address is **not** `sig_restorer[sig]` — checked, `SA_RESTORER`
|
|
is not defined anywhere in this musl build, so `sigaction()` never fills
|
|
in a restorer; it's always 0, and pushing 0 as a return address crashes
|
|
with `rip=0` the instant the handler function returns. Instead,
|
|
`deliver_signals()` injects a tiny 7-byte trampoline (`mov eax,15;
|
|
syscall` — `rt_sigreturn`) directly onto the user's own stack, below the
|
|
current `rsp` (clear of the SysV red zone), and points the return
|
|
address at that — the standard technique for when the C library doesn't
|
|
supply its own restorer.
|
|
- `sys_rt_sigreturn()` restores `*proc->tf` from `proc->saved_sigtf`,
|
|
clearing `in_signal`.
|
|
|
|
**A real bug found and fixed along the way**: the first version of
|
|
`sys_rt_sigaction()` translated the user's `struct sigaction` pointer
|
|
*once* via `uva2ka()` and then did a bulk `memset`+copy across the whole
|
|
~152-byte structure. `uva2ka()` only guarantees the *page containing that
|
|
address* is mapped, not everything up to some further offset — when the
|
|
user's pointer landed close enough to a page boundary, the write ran past
|
|
the mapped page into whatever physical page happened to be next in kernel
|
|
address space (P2V is a flat offset, so "next page" there has nothing to
|
|
do with the user's actual next page), corrupting unrelated kernel memory.
|
|
This crashed every freshly `exec`'d `/bin/sh` almost immediately, since
|
|
mksh calls `sigaction()` during its own startup. Fixed by only touching
|
|
the two individual 8-byte fields actually needed (`sa_handler` at offset
|
|
0, `sa_restorer` at offset 144), each through its own `uva2ka()` call.
|
|
|
|
`sys_waitpid()`/`sys_wait4()` (`kernel/sys/sys_proc.c`) were also rewritten
|
|
on top of a new `waitpid(pid, status, options)` in `kernel/proc/proc.c`
|
|
(refactored from the old any-child-only, always-blocking `wait()`, which
|
|
is now just `waitpid(-1, 0, 0)`): a specific `pid` (not just "any child"),
|
|
`WNOHANG` (return 0 immediately instead of blocking), and — importantly —
|
|
a genuinely optional status pointer. The old code ran a NULL status
|
|
pointer through `argptr()`, which rejects NULL/unmapped addresses outright
|
|
(page 0 is deliberately unmapped) — but `waitpid(pid, NULL, WNOHANG)` is
|
|
completely standard, and is exactly what mksh's job control does.
|
|
|
|
**Status: signal delivery mechanically works** — verified directly (a
|
|
debug build logged the handler being invoked with the correct trapframe
|
|
and `sys_rt_sigreturn()` restoring cleanly, no crash, repeatable). **mksh's
|
|
job control still doesn't reliably progress afterward**, including for
|
|
plain non-piped foreground commands, not just the original piped-into-head
|
|
case. Root cause not yet isolated. Leading suspects, in order of
|
|
likelihood:
|
|
- `sys_setpgid()`/`sys_getpgid()` are no-op stubs (`kernel/sys/sys_proc.c`)
|
|
— `j_sigchld()` (`ports/mksh (mksh R59c source): jobs.c:1344-1348`) has an early-out
|
|
keyed on `j->ppid == procpid`, which may never resolve the way mksh
|
|
expects without real process-group tracking.
|
|
- `getrusage(RUSAGE_CHILDREN, ...)` — called at the top of `j_sigchld()` —
|
|
isn't verified to behave sanely under this kernel's implementation
|
|
(`kernel/sys/sys_proc.c`'s `sys_getrusage()` only fills in `ru_utime`
|
|
from the *calling* process's own tick count, not accumulated child
|
|
time; `RUSAGE_CHILDREN` isn't distinguished from `RUSAGE_SELF` at all).
|
|
- Possibly something in how `j_sigchld()` matches a reaped `pid` against
|
|
its own `job_list` (`ports/mksh (mksh R59c source): jobs.c:1372-1385`) silently fails
|
|
to find the job for reasons not yet traced.
|
|
|
|
This was left here deliberately rather than continuing to iterate blind:
|
|
SIGCHLD delivery is left **enabled** (`kernel/proc/proc.c`'s `exit()`)
|
|
since disabling it guarantees zero chance of mksh's wait loop ever exiting,
|
|
whereas leaving it on at least gives the cases that don't hit the
|
|
still-unknown remaining gap a chance to work. Next session should start
|
|
by instrumenting `j_sigchld()`'s own control flow (or strace-equivalent
|
|
logging in the kernel around `sys_setpgid`/`sys_getrusage`/`sys_waitpid`
|
|
calls specifically while reproducing `cd; cd var; ls` or even simpler
|
|
`ls -l /bin` followed by a second command) rather than re-deriving the
|
|
signal-delivery mechanism, which is now confirmed solid.
|
|
|
|
---
|
|
|
|
## 7b. The loader jumped into the framebuffer and executed pixels
|
|
|
|
The same bug as section 4, in the other loader, found five years later by a
|
|
compiler upgrade. Worth its own entry because it is the *third* time a register
|
|
the code depends on but never asks for has broken this project.
|
|
|
|
**Symptom.** Boot died immediately after `schos: exiting boot services` with a
|
|
KVM internal error and a register dump:
|
|
|
|
RIP=00000000801a5dc5 RBX=0000000080000000
|
|
Code=13 0e 0c 00 13 0e 0c 00 ... dc d5 d1 00 dc <d5> d1 00
|
|
|
|
`0x80000000` is the framebuffer. `0x0C0E13` is `SCH_BG` and `0xD1D5DC` is a grey
|
|
from the splash's metal gradient. So `RIP` was *inside video memory* and the
|
|
bytes being executed were the boot logo. The machine was executing the picture
|
|
of itself starting up.
|
|
|
|
**Cause.** `boot/uefi/main.c`'s hand-off to the kernel:
|
|
|
|
"mov %0, %%cr3\n\t"
|
|
"mov %1, %%rbx\n\t" <- writes rbx
|
|
"jmp *%2\n\t"
|
|
: : "r"(PML4_ADDR), "r"(fb), "r"(entry)
|
|
: "memory"); <- rbx NOT declared clobbered
|
|
|
|
Nothing told the compiler rbx was written, so it was free to allocate an
|
|
*input* there. clang 21 allocated `entry`:
|
|
|
|
movq %rax, %cr3
|
|
movq %rcx, %rbx <- the framebuffer, into rbx
|
|
jmpq *%rbx <- %2 was rbx; it now holds the framebuffer
|
|
|
|
The fix is `"rbx"` in the clobber list, which forbids the allocation. Confirmed
|
|
by reading the generated assembly before and after -- `jmpq *%rbx` became
|
|
`jmpq *%r14`.
|
|
|
|
**Why it appeared now.** It did not. It had been latent since the loader was
|
|
written and worked only because every compiler that had built it happened to
|
|
choose a different register. It surfaced the first time the binary was relinked
|
|
with a different clang.
|
|
|
|
That is the whole lesson, and it is identical to section 4's: **a register the
|
|
code depends on, that nothing in the source actually asks for, is not a
|
|
dependency -- it is a coincidence with a long half-life.** Section 4 was the
|
|
BIOS loader passing the framebuffer in EAX by luck; section 8 was `%fs:0` used
|
|
as scratch when the ABI reserves it; this is an asm block writing a register it
|
|
did not declare.
|
|
|
|
Reading the *generated* assembly is what settles all three, and it takes a
|
|
minute:
|
|
|
|
clang $(UEFI_CFLAGS) -S -o - boot/uefi/main.c | grep -B3 'jmpq.*\*'
|
|
|
|
**A second failure sat underneath it and is worth its own note.** The loader had
|
|
been stale for half a day -- the Makefile rule for `BOOTX64.EFI` did not list
|
|
`logo.h`, `theme.h` or `font.h`, all of which `boot/common/ui.c` includes, so a
|
|
new logo never rebuilt it. The splash kept drawing an old mask while `make`
|
|
reported nothing to do. Fixing that dependency is what caused the relink, which
|
|
is what exposed the register bug. A stale artifact hides the bug that the fresh
|
|
one reveals.
|
|
|
|
---
|
|
|
|
## 8. Two ABI assumptions that only GCC was keeping true
|
|
|
|
Found when the build moved from GCC-in-WSL to clang-on-Windows. Neither is a
|
|
clang bug; both are places where the code relied on GCC doing something it
|
|
never promised, and both had been latent for years.
|
|
|
|
### `%fs:0` was being used as scratch — it is the TCB self-pointer
|
|
|
|
`syscall_entry` (`kernel/arch/x86_64/trapasm.S`) stashed `%rax` at `%fs:(0)`
|
|
while it fetched `proc` to find the kernel stack. The comment called it a
|
|
"per-CPU scratch slot". It is not: the x86-64 TLS ABI reserves the word *at*
|
|
the thread pointer to hold the thread pointer, and a compiler may read it to
|
|
materialise the TP before applying a variable's offset.
|
|
|
|
GCC compiles `__thread` access to a direct `%fs:-8` segment reference and never
|
|
reads that word, so the clobber was invisible. clang at `-O0` emits
|
|
`movq %fs:0, %rax; addq $-8, %rax; (%rax)` — reading back the syscall number
|
|
this code had just stored. The first process's first syscall is
|
|
`exec` (7), so `proc` resolved to address `7 - 8 = -1` and the kernel
|
|
page-faulted recursively until the stack was gone.
|
|
|
|
Fixed by moving the scratch to `%fs:(8)`. Positive offsets are safe: the TLS
|
|
block lives at negative offsets and `seginit` places the thread pointer 2048
|
|
bytes into a 4096-byte page.
|
|
|
|
**How it was found** is the part worth copying next time. Three rounds of
|
|
`cprintf` narrowed it to "the word is right at `mpmain`, wrong by the first
|
|
trap" and no further — the instrumentation perturbed the timing enough to move
|
|
the symptom. A hardware watchpoint through QEMU's gdb stub named the
|
|
instruction on the first run:
|
|
|
|
```
|
|
qemu ... -S -gdb tcp::26000
|
|
gdb -batch -x tcp.gdb # hbreak mpmain; watch *(unsigned long*)kernel_fs_base
|
|
```
|
|
|
|
`seginit` also now writes the self-pointer, which it never did. That is ABI
|
|
-correct regardless and costs one store per CPU.
|
|
|
|
### `_start` read incoming registers with `register ... asm("rdi")`
|
|
|
|
`lib/glue.c` captured `argc`/`argv` from `%rdi`/`%rsi` using GCC local register
|
|
variables. Both compilers only guarantee that binding for inline-asm operands;
|
|
using it to pick up an incoming argument is undefined. clang ignored it and
|
|
read two uninitialised stack slots:
|
|
|
|
```asm
|
|
movl -0x4(%rbp), %eax # should have been %edi
|
|
movq -0x10(%rbp), %rax # should have been %rsi
|
|
```
|
|
|
|
Every program still ran. `init`, `shmtest` and `socktest` take no arguments and
|
|
passed their entire suites; the only symptom in the whole system was
|
|
`inputtest -n 6` ignoring its limit. Moved to `lib/start.S`, where reading
|
|
incoming registers is expressible and correct — `exec` passes argc/argv in the
|
|
SysV argument registers already, so `_start` calls `main` without touching
|
|
them.
|
|
|
|
---
|
|
|
|
## 9. The boot looked like a hobby OS, and two things were why
|
|
|
|
Not a bug — a design problem, fixed by looking at a screenshot instead of the
|
|
code.
|
|
|
|
**The display was the kernel log.** Boot printed `pci: 6 devices` and
|
|
`vga: display controller 1234:1111, aperture fd000000 (16 MB)` to the screen
|
|
the user is looking at. That single fact is most of what separates a hobby
|
|
project from a product; every shipping system puts that behind a flag.
|
|
|
|
`cons_serial_only` already existed for panic, so the fix was to start it *set*.
|
|
Everything still goes out the UART — which is where `tools/windows/bootcheck.ps1` reads
|
|
it from, so all five suites kept passing untouched — and `console_takeover()`
|
|
clears it on the first `exec()`, the moment userspace genuinely starts.
|
|
`vga_init` no longer clears the screen, so the splash survives the whole of
|
|
boot rather than being wiped a few hundred milliseconds in.
|
|
|
|
**There were three unrelated designs.** The splash was deep purple with gold
|
|
text, deliberately matching the *panic* screen. The console was cream with
|
|
near-black text. So a healthy boot was dressed as a crash, then abruptly
|
|
became an amber terminal. `include/theme.h` is now the one palette, and the
|
|
rule is: **normal states are calm and dark; only failure is loud.** PSOGM keeps
|
|
the purple entirely to itself, which is what makes it mean something.
|
|
|
|
The splash copy went from "SchOS Boot Manager / version 1.0 / Memory: 1023 MB
|
|
/ Press F8 for boot menu..." to the product name, a rule in the accent colour,
|
|
and the one hint that is actionable — moved to the bottom, where a hint
|
|
belongs. No shipping OS names its bootloader on the splash.
|
|
|
|
### Three latent bugs it flushed out
|
|
|
|
Retheming meant `stage2main.c` included `types.h` properly for the first time,
|
|
and the 32-bit build stopped compiling:
|
|
|
|
- `_Static_assert(sizeof(uint64) == 8)` fired. `uint64` was `unsigned long`,
|
|
which is **4 bytes** in the `-m32` loader — the file even carried a local
|
|
`e820_u64` workaround with a comment saying so. Now conditioned on
|
|
`__SIZEOF_LONG__` rather than on the platform, which covers LP64, LLP64 *and*
|
|
ILP32 correctly.
|
|
- `x86.h`'s `stosq` and `xchg` use `rep stosq` and `xchgq`, which do not exist
|
|
in 32-bit mode. They only ever compiled because `uint64` was silently
|
|
narrowed. Now behind `#ifdef __x86_64__`.
|
|
- The progress bar computed `(uint64)done * 100 / total`, a 64-bit divide that
|
|
needs libgcc's `__udivdi3` — which a freestanding loader does not link. Now
|
|
scaled to KiB and done in 32 bits.
|
|
|
|
All three had been sitting in a bootloader that worked fine, waiting for
|
|
someone to make `uint64` mean what it says.
|
|
|
|
---
|
|
|
|
## 10. A full-screen program typed the whole session into the shell
|
|
|
|
Keys reached `/dev/input/event0` **and** the tty line discipline at the same
|
|
time. That is correct for two consumers of one keyboard and completely wrong
|
|
for a full-screen program: while it had the display, the shell behind it was
|
|
quietly accumulating every keystroke, and the first Enter afterwards ran
|
|
whatever had piled up. Arrow keys arrived as CP437 glyphs on the console for
|
|
good measure.
|
|
|
|
The fix is the standard one and it is a *primitive*, not a patch: an exclusive
|
|
grab, `EVIOCGRAB`, with Linux's ioctl number. While a device is grabbed its
|
|
events still flow to `/dev/input/eventN` but both keyboard drivers withhold the
|
|
decoded character from the console.
|
|
|
|
Three details that matter more than the feature:
|
|
|
|
- **The grab is released by the devsw `close` hook**, not by the program. A
|
|
program that grabs the keyboard and then crashes would otherwise leave the
|
|
console permanently deaf, with no way to type the command that fixes it.
|
|
- **Modifier state is still tracked while grabbed** (`kbdgetc` keeps updating
|
|
shift/caps and only skips the character). Otherwise releasing the grab would
|
|
hand the line discipline a stuck Shift.
|
|
- **The USB path updates `prev[]` before returning**, or the next report would
|
|
look like every held key had just been pressed again.
|
|
|
|
It is also exactly what Schcom will need, which is why it lives in the input
|
|
layer rather than in any one client.
|
|
|
|
### The near-miss worth remembering
|
|
|
|
The first attempt appeared to work: the harness passed, every assertion green.
|
|
It had not worked at all — the ioctl call was never inserted into the client
|
|
source, because a scripted string replacement silently failed to match. The
|
|
`grep` that should have caught it printed three hits (a comment, a `#define`,
|
|
and the *release* call) and was read as confirmation without counting what
|
|
they were.
|
|
|
|
What actually caught it was reading the transcript rather than the verdict:
|
|
four bare `#` prompts after quitting, which is precisely the symptom the change
|
|
was supposed to remove. `input_grab()` now announces itself, so "did the grab
|
|
happen" is never again a thing anyone has to infer.
|
|
|
|
---
|
|
|
|
## 11. `ps` and `top`, and why they never worked
|
|
|
|
/proc was a set of character devices: init ran `mknod("/proc/uptime", 6, 2)` and
|
|
friends, so every file was a real inode on the root filesystem with a
|
|
major/minor behind it. That is fine for a fixed list and cannot work at all for
|
|
the thing /proc is mostly for -- one directory per process. You cannot mknod a
|
|
directory for a process that does not exist yet and will be gone in a minute.
|
|
`ps` calls `dirtree_flagread("/proc")`, got a listing with no numbers in it, and
|
|
reported nothing. It was never a `ps` problem.
|
|
|
|
So /proc is now a real filesystem behind the same `struct fs_ops` vtable SchFS
|
|
uses (`kernel/fs/procfs.c`, `PROCFS_DEV`), mounted by init with
|
|
`mount("proc", "/proc", "proc", ...)`. Nothing is stored: directory listings
|
|
are generated from the process table when asked, file contents when read.
|
|
|
|
Three things worth keeping in mind:
|
|
|
|
- **The split is deliberate.** `kernel/fs/procfs.c` owns the *namespace* (what
|
|
exists); `kernel/dev/procfs.c` keeps the *generators* (what the global files
|
|
say). They change for different reasons, so `proc_gen_global()` is the only
|
|
thing that crosses between them.
|
|
- **procfs never touches ptable.** `proc_snapshot()` copies what is needed out
|
|
from under the lock, so a process that exits between the readdir that listed
|
|
it and the open that reads it produces a stale line rather than a
|
|
use-after-free.
|
|
- **Sizes are reported as zero**, exactly as Linux does. A synthetic file has
|
|
no length until it is generated, and generating every one on every `stat()`
|
|
to fill in a number almost nothing reads would be absurd.
|
|
|
|
### What the suite caught
|
|
|
|
Marking every procfs inode read-only broke `echo s > /proc/sysrq`, and three
|
|
USB checks failed on it within a minute of the change -- they drive the disk
|
|
through sysrq. /proc is read-only *except* sysrq, which is the one deliberate
|
|
write target, and the code now says so in one place.
|
|
|
|
### Still not right
|
|
|
|
`ps -o comm` prints `[init]` rather than `init`. That field comes from
|
|
`/proc/<pid>/exe`, which Linux makes a **symlink** and toybox `readlink()`s;
|
|
ours is a regular file, so the readlink fails and toybox brackets the name as
|
|
it would for a kernel thread. Default `ps` and `top` output are unaffected.
|
|
Fixing it needs symlink support in procfs, which belongs with the rest of the
|
|
VFS work rather than as a one-off.
|
|
|
|
---
|
|
|
|
## 12. A test program crashed at random, and had been typing its own launch command
|
|
|
|
Symptom: a full-screen framebuffer program, launched with arguments, worked
|
|
four times and then died with
|
|
|
|
pid 9 <prog>: trap 14 err 4 on cpu 0 rip 0x2269be addr 0x18--kill proc
|
|
|
|
`err 4` is a user-mode read of a non-present page and `addr 0x18` is a null
|
|
pointer at offset 24. `llvm-nm` put `rip` inside the routine that opens the
|
|
program's overlay view, which dereferences a pointer the program only fills in
|
|
once a level is loaded -- at offset 0x18 on x86-64, because the three 64-bit
|
|
words of a base struct sit in front of it. So the program had been asked to open
|
|
that view before there was anything to show.
|
|
|
|
**The technique is the transferable part:** the fault address alone said
|
|
"null pointer plus 24", which is nearly useless; `llvm-nm` on the faulting `rip`
|
|
turned it into a function name, and the offset then identified the exact field.
|
|
Reach for that before adding printfs to a program you did not write.
|
|
|
|
The cause was ours, and it was visible in the log the whole time: every run
|
|
printed a burst of garbage bytes *before* the grab was taken, and the amount
|
|
differed each run.
|
|
|
|
**`/dev/input/eventN` had no notion of being opened.** Events were queued from
|
|
boot onwards whether or not anything was listening, into one 256-entry ring
|
|
with one read cursor. When the program opened the device it inherited the entire
|
|
backlog -- including the keystrokes of the command line that had launched it,
|
|
which the shell had already consumed -- and replayed them as input. Whether that
|
|
crashed depended on which keys happened to be sitting there, which is exactly
|
|
the "sometimes" in the report.
|
|
|
|
Fixed by giving `struct devsw` an `open` hook to match `close`, and having
|
|
`/dev/input`:
|
|
|
|
- drop the backlog on open (`r = w`) -- a reader starts from *now*;
|
|
- only queue events while `opens > 0`, which is what Linux does: an evdev
|
|
device with no clients does not accumulate.
|
|
|
|
Linux gets both for free by giving every open its own client queue. One shared
|
|
ring plus "start from now" is the same answer for a single reader, which is the
|
|
only case that exists today; per-client queues become necessary the moment
|
|
Schcom and a client both want the keyboard.
|
|
|
|
### Also fixed
|
|
|
|
`cd` into a file reported "Operation not permitted". It was right to fail, but
|
|
`sys_chdir` returned a bare `-1`, so the shell printed whatever errno happened
|
|
to be lying around. It returns `-ENOTDIR` now, and `-ENOENT`/`-EFAULT` on the
|
|
other two failure paths -- "Not a directory" sends you to the right place,
|
|
"Operation not permitted" sends you looking at permissions.
|
|
|
|
## 13. The clock ran seven times slow, and the graphics card was why
|
|
|
|
The report was about time. fastfetch said the machine had been up for 3 seconds
|
|
after 15 real ones. `time ping 127.0.0.1` claimed `0m03.12s real` for a command
|
|
that visibly took 20. ping's one-second interval was closer to six. Three
|
|
programs, three wrong numbers, all wrong by roughly the same factor and all in
|
|
the same direction -- which is the shape of one shared cause, not three bugs.
|
|
|
|
The shared cause was obviously the tick. Everything above is derived from
|
|
`ticks`, and `ticks` comes from the timer interrupt. So the hunt started at the
|
|
bottom of that chain, and the first thing it found was real:
|
|
|
|
```c
|
|
// If xv6 cared more about precise timekeeping,
|
|
// TICR would be calibrated using an external time source.
|
|
lapicw(TICR, 10000000);
|
|
```
|
|
|
|
That is xv6's own comment, still in the tree, admitting that the LAPIC timer's
|
|
countdown value was never measured against anything. 10000000 yields the
|
|
intended 100 Hz only if the APIC bus happens to run at exactly 1 GHz.
|
|
|
|
It was a genuine gap and it is now fixed -- `calibrate_timers()` measures the
|
|
LAPIC and the TSC against the 8254 PIT, which is fixed at 1193182 Hz by the
|
|
hardware and is exactly the external time source the comment asked for. But it
|
|
was not the bug. The measurement came back at 999.9 MHz. The bus really was
|
|
1 GHz, `TICR = 10000000` really was 100 Hz, and the clock was still wrong.
|
|
|
|
### What the instruments said
|
|
|
|
Every clock agreed with every other clock, which is the confusing part:
|
|
|
|
| measured against | TSC | LAPIC timer |
|
|
|---|---|---|
|
|
| the PIT | 3792 MHz | 999 MHz |
|
|
| one CMOS RTC second | 3791 MHz | 999 MHz |
|
|
|
|
Three independent clocks, mutually consistent, and 3792 MHz is exactly the
|
|
5700G's base clock. So the timer was programmed for 10 ms and the registers
|
|
read back correct at runtime: `TICR=10000314`, `TDCR=11` (divide by one),
|
|
`LVT=0x20020` (periodic, vector 32). Interrupts nonetheless arrived every 68 ms.
|
|
|
|
Two hypotheses died next. Interrupts were not being masked -- the CPU had
|
|
`IF=1` for 99.98% of the measured window. And it was not the idle `hlt()`:
|
|
deleting it changed nothing, and neither did dropping to `-smp 1`.
|
|
|
|
What broke it open was measuring the gaps between consecutive timer interrupts
|
|
instead of averaging them:
|
|
|
|
```
|
|
timer gaps us: 2851 137614 2438 136293 3805 136889 3019 138420 6950 137248
|
|
```
|
|
|
|
Bimodal, strictly alternating. Not a slow clock -- a clock being interrupted.
|
|
In one-shot mode the short gaps sharpened to 10031, 10078, 10064, 10011 µs,
|
|
which is a perfect 10 ms: the LAPIC was doing its job exactly as programmed,
|
|
and then something was eating the next 130 ms.
|
|
|
|
Timing every trap by vector found it in one boot:
|
|
|
|
```
|
|
trapno 43: 5828 ms total, 510000 entries
|
|
```
|
|
|
|
Vector 43 is `T_IRQ0 + 11`. IRQ 11 was taking **72,000 interrupts a second** and
|
|
consuming 83% of CPU0.
|
|
|
|
### The actual bug
|
|
|
|
IRQ 11 was the e1000. Its handler reads ICR, and reading ICR clears it, so the
|
|
driver looked correct -- and it was. The cause register read back **zero** on
|
|
essentially every one of those 500,000 interrupts: the e1000 was being handed
|
|
somebody else's interrupt and correctly answering "not mine".
|
|
|
|
The somebody else was `virtio-gpu-pci`, sharing IRQ 11, **with no interrupt
|
|
handler registered at all**. PCI INTx is level-triggered. The device asserted
|
|
the line, the kernel signalled EOI, nothing had cleared the device's interrupt
|
|
status, so the line was still asserted and it fired again immediately. Forever.
|
|
|
|
The fix is one read. Reading virtio's ISR byte clears it and drops the line:
|
|
|
|
```c
|
|
static void
|
|
vgpu_intr(void *arg)
|
|
{
|
|
struct vgpu *g = arg;
|
|
if (g && g->isr)
|
|
(void)*g->isr;
|
|
}
|
|
```
|
|
|
|
This driver polls for command completion and wants no notifications. "Wants
|
|
none" and "gets none" are different things, and only the second one is free.
|
|
|
|
Booting without `-device virtio-gpu-pci` had already proved it: 100 ticks in
|
|
999 ms, and the e1000 taking 2 interrupts instead of half a million. With the
|
|
handler registered, uptime advances 5.01 seconds per 5 real seconds.
|
|
|
|
### What to take from it
|
|
|
|
**A shared level-triggered line is only as good as its worst driver.** Every
|
|
other device on IRQ 11 was correct. One driver that never acknowledged its
|
|
device was enough to starve the whole machine.
|
|
|
|
**The symptom appears where the missing CPU time hurts first, which is nowhere
|
|
near the fault.** This surfaced as a timekeeping bug, in userspace, in three
|
|
unrelated programs. It sent the investigation into the timer code, where there
|
|
was a real defect sitting in plain sight with a comment explaining itself --
|
|
and fixing that defect changed nothing, because it was not this one. A
|
|
plausible bug found early is the most expensive thing in a debugging session.
|
|
|
|
**Averages hide alternation.** "68 ms per interrupt" suggested a wrong
|
|
frequency and implied the timer. "10 ms, then 130 ms, repeating" says the timer
|
|
is fine and something else is stealing the machine. Same data, one of them
|
|
divided.
|
|
|
|
`irq_dispatch` now measures the rate on every line against the TSC -- not
|
|
against `ticks`, which is the first casualty of a storm -- and says so once:
|
|
|
|
```
|
|
irq 11: 75894 interrupts/second -- a device on this line is not acknowledging it.
|
|
irq 11: handler 'virtio-gpu' is attached
|
|
irq 11: handler 'e1000' is attached
|
|
```
|
|
|
|
That is the message this cost an afternoon for. The threshold is 20000/s, which
|
|
no real device on this machine sustains.
|
|
|
|
### Also fixed
|
|
|
|
`microdelay()` was an empty function body -- xv6's stub, with a comment saying
|
|
real hardware would want to tune it. Every `microdelay(1000)` in the xHCI reset
|
|
path and the USB hub power-on sequence returned instantly. Those waits are in
|
|
the specifications because the hardware needs the time; a port that "works
|
|
anyway" is racing and winning. It now spins on the calibrated TSC.
|
|
|
|
The tick rate itself stopped being a magic number. `HZ` lives in `param.h`, and
|
|
the dozen places that wrote `ticks / 100` or `sec * 100` use it. `USER_HZ` is
|
|
separate and deliberately does not follow it: musl answers
|
|
`sysconf(_SC_CLK_TCK)` with 100 no matter what, so `times()` and `/proc/stat`
|
|
are scaled at the syscall boundary the way Linux does it. Before, `sys_times`
|
|
returned raw ticks -- correct only while `HZ` happened to be 100, and silently
|
|
wrong the day anyone changed it.
|