SchOS/docs/architecture/debugging.md

Finding out what the kernel is doing

Every bug in this project used to be found the same way: add a cprintf, rebuild, boot, read the serial log, guess again. That loop is about ninety seconds long and it answers exactly one question per turn — the question you thought to ask before you rebuilt.

What ended it was a real bug. A DMA block was on two allocators' free lists at once, and finding that took several rounds of that loop, because the kernel could not be asked whether two allocators owned the same page. It could not be asked anything.

The kernel had no way to answer a question it was not already compiled to answer.

Five things close that, and none of them is a debugger in the stepping sense: names for addresses, a log that survives, a way to ask each subsystem what it knows, a way to ask all of them about one page, and the processor's own watchpoints.

---

Turning it on at the boot menu

schdbgd ships Disabled, and the reason is in its manifest: a debugger that can read the process table should not be running on a machine whose owner never asked for one. That is the right default and it has one bad consequence — the machines that most need debugging are the ones you cannot get a shell on to enable it. A laptop with no serial port that stops before it can draw has nowhere to say why, and schinitd enable needs a prompt that does not exist.

So a build made with make DEBUG=1 has a sixth entry in the F8 menu:

  > 6. Remote debugging: off

Picking it toggles the entry, booting carries the choice through SCHBOOT_DEBUG_FLAG, the kernel publishes it as /proc/bootdebug, and schinitd starts the one job that flag is allowed to un-disable. Plug the machine into a router, pick the entry, and connect from the laptop next to it:

nc 192.168.1.50 4444
dma

Four decisions worth stating, because this is a network-reachable debugger:

It is compiled out, not hidden. A release build has no way to set the flag, because the code that would set it is not in the binary. A menu item that is present and refuses is an invitation to work out how to make it not refuse.

The consent is asked for at the machine. Somebody standing at the keyboard during boot is the strongest consent this system can ask for, and the weakest one that is any use on hardware that will not boot.

One job, named in schinitd. Not a manifest key like EnableIfDebug — the general version of "the boot menu can start things that ship switched off" is a worse idea than the specific one, and this way the list of what the flag can start is one line anybody can read.

The kernel does nothing with the flag but publish it. A kernel that changed behaviour on a debug flag would be a kernel whose bugs could depend on it, and a debug build and a release build would stop being the same kernel.

The rule the shape follows

It observes; it does not control. No stepping, no software breakpoints, no stopping the world.

That is not a scope compromise. Half the bugs this kernel actually produces are timing: an interrupt storm at 77,000 a second, a level-triggered line nobody acknowledges, a driver that faults only on its second start, a supervisor that restarts a job fifteen times in forty-five seconds. Every one of those disappears when you halt the machine to look at it.

And the layering rule, which is the circularity rule the display already has, pointed somewhere else:

A debugger that needs lwIP cannot debug lwIP. A debugger that needs a process cannot debug the scheduler. A debugger that needs to allocate cannot debug the allocator.

So the kernel's half is the minimum that works when nothing else does, and everything convenient is a process.

---

Naming an address

tools/ksyms.pl turns the kernel's own symbol table into a table the kernel carries, and ksym_lookup() resolves an address through it. A crash chain used to be nine hex numbers:

    Call chain
      #0  ffff80000010a9d9  panic+0x5f
      #1  ffff80000011e07f  proc_sysrq_cmd+0x99
      #2  ffff80000011e205  proc_write_sysrq+0x6e
      #3  ffff800000130159  procfs_write+0x59
      #4  ffff80000012e566  writei+0x45
      #5  ffff800000128a96  filewrite+0x2ec
      #6  ffff80000016c0fa  sys_writev+0x12b
      #7  ffff80000016986e  syscall+0xf6
      #8  ffff800000100d2e  syscall_trapret

Two link passes, and why two is enough

The kernel is linked twice. Pass one exists to be read; pass two carries the table built from it.

The obvious objection is that adding forty kilobytes to the image moves everything the table describes — which is why Linux's kallsyms needs three passes and a convergence check. .ksym is placed after .text and .rodata, so it cannot move a single address the table records. Two passes, and the second is stable by construction.

Not by assumption, though: the build lists the text symbols of both passes and fails if they differ. A symbol table that is subtly wrong for every address is worse than none, because it produces confident, false answers.

ksym.c reads the table through weak symbols, so pass one — which has no table — still links, and a tree with the generator removed still boots and simply cannot name anything.

---

A log that outlives the kernel

cprintf used to go to a serial line and a screen and then be gone. panic.c said so in its own header: "there is no core dump and no log to go back to."

There is now. Every character that passes through consputc() — which is every kernel message, including the whole PSOGM report — is also appended to a byte ring with a timestamp per line. It is readable as /proc/kmsg.

The ring lives in a region carved out before the page allocator is given anything, and it has a magic header, so a kernel that reboots finds the previous kernel's log still there:

--- boot 1 ---
[     0.00] e820: 1018 MB usable in 7 regions, top 1016 MB (19 entries)
...
[     7.18]   PSOGM -- Purple Screen of Guru Meditation
[     7.18]     Call chain
[     7.18]       #0  ffff80000010a9d9  panic+0x5f
...
--- boot 2 ---
[     0.00] klog: 128 KB at ffff80000053e000, 2162 bytes carried over from the previous boot

Where it lives, and why not where you would put it

The obvious place is the top of RAM, beside the DMA arena. That was the first attempt, and on the reboot the magic came back as ASCII — because the top of usable memory is exactly where the firmware puts its own allocations before it hands the machine over.

It sits immediately above the kernel image instead. end is the same address on every boot of the same build, which is the property a region has to have to be found again, and the bytes just past the kernel are the ones the loader has already committed to leaving alone. No hole has to be punched in the allocator: kinit1's lower bound is a parameter.

The magic and a header checksum mean a region something else has used is re-initialised rather than printed as if it were a log. A reboot that does not preserve DRAM loses the log, and says so rather than showing garbage.

Two properties of the writer are deliberate. It takes no lock — it runs inside consputc(), and a lock there would be a way for the logger to deadlock the thing it exists to report on. And it buffers before it exists: the region is carved after e820_init(), so the handful of lines before that go into a static array and are flushed in, because a log that is blank for the earliest part of the boot is blank for the part that is hardest to debug any other way.

---

Asking a question

/dev/dbg is a conversation: write a line, read the answer.

# schdbg dma
arena  0xffff80003e8ed000-0xffff80003f8ed000
       16384 KB total, 12295 KB free in 3 extent(s), 4088 KB out

  #   base                 phys                 bytes
   0  0xffff80003e8f3000   0x000000003e8f3000      4091904
   1  0xffff80003ecea200   0x000000003ecea200         3584
   2  0xffff80003f0d3000   0x000000003f0d3000      8495104

It is text, not a typed binary protocol, and the reason is that the same bytes have to work at every level — including the one where nothing can allocate, frame a record, or wait for a client to acknowledge anything. A protocol you cannot drive by hand is a protocol you cannot debug. Everything schdbg does is also:

# echo dma > /dev/dbg && cat /dev/dbg

The registry is the point, not the views

A subsystem publishes its state with one line at the bottom of the file that owns the data:

dbg_register("dma", dma_dump, "the DMA arena's free extents");

Nothing central is edited to add one. That is the difference between something that stays current and something that does not — /proc/sysrq is the version that does not, a switch in one file with a letter per action, and after two years it holds three self-tests and no state at all.

View
dma	the arena's free extents, in virtual and physical
mem	the page allocator's free list, and whether it has a cycle in it
proc	every process, with state, size and its mmap bump pointer
vma	every mapping a process holds but does not own the pages of
claims	devices, DMA blocks and interrupts held by userspace drivers
pci	the bus, with each device's command register decoded
sock	the socket table, with buffered bytes and descriptors in flight
watch	the hardware watchpoints, and which CPUs have loaded them

all prints every view; help lists them; a view may take an argument, so vma 4 narrows to one process.

Several of those exist because of a specific bug. vma is the table that decides whether exit() frees a page or leaves it alone, and the bug that made this worth building was a DMA block that was never in it. claims shows the three things that go wrong with a userspace driver — a device held by a process that no longer exists, DMA handed out and never returned, an interrupt line left masked with nobody reading it. pci decodes the command register because "is bus mastering actually off?" is a question with a wrong answer that looks fine.

Three ways in, and the one that always works

	Works when
Ctrl-G on the console	there is a scheduler — so from early in boot, with nothing mounted and nothing in userspace started
sysrq g	/proc is mounted
/dev/dbg	/dev is mounted
schdbg	there is a shell
schdbgd over TCP	there is a network, and somebody enabled it

Ctrl-G is the one that matters for boot problems, because it is the only one that does not need a filesystem. It sits beside the older Ctrl-P, which dumps the process table — and the difference between them is worth knowing. procdump() takes no lock at all, deliberately: a lock is a way to hang while reporting a hang. The views cannot follow that rule, because a free list or a socket table read torn is worse than not read. So they take locks, and a lock must never be taken from an interrupt handler that may have interrupted its holder.

The key therefore requests and a kernel thread performs. The cost is stated plainly: a scheduler too wedged to run a thread will not answer Ctrl-G. Ctrl-P still will, and that division of labour is the honest one.

A watchpoint's hits go to the console rather than to any of these, because they happen while you are not looking, which is the point of having them.

Views run in ordinary process context and may take locks. They must not be called from panic().

---

Over the network

The fourth way in, and the only one that does not need you to be sitting at the machine: a target that has locked its display, a board with no keyboard, or a bug that only appears under load you cannot produce by hand.

# schdbgd &
schdbgd: debugger on port 4444, loopback only

$ nc 127.0.0.1 4444
SchOS debugger. 'help' for the views, 'quit' to go.
read-only: views that change state are refused here.

dma
arena  0xffff80003da41000-0xffff80003ea41000
       16384 KB total, 16319 KB free in 1 extent(s), 64 KB out

schdbgd is a bridge and nothing else: a line in becomes a line written to /dev/dbgro, and the answer comes back. No framing, no state, no parsing of anything the kernel said — which is what makes nc a complete client, and what keeps this usable on the day the clever client is one of the broken things.

It is in a process rather than in the kernel because there is no reason for it to be in the kernel. A TCP listener inside a kernel debugger is a listener that has to work when the kernel does not, and this one does not pretend to: if the scheduler is wedged, schdbgd is not running either, and the answer is Ctrl-G.

What a listener had to be decided about

A kernel debugger plus a TCP socket is a remote root hole. That is true of every one ever written; it is not a reason not to build one, and it is a reason to decide rather than discover. Three decisions, in increasing order of how much they actually protect:

It does not start by itself. /etc/schinit/schdbgd.job ships Disabled. SchOS has no kernel command line, so the boot flag is the job manifest — the same thing in this system's own idiom. A machine whose owner never asked for a debugger is not running one.

It binds loopback, and binding anywhere else takes -a naming the address, and says so in a paragraph rather than a word. Reaching it then means ssh -L, which is somebody's deliberate act.

It cannot reach a view that changes state, and that is enforced in the kernel. /dev/dbgro is /dev/dbg on minor 1. The minor is the one piece of per-open state a character device already sees, so which node you opened is the permission: there is nothing to latch, nothing to remember between the write and the read, and no way to get from one descriptor to the other.

Which views are refused comes from the registration — dbg_register_rw instead of dbg_register — for exactly the reason the registry exists at all. A list of dangerous views in one central file is a list that goes stale, and it goes stale in the direction where a newly added view is quietly treated as safe.

Today that is one view. watch <addr> arms a debug register, which is a reasonable thing for a debugger to do and not a reasonable thing for a stranger on a socket to do:

$ nc 127.0.0.1 4444
watch 0xffff80003da41000
'watch' changes state, and this is /dev/dbgro.
use /dev/dbg from the console for that.

watch with no argument is still answered, because that is the listing and it arms nothing.

---

Who owns this page

The views each speak for one subsystem, which is what keeps them cheap and current — and it is exactly why none of them can see the bug that matters. A page on the DMA arena's free list looks fine from dma.c. The same page on kalloc's free list looks fine from kalloc.c. That it is on both is a fact no single subsystem holds, and it is the bug that cost this project a day.

whose asks every subsystem about one page and counts the answers:

# schdbg whose 0x3e239000
phys 0x000000003e239000   kernel va 0xffff80003e239000
  dma     arena, handed out
  pcidma  slot 2, 0 KB into a 4000 KB block given to pid 4 (vgpud)
  mapped  pid 4 (vgpud) at 0x000000004000d000  rwu  vma[5] no_free

  consistent: 1 owner, 1 mapping(s)

That is the complete life of one page in three lines: the arena gave it out, /dev/pci handed it to a driver, and the driver has it mapped under a VMA marked no_free so exit() will not free it twice.

The claimants are registered exactly as views are, for the same reason — adding one is a line in the file that owns the data:

kernel	inside the kernel image, below end
klog	inside the log region
dma	the arena owns it, and whether the arena thinks it is free
mem	on kalloc's free list, and where
pcidma	inside a block handed to a userspace driver, and which
mapped	every page table that maps it, at what address, under which VMA

mapped is the one no allocator can answer. There is no reverse map in this kernel, so it walks every mapped page of every live process — a few thousand iterations, which is nothing for a command somebody typed and would be unacceptable anywhere else.

The two verdicts that matter

More than one owner means whichever allocator hands the page out second will be handing out memory the first one is still using. That is the H2 bug, and it would have printed as three claimant lines instead of taking a day.

Free, but still mapped means an allocator believes a page is spare while page tables still point at it — it will be given away from under them.

Anything else is reported as fact, not verdict. In particular no owner is normal: kalloc keeps a free list and no record of what it has handed out, so an ordinary allocated page has nobody to speak for it, and saying "nobody owns this" about one would be the query crying wolf.

An address at or above KERNBASE is taken as a kernel virtual address and translated; anything below is taken as physical. A user virtual address is refused rather than guessed at — it means nothing without saying which address space, and answering for whichever one happened to be current would be wrong in a way that looks right.

---

Watching an address

The question no amount of printing gets at: something wrote here — who? Adding a print to every writer only works when you already know who the writers are, and the bug is invariably a writer you have not thought of.

The processor will simply tell you. Four debug registers had been sitting unused in this kernel since it was written.

# schdbg watch 0xffff80003e239000 8 w
watch 0 armed on 0xffff80003e239000, 8 byte(s), on write

watch 0: 0xffff80003e239000 written, 8 byte(s), by stosq+0x1f on cpu 0, pid 12 vgpud
         #0  memset+0xba
         #1  dma_alloc+0x2e2
         #2  do_dma+0x22a
         #3  pciuser_ioctl+0x13b
         #4  sys_ioctl+0x3c7
         #5  syscall+0xf6

The chain is the answer, not the rip: "memset wrote to it" is not useful; "memset, from dma_alloc, from do_dma" is.

It reports and continues. A data watchpoint on x86 is a trap, not a fault — it is delivered after the storing instruction has completed — so returning from the handler carries on with the program none the wiser. That is what makes it usable on a machine that is still running, which is the whole stance of this document. The cost is that you cannot prevent the write, only learn about it.

Every CPU watches, and there is no IPI. Debug registers are per-CPU, so arming DR0 on the processor that ran the command would watch one quarter of a four-way machine and silently miss the rest. The table carries a generation number instead, and each CPU reloads from its timer interrupt when it notices the number has moved: one comparison per tick, and at worst one tick of latency. watch reports which CPUs have caught up, because "this watchpoint is watching" and "this watchpoint is watching one CPU" must not look the same:

  table generation 2, loaded by:  cpu0=2  cpu1=2

Addresses must be naturally aligned for their length — the processor quietly ignores the low bits otherwise and watches a span you did not ask for, so it is refused instead. A watchpoint below KERNBASE is a user linear address and will fire in whatever process is current; watch says so rather than arming something that reports nonsense.

---

What it does not do

• It does not step, break, or halt. If a bug genuinely needs a stepper, this is the wrong tool, and that is a deliberate trade rather than an omission.
• whose cannot take a user virtual address, by refusal rather than oversight. vma <pid> is the view for that question.
• whose is a snapshot with no lock held across it. Each claimant takes its own subsystem's lock and releases it, so a page that changes hands while the query runs can be reported inconsistently. Taking every allocator's lock at once to fix that would deadlock against the allocators themselves.
• Four watchpoints, and no more. That is the hardware. There is no software watchpoint fallback and there should not be one.
• Watchpoints cannot stop a write, only report it — see above. And a watchpoint on something cprintf itself writes is silently dropped rather than looping; the handler guards against re-entering itself per CPU.
• A watchpoint takes up to one timer tick to reach the other CPUs.
• Ctrl-G needs a working scheduler, per the note above. Before dbg_thread_start() — which is the last thing main() does before entering the scheduler — nothing answers but the log, and the log is enough because it is read on the next boot.
• No memory writes, and no way to poke anything. Reading is what finds bugs.
• schdbgd has no authentication. Reaching the port is the permission, which is why the port is on loopback and why the daemon is off. Anyone who can open a TCP connection to it can read this kernel's memory layout, its process table and its open sockets. Putting a password on it would be worse than useless — it would make the current arrangement feel safer than it is.
• One client at a time. /dev/dbg holds one answer at a time, so two sessions would read each other's; a second caller waits.
• A disconnected client is noticed only when written to. A session that goes away between commands holds the daemon until TCP notices.
• all truncates at 16 KB and says so. On a busy machine, ask for one view at a time.
• One conversation at a time. The answer buffer is global, so two programs asking at once get one answer each in some order — never half of the other's, but not two independent sessions either.
• No userspace symbolization. The kernel names kernel symbols. A fault in a process still reports a bare address, and resolving it is a host-side job.
• The stack walk stops where the frame pointer stops. getcallerpcs() walks rbp chains, so a trap frame in the middle of a chain ends the walk.
• sysrq g costs you log history. Its output goes through cprintf, so sixteen kilobytes of views push the same amount out of a 128 KB ring.
• No tracing. No static tracepoints, no event ring, no counters. "What happened in the two hundred events before this" is not a question this can answer.

Nothing remains on the plan this was built from. What is not on it, and is the obvious next thing if this is ever picked up again, is tracing: static tracepoints and an event ring. That is a different tool that happens to share a transport.