Observability & Debugging

A kernel is only as debuggable as it is observable. Aegis ships a layered set of in-kernel diagnostics designed around one hard constraint: the serial console is frequently the only channel available — there is no host debugger on real hardware, no dmesg you can read after a hang, and a fault often kills the very code that would have printed the explanation. Every facility on this page is built to produce a useful artifact on the serial line, in the moment, even when userspace or the scheduler is wedged.

v1 maturity notice. Aegis v1 is a first public release, not a production-hardened system. These diagnostics were built to make the kernel’s own bugs findable; they are not a security boundary and several (SysRq-over-serial, /proc/stackshot) deliberately expose kernel state. The kernel is predominantly C and undergoing a gradual translation to Rust (kernel/cap/ is the Rust beachhead). Contributions welcome — file issues at exec/aegis.

These facilities were added after a multi-day SMP debugging session whose bugs were all, in hindsight, visibility failures: an Application Processor that came up but signalled “online” just after a too-short timeout; serial output from two CPUs interleaving into unreadable garble; an intermittent input-corruption race with no trace of the byte flow. The lesson — and the design principle here — is that the cheapest fix for a class of bug is usually a tool that makes it visible the first time.

printk and the kernel log

All kernel output flows through printk() (kernel/core/printk.c). Two laws govern it:

1. Serial is written unconditionally (once serial_init has run). The VGA text console and the framebuffer are written only if available and not suppressed — VGA/FB failure never silences serial.
2. Output is serialized under printk_lock so two CPUs (or an ISR and a thread) cannot interleave a line.

printk supports a deliberately small format set: %s %c %u %lu %x %lx %%. There is no %d — signed values must be formatted by the caller (a %d is emitted literally and consumes no argument, which silently mis-aligns every subsequent conversion; this is a recurring foot-gun).

The kernel log ring (/proc/dmesg)

Every emitted byte is also written to a 64 KB circular log buffer (klog_buf). klog_read() returns the newest bytes when the destination is smaller than the log, which is what /proc/dmesg surfaces to userspace.

Serialized console — the SMP serial-garble fix

printk holds printk_lock across an entire line, so two printks can never interleave. But userspace writes to /dev/console took a separate, unlocked path to the serial port — so a userspace line (say [DHCP] acquired ...) on one CPU would interleave character-by-character with a kernel printk on another:

[EXT[D2HC]P ] sacyqnuicr:ed  10.0.2.15 ...

The fix is printk_emit_bytes(): the /dev/console writer (kernel/fs/console.c) now routes through it, taking the same printk_lock as printk. Kernel and userspace output are now serialized against each other:

[cpu0 t0.12] [NET] configured: 10.0.2.15/24 gw 10.0.2.2
[DHCP] acquired 10.0.2.15/24 gw 10.0.2.2 lease 86400s dns 10.0.2.3

Per-CPU line decoration

Once more than one CPU is online, printk prefixes every kernel line with the originating CPU and uptime:

[cpu0 t0.06] [EXT2] sync: flushed 7 dirty blocks

The prefix is [cpu<N> t<sec>.<centiseconds>] — CPU id from lapic_id(), uptime from pit_ticks(). It is off until SMP bring-up brings a second CPU online (smp_start_aps calls printk_set_decorate(1) when g_cpu_count > 1), so single-CPU boots — and the boot test oracle — see byte-identical output to before. Without this, concurrent AP/BSP output is an unattributable interleave; with it, every line says which core produced it and when.

Panic, faults, and symbolized backtraces

A CPU exception from ring 3 is converted to a signal (see Interrupts & Exceptions) — a user segfault never takes down the kernel. A fault from ring 0 is a kernel bug and panics, printing a structured record:

[PANIC] cpu0 exception 14 at RIP=0xffffffff80149abc error=0x2 CS=0x8
[PANIC] #PF CR2=0x30 rax=0x0 rbx=0xffffffff8123...
[PANIC] backtrace (resolve: make sym ADDR=0x<addr>):
    [0] 0xffffffff80149abc sys_write+0x5c
    [1] 0xffffffff80149113 syscall_dispatch+0xcc
    [2] 0xffffffff80107770 syscall_entry+0x50

The first line carries the originating CPU, the exception vector, faulting RIP, error code, and CS. For #PF it adds CR2 and key registers; for #GP at the iretq boundary it dumps the full 5-slot interrupt frame.

The backtrace walks the frame-pointer chain (print_backtrace_from() in kernel/arch/x86_64/idt.c). The kernel is built with -fno-omit-frame-pointer, so every frame stores [rbp+0] = previous RBP and [rbp+8] = return address. Each return address is symbolized to function+0x<offset> when the in-kernel symbol table is present (below), otherwise it is bare hex, resolvable offline with make sym.

The in-kernel symbol table

Bare hex addresses force a host round-trip (make sym ADDR=...). On real hardware with no host attached, that is impossible. So the kernel embeds its own sorted symbol table and resolves addresses live, the way Linux’s kallsyms does.

How it is built. A small generator (tools/gen-ksyms.sh) runs nm -n on the linked kernel, keeps the text-segment function symbols, and emits build/ksyms.c — sorted {address, name} arrays. This is wired into the link as a two-pass build (Makefile):

1. Link the kernel once with weak, empty ksym_* fallback arrays (kernel/core/ksym.c).
2. Generate build/ksyms.c from that linked image and compile it.
3. Relink with the generated table; its strong symbols override the weak fallbacks.

A single extra pass is sufficient — no iterate-to-fixpoint — because .text precedes .rodata in the linker script (tools/linker.ld). The symbol blob is const data (.rodata), placed after all code, so embedding it never moves a function address: the addresses captured in pass 1 stay valid in the relink.

How it is used. ksym_lookup(addr, &offset) binary-searches the table for the greatest symbol address <= addr and returns name + offset. print_backtrace_from() calls it for every frame. The table holds ~2000 symbols and costs ~50 KB of image. If the generated file is ever absent, the weak fallback makes ksym_count == 0, ksym_lookup returns NULL, and backtraces fall back to hex — the kernel always links.

The full-debug build/aegis.elf (kept for make sym / GDB) carries -g DWARF info; the symbol table is independent of that and survives --strip-all into the packaged kernel, so symbolized backtraces work on the shipped ISO too.

Stackshot — dump every task with its backtrace

The single most useful artifact for a deadlock, lost wakeup, or “everything is blocked and nothing is moving” bug is a snapshot of all tasks and what each is waiting on. dump_all_tasks() (kernel/sched/sched.c) produces it:

[STACKSHOT] ==== all tasks (sysrq-t) ====
[STACKSHOT] pid=0 <kthread> state=0 on_cpu=0 sc=0 wait=0 <== current
    [0] sysrq_handle+0x27
    [1] serial_rx_handler+0x36
    [2] isr_dispatch+0x41a
    [3] task_idle+0xe
[STACKSHOT] pid=5 /bin/sshd state=1 on_cpu=-1 sc=43 wait=0
    [0] sys_accept+0x345
    [1] syscall_dispatch+0x74f
    [2] syscall_entry+0x50
[STACKSHOT] pid=4 /bin/login state=1 on_cpu=-1 sc=0 wait=0
    [0] kbd_read_interruptible+0x8f
    [1] console_tty_read_raw+0x20
    [2] tty_read+0x3e0
[STACKSHOT] ==== end (N tasks) ====

Each line gives the task’s pid, name, state (0 running, 1 blocked, 2 zombie), the CPU it is running on (-1 = not running), its last syscall number, and its wait target — followed by a kernel backtrace.

Recovering a blocked task’s stack is the interesting part. A task that is not currently running saved its kernel stack pointer into task->sp (offset 0, read by ctx_switch). ctx_switch pushes callee-saved registers in a fixed order (rbx, rbp, r12–r15) and then stores RSP, so from the saved sp the stackshot reads [sp+32] = saved RBP and [sp+48] = the resume return address, and walks the frame chain from there. The current task on the calling CPU uses its live frame instead; a task running on another CPU is skipped (its saved sp is stale).

dump_all_tasks() is ISR-safe: it takes sched_lock via trylock (printing a warning and proceeding best-effort if it is busy) so it can be invoked from an interrupt handler — the SysRq path and a future watchdog — without deadlocking against code that already holds the lock. (Lock order and the sched_lock invariants are described under Scheduler.)

/proc/stackshot

Reading /proc/stackshot triggers a full stackshot to the kernel log / serial and returns a short acknowledgement. This is the on-demand form for a system that is still responsive:

$ cat /proc/stackshot      # dump appears on serial / in dmesg

SysRq-over-serial

/proc/stackshot requires running a process. When the system is wedged — the scheduler stuck, userspace unresponsive — you need a channel that bypasses all of it. The serial RX interrupt handler provides one.

serial_rx_handler() (kernel/arch/x86_64/serial.c) watches for the prefix byte 0x1F (Ctrl-_, a control code no shell or application emits) followed by a command letter. The prefix and command are consumed (never injected into the input ring); the command runs directly in interrupt context:

Because it runs from the RX ISR, it works when nothing else does. Sending 0x1F t over the serial line to a hung Aegis prints the full symbolized stackshot — frequently enough to see exactly which task never woke and where it is parked.

Trace ring — a lockless flight recorder

Stackshot photographs a frozen system. Many bugs never freeze — an intermittent data race, an out-of-order event, a byte that scrambles once in a hundred times. For those you need a record of what happened in the moments before, captured without perturbing the timing. That is the trace ring (kernel/core/trace.c).

It is a fixed-size ring of binary event records appended from any context, any CPU, via a single atomic index — no lock, by design: a lock would serialize the producers and mask the very race under study. Each record captures who (CPU), what (event id), which state (a few args), and when (TSC, for cross-CPU ordering). The append is a handful of instructions, so tracepoints can sit on hot paths.

The motivating use is the keyboard input ring. Two tracepoints — TRACE_KBD_INJECT (producer) and TRACE_KBD_CONSUME (consumer) — record (byte, head, tail) at every touch of the shared ring. Dumping the ring (0x1F r, or cat /proc/trace) shows the exact interleaving:

[TRACE] ==== ring dump (sysrq-r) 6 records ====
[TRACE] seq=0 cpu=0 KBD_INJECT  byte=0x61 'a' head=0 tail=0
[TRACE] seq=1 cpu=0 KBD_CONSUME byte=0x61 'a' head=1 tail=0
[TRACE] seq=2 cpu=0 KBD_INJECT  byte=0x62 'b' head=1 tail=1
[TRACE] seq=3 cpu=0 KBD_CONSUME byte=0x62 'b' head=2 tail=1
[TRACE] ==== end ====

On a single core every byte is injected then cleanly consumed with the indices advancing. On multiple cores, an input-corruption race shows up as a concrete inconsistency — a consumed byte that does not match the injected one, or head/tail values that disagree between the producer CPU and the consumer CPU — instead of the symptom “a byte scrambled somewhere upstream.” The ring is the general substrate; adding a tracepoint elsewhere (a syscall, a fork, an IPC send) is a one-line trace_emit().

Process-lifecycle tracing

A multi-process application — Ladybird’s frontend plus its RequestServer / WebContent / Compositor / ImageDecoder — fails in ways a single process never does: did all the services even spawn? which one exited first? Process-lifecycle tracing answers that on the serial line. With the proc_trace kernel cmdline flag set, the kernel emits one line per process transition:

[PROC] exec  pid=2 ppid=1 /bin/chronos
[PROC] exec  pid=5 ppid=1 /bin/sshd
[PROC] exit  pid=3 ppid=1 /bin/dhcp
[PROC] exec  pid=6 ppid=5 /bin/tinysshd-makekey
[PROC] exit  pid=6 ppid=5 /bin/tinysshd-makekey

The hooks sit in the fork, execve, spawn, and exit paths and print verb · pid · ppid · name. The flag is off by default, so ordinary boots and the test oracle are unchanged; it is enabled only when watching a spawn sequence. For a service pipeline this turns “no window renders and I don’t know why” into a precise record of which process launched, in what order, and which one died.

Runtime assertions

Two macros (kernel/core/printk.h) make invariant violations fail loudly and at their source rather than as a distant, uninformative panic:

KASSERT(cond);            /* on failure: print "[ASSERT] FAIL: <cond> at file:line cpuN", halt */
WARN_ONCE(cond, "msg");   /* if cond: print "[WARN] msg at file:line" exactly once, then continue */

KASSERT is for “the kernel is already corrupt if this is false” — it prints the condition text, file, line, and CPU, then halts. WARN_ONCE is for “shouldn’t happen but is survivable” — it fires once per call site and continues, so a recurring anomaly leaves exactly one line instead of a flood.

SMP bring-up checkpoints

Application Processor startup (smp_start_aps, Scheduler) now reports per-AP timing:

[SMP] AP 1 (LAPIC 1) online after 39 Mcycles
[SMP] AP 2 (LAPIC 2) online after 40 Mcycles
[SMP] AP 3 (LAPIC 3) online after 40 Mcycles
[SMP] OK: 4 CPUs online

The BSP polls a fixed TSC-cycle budget waiting for each AP to signal online. The checkpoint prints how long that actually took. The reason this matters: the budget is in raw TSC cycles, but TSC frequency varies wildly (a KVM host passes through ~3–5 GHz), so a budget that is “generous” at 1 GHz can silently expire before an AP finishes lapic_timer_init on a fast host — and a too-short budget makes the BSP fire the next AP’s startup while the previous one still holds the shared PIT calibration channel, so they contend and none come online. With the checkpoint, the bring-up time is visible; if it ever creeps toward the budget ceiling, the regression is obvious before it starts failing.

Tooling

Three host-side make targets complete the picture. The first two operate on the full-debug build/aegis.elf.

make sym ADDR=0x...

Resolve a single address to function and file:line via addr2line. The companion to a hex backtrace from a kernel without the symbol table, or for file:line precision the in-kernel table does not carry:

$ make sym ADDR=0xffffffff8013fb60
ramdisk_init at kernel/drivers/ramdisk.c:64

make gdb

Boot QEMU with its GDB stub (-s -S, CPU halted at entry), serial redirected to build/debug.log, and auto-connect GDB via tools/aegis.gdb. Source-level breakpoints, single-stepping, and structure inspection against the running kernel. This reaches QEMU only — there is no in-kernel GDB stub for bare metal yet.

make trace — diagnosing a silent boot death

The hardest class of bug is a kernel that dies with no serial output at all — boots fine on one configuration, silent on another. There is nothing to read. make trace boots under TCG with QEMU’s own exception/reset logging and captures everything QEMU sees that the kernel could not print:

$ make trace                          # defaults: -cpu qemu64, 25s
$ make trace TRACE_CPU=Broadwell TRACE_SECS=60

It writes the executed-exception / reset / guest-error log to build/qemu-trace.log and the serial output to build/qemu-serial.log, then prints the tail — the faulting vector (v=<N>) and RIP, or a CPU Reset indicating a triple fault. Resolve the RIP with make sym, and a silent death becomes a one-line diagnosis. (This is exactly how an apparent “kernel won’t boot under -cpu Broadwell” turned out to be not a fault at all, but a slow boot under TCG — the trace showed the CPU reaching idle, just late.)

Summary