Lab 2 · reveal · 16 steps · 8 commits
When this kernel panics it prints one line, such as panic: sched locks, and stops. The
line names the check that failed, not the path that led to it. In this lab you add
backtrace(), which prints the return address of every function on the current kernel
call chain, and make panic call it. On the host, addr2line turns the addresses
into file names and line numbers.
The walk itself is a five-line loop over the frame pointers the compiler
already maintains. The interesting part is where the loop must stop, and that depends on
which stack it is walking. A process’s kernel stack is one page, so its top is a
page boundary. A hart’s scheduler stack is a 4096-byte slice of stack0, which is
only 16-byte aligned, so its top is in the middle of a page, and its top 32 bytes hold two
frames left over from boot. And when an interrupt arrives in the middle of a call chain, kernelvec
pushes a 256-byte kernelvec frame that the walk has to step across. You will see all
three, in real output from three harts, and you will see what goes wrong, in
recorded runs, when the walk does not stop where it should.
Each step shows one change on the branch ext/02-backtrace, the code around it, and the state of the machine when that code runs.
kernel/riscv.hStep 1 of 16 · commit 1: Add r_fp to read the frame pointer
The story of this tour is one run of bttest on three harts, recorded with gdb
breakpoints on backtrace and on sys_kbacktrace. bttest is pid 3 in proc slot 2,
so its kernel stack is the page at 0x3fffff9000. Cases 0 and 1 ran on hart 2; for
case 2 it went to sleep on hart 0, and hart 1 printed. Every address in this tour is
from that build of the finished branch; earlier commits build to slightly different
addresses.
The first commit adds one accessor, next to r_sp and r_ra. C cannot name a
register, so r_fp is a one-instruction asm statement that copies
s0 into a variable. Because it is static inline, the mv runs inside the caller,
after the caller’s prologue: in backtrace, it reads backtrace’s own frame pointer,
0x3fffff9f90 in case 0.
The state shown is that moment: hart 2 in supervisor mode on bttest’s kernel stack,
interrupts on (as in every system call after usertrap's intr_on), no lock held.
The walk will read only memory of this stack, so it needs no lock: nothing else writes
a running process’s kernel stack.
Step 2 of 16 · commit 1: Add r_fp to read the frame pointer
Nothing in this commit changes the Makefile; this is the flag the lab depends on.
-fno-omit-frame-pointer (-fno-omit-frame-pointer) makes every C function keep a frame
pointer in s0. backtrace’s own prologue in this build:
80000834: 7179 addi sp,sp,-48
80000836: f406 sd ra,40(sp)
80000838: f022 sd s0,32(sp)
...
8000083e: 1800 addi s0,sp,48
s0 ends up 48 bytes above the new sp, at the old sp, with the return address at
s0-8 and the caller’s s0 at s0-16. In case 0, gdb showed sp = 0x3fffff9f90 on
entry, so backtrace’s record holds 0x80002c46 (its return address in
sys_kbacktrace) at 0x3fffff9f88 and 0x3fffff9fc0 (sys_kbacktrace’s frame
pointer) at 0x3fffff9f80.
Each saved s0 points at the caller’s record: the frames form a linked list running
up the stack. Without the flag, s0 would hold some variable instead (clinic 4).
kernel/printk.cStep 3 of 16 · commit 2: Add backtrace() that walks the frame pointers
The walk is a loop over records. Print the return address at fp-8, load the caller’s
frame pointer from fp-16, repeat. Here is what it found in case 0 (gdb):
bttest's kernel stack (KSTACK(2), one page)
0x3fffffa000 top = usertrap's fp record: ra 0x3ffffff09c, s0 0x3fd0
0x3fffff9fe0 syscall's fp record: ra 0x80002736, s0 0x3fffffa000
0x3fffff9fc0 sys_kbacktrace's fp record: ra 0x800029f2, s0 0x3fffff9fe0
0x3fffff9f90 backtrace's fp record: ra 0x80002c46, s0 0x3fffff9fc0
Three iterations print 0x80002c46, 0x800029f2 and 0x80002736; then fp is
0x3fffffa000, which equals top, and the loop ends without reading usertrap’s
record. Its contents are the subject of the next step: they are not kernel frames.
top is PGROUNDUP(fp) of the first fp: kernel stacks are exactly one page at
page-aligned addresses (proc_mapstacks), and backtrace’s own frame is strictly
inside the page, so the next page boundary is the top. The prev <= fp test is the
second guard: callers’ frames are always higher on a downward-growing stack, so a
saved frame pointer that is not higher means the chain is broken, and the walk stops
rather than follow it. A panic is exactly when the chain may be broken.
The function goes in printk.c because it prints and because panic will call it,
and its prototype in kernel/defs.h.
csrw satp (kernel/trampoline.S:92) made the kernel stack loaded on line 76 usableStep 4 of 16 · commit 2: Add backtrace() that walks the frame pointers
Why must the walk stop before usertrap’s record? Because of how usertrap is
entered. Earlier in this same system call, uservec loaded sp with the empty
kernel stack’s top (line 76), switched to the kernel page table (line 92), and here
jumps to usertrap with jalr t0. That jalr sets ra to the next instruction,
0x3ffffff09c (the trampoline page runs at TRAMPOLINE), and nothing in uservec
writes s0: it still holds the user program’s frame pointer.
So usertrap’s prologue saves ra = 0x3ffffff09c and “the caller’s s0” =
0x3fd0, an address in bttest’s user stack. The return address is real
(usertrap does return here, and uservec falls into userret), but there is no
kernel frame above it. Following 0x3fd0 means loading from 0x3fc8 under the
kernel page table, which maps nothing there: a kernel page fault (clinic 2 shows the
recursion that follows).
The frame chain ends exactly where the kernel stack does, at 0x3fffffa000. That is
why a stack-top bound is not just a safety net: it is the only way the walk can know
where the kernel’s chain stops.
kernel/sysproc.cStep 5 of 16 · commit 3: Add the kbacktrace system call
A user program cannot call backtrace(), but it can ask the kernel to. This commit
adds the system call kbacktrace(where) with the full registration that lab 1
(trace) walks through: SYS_kbacktrace (23) in kernel/syscall.h, entry("kbacktrace") in
user/usys.pl, the prototype in user/user.h, and the table entry in
kernel/syscall.c. For now only where == 0 does something.
argint fetches where from the trapframe, and backtrace() walks the stack it is
on: usertrap, syscall, sys_kbacktrace, then its own frame. This is the simplest
case, and the one to get right first: one stack, no trap in the middle, a chain of
three callers.
The recorded output of case 0, on hart 2:
backtrace:
0x0000000080002c46
0x00000000800029f2
0x0000000080002736
kernel/syscall.cStep 6 of 16 · commit 3: Add the kbacktrace system call
The diff is the table entry for 23 (line 134). The interesting line for this step is
148: the call through the table. The second address of case 0, 0x800029f2, is the
return address of that call, and on the host:
$ ${TOOLPREFIX}addr2line -e kernel/kernel -f -p 0x800029f1
syscall at ./kernel/syscall.c:148
Look up the address minus one. A return address is the instruction after the call,
and with -O that can belong to another line: 0x80002736 (in usertrap) gives
trap.c:88 as printed but trap.c:75, the syscall() call, minus one. The worst case
is case 2’s 0x80000f66, which gives main.c:14 (consoleinit()), because main’s
last instruction is the call to scheduler on line 44, and the compiler placed the
code of the cpuid() == 0 branch right after it. Minus one always lands inside the call
instruction (4 bytes for jal, 2 for c.jalr).
The kernel needs no symbol table at run time for any of this: kernel/kernel on the
host has them, from -ggdb.
kernel/sysproc.cStep 7 of 16 · commit 4: Take a backtrace from a timer interrupt in the kernel
Case 1 needs a timer interrupt to arrive while a system call is running, and the walk
to start inside the interrupt handler. sys_kbacktrace records a request, its own pid,
in a global btwant (declared volatile in trap.c, so that the loop reloads it),
and spins until the request is gone.
The spin works only because interrupts are on: usertrap turned them on before
calling syscall (kernel/trap.c:66), and nothing here takes a spinlock. The
next timer interrupt on hart 2 (within a tenth of a second) lands somewhere in this
loop. In the recorded run (of the finished branch, where the loop is three lines
lower) it struck at sepc 0x80002c64, inside the loop.
Only bttest can match its own pid, and a process runs on one hart at a time, so in
this commit a plain store can clear the request. Case 2 will change that.
Step 8 of 16 · commit 4: Take a backtrace from a timer interrupt in the kernel
The timer interrupt traps to kernelvec, on the stack the hart is already using:
xv6 has no interrupt stack (The stacks of xv6). Line 14 moves sp down 256
bytes, from 0x3fffff9f90 to 0x3fffff9e90, and the stores save ra, gp and the
t and a registers: the caller-saved ones, which kerneltrap may destroy.
What it does not do matters for the walk. It does not save s0 (callee-saved: the
C code will preserve it), and it builds no record. So when kerneltrap's prologue
saves “the caller’s s0”, it saves sys_kbacktrace’s frame pointer, 0x3fffff9fc0,
and the chain jumps straight over these 256 bytes to the interrupted function’s
record. The only trace kernelvec leaves in the chain is kerneltrap’s return
address, 0x800057e8, the instruction after call kerneltrap on line 38.
The ra saved at line 17 is the interrupted code’s ra register, not a return
address of this frame; the walk never looks at it.
kernel/trap.cStep 9 of 16 · commit 4: Take a backtrace from a timer interrupt in the kernel
devintr returned 2 (the timer), the current process is bttest, and btwant
holds its pid. The request is cleared and the walk runs, from inside the interrupt
handler, with interrupts off and no lock held (gdb: noff 0). Recorded:
fp function ra in its record saved s0
0x3fffffa000 usertrap 0x3ffffff09c 0x3fd0
0x3fffff9fe0 syscall 0x80002736 (usertrap) 0x3fffffa000
0x3fffff9fc0 sys_kbacktrace 0x800029f2 (syscall) 0x3fffff9fe0
kernelvec's 256 bytes: no record
0x3fffff9e90 kerneltrap 0x800057e8 (kernelvec) 0x3fffff9fc0
0x3fffff9e60 backtrace 0x80002862 (kerneltrap) 0x3fffff9e90
The console showed 0x80002862, 0x800057e8, 0x800029f2, 0x80002736:
kerneltrap, kernelvec, syscall, usertrap. sys_kbacktrace is missing.
Each line is the return address in a frame’s record, which names that frame’s
caller; the interrupted function was not called by kernelvec, so no record
points into it. Where it was interrupted is sepc (0x80002c64), which
kerneltrap holds in a register and never prints for an interrupt. When a fault
panics through here, the scause=... sepc=... line printed just before the panic is
the only place the faulting function is named.
PGROUNDUP(0x3fffff9e60) is still 0x3fffffa000: a trap in the middle of a kernel
stack does not change its top.
stack0top of hart 1’s slice: 0x800098d0 in this buildadd sp, sp, a0 (kernel/entry.S:17)Step 10 of 16 · commit 5: Find the top of the stack0 slice as well as a kernel stack
Now the other kind of stack. At power-on, every hart computes its own stack from
stack0: sp = stack0 + (hartid + 1) * 4096. stack0 is declared in
kernel/start.c:11 as __attribute__((aligned(16))) char stack0[4096 * NCPU]:
aligned to 16 bytes, not to a page. In the unmodified kernel it is at 0x80007890; in
this branch’s build the new code moved it to 0x800078d0. So the three slices in use
end at 0x800088d0, 0x800098d0 and 0x8000a8d0, all in the middle of pages.
This stack becomes hart 1’s scheduler stack when main calls scheduler,
with no switch (The stacks of xv6). Two frames sit at its top forever:
start’s, whose record holds the return address of call start (line 19, so
0x8000001a, spin) and whatever s0 held at power-on (0, recorded); and
main’s, below it.
PGROUNDUP of a scheduler-stack address is therefore not the top. On hart 1, a walk
starting at 0x80009720 would stop at 0x8000a000, 1840 bytes too high, past
start’s record; one starting below 0x80009000 would stop there, in the middle of
the slice. This commit’s other change, in the next step, fixes the bound.
stack0hart 1’s slice of stack0, kernelvec frame on top; backtrace’s fp 0x80009720was: boot stackkernel/printk.cStep 11 of 16 · commit 5: Find the top of the stack0 slice as well as a kernel stack
stacktop(fp) decides by address. Inside stack0’s NCPU * 4096 bytes, the slice is
(fp - base) / 4096, and its top is one slice above that: for hart 1’s 0x80009720,
0x800078d0 + 2 * 4096 = 0x800098d0. Inside the 64 kernel stacks (from KSTACK(63) up
to TRAMPOLINE), the next page boundary. Anywhere else, 0, and backtrace prints a
warning instead of walking: clinic 4 shows that message saving a kernel built without
frame pointers.
The division is safe because the first fp is always strictly inside its slice:
backtrace is called by a function with a frame of its own, so its frame pointer is
below the caller’s, which is at most the top. (Only start’s frame pointer equals a
slice’s top, and the walk never starts there.)
The state is from the moment this code is first used, in case 2 in the next commit:
hart 1, idle, on its scheduler stack, inside the timer interrupt. gdb recorded
noff 0 and SIE 0 there. There is no current process (cpus[1].proc = 0).
stack0kernelvec frame below scheduler’s; kerneltrap’s fp 0x80009750kernel/trap.cStep 12 of 16 · commit 6: Take a backtrace on a scheduler stack
Case 2 asks for a backtrace from any idle hart: btwant = -1. Every hart in
scheduler takes timer interrupts in the intr_on(); intr_off(); window
(kernel/proc.c:441); in the recorded run hart 1 took this one at sepc
0x80001ed6, the csrci of intr_off right after intr_on. With no current process,
want is -1.
Several idle harts can see -1 at once. The test and the write must be one atomic
step: __sync_bool_compare_and_swap(&btwant, want, -2) succeeds on exactly one hart
(it compiles to an lr.w/sc.w loop). The winner prints and only then writes 0. The
value -2, “being printed”, keeps the requester waiting until the last line is out.
What the walk found on hart 1:
hart 1's slice of stack0
0x800098d0 top = start's fp record: ra 0x8000001a (spin), s0 0x0
0x800098c0 main's fp record: ra 0x800000c2 (start), s0 0x800098d0
0x800098b0 scheduler's fp record: ra 0x80000f66 (main), s0 0x800098c0
kernelvec's 256 bytes
0x80009750 kerneltrap's fp record: ra 0x800057e8, s0 0x800098b0
0x80009720 backtrace's fp record: ra 0x80002862, s0 0x80009750
Printed: 0x80002862, 0x800057e8, 0x80000f66, 0x800000c2, then fp reached
0x800098d0 = stacktop and the walk stopped, before start’s record. scheduler
is missing for the same reason as sys_kbacktrace in case 1: it was interrupted.
tickslockkernel/sysproc.cStep 13 of 16 · commit 6: Take a backtrace on a scheduler stack
For case 2 the system call must wait while some other hart prints, so spinning would
be wrong: the requester would keep its own hart busy. It sleeps on ticks, exactly as
sys_pause does, and re-checks btwant each time clockintr wakes it (once per
tick). Recorded: bttest armed the request on hart 0 (btwant was 0 just before).
At the focus lines it holds tickslock: noff is 1, and intena is 1 because
interrupts were on when the system call took the lock. It releases the lock before
sleep() (Locks and interrupt state); clinic 5 is what happens otherwise.
After 10 ticks with no taker, the call withdraws its request with another
compare-and-swap, from -1 to 0. If a hart took it in the meantime (-2), the swap fails
and the loop keeps waiting for 0. A version that cleared the request
before printing would be wrong: reasoning from the code, the woken bttest could return and
print its next line in the middle of the backtrace (think question 7 quotes a run).
stack0start’s 16-byte frame at the top of hart 1’s sliceStep 14 of 16 · commit 6: Take a backtrace on a scheduler stack
Case 2’s last line, 0x800000c2, comes from main’s record. But start never called
main: it reaches it with mret (line 51), which sets the mode and the pc and touches
no general register. main’s prologue then saves whatever ra holds, and the last
thing that wrote ra was the jal timerinit on line 44: 0x800000c2 is the
instruction after it (addr2line of 0x800000c1: start.c:44).
So every backtrace that reaches the top of a scheduler stack ends with this line, a
leftover from boot. Above it is start’s record: return address 0x8000001a (spin,
after call start in _entry) and the s0 of power-on, 0. The walk stops at
start’s frame pointer, 0x800098d0, before reading either, which is right: neither
describes a call.
The state here is the boot-time moment that created the fossil, in machine mode with paging off, on what is still hart 1’s boot stack.
tickslockbttest's p->lockkernel/printk.cStep 15 of 16 · commit 7: Print a backtrace when the kernel panics
The one-line commit the lab is named after. panic prints its message, then the
chain, then sets panicked. The order is forced by uartputc_sync: once panicked
is set, the next character printed by any hart spins forever, this one included
(kernel/uart.c:108). A copy with the two lines swapped printed panic: sched locks and nothing more.
panicking, set first, makes printk skip pr.lock, so a panic on a hart that
already holds it (inside printk) still gets its backtrace out. The cost: two harts
panicking at once interleave character by character (clinic 6).
The state shown is a real panic: clinic 5’s bug (sleeping with tickslock held),
caught with gdb on hart 1 with noff 2 and intena 1. Its backtrace, symbolized,
reads panic, sched (proc.c:488), sleep (proc.c:569), sys_kbacktrace
(sysproc.c:153), syscall, usertrap, which names the faulty line directly. The
walk is safe to run here because it never leaves the stack it started on: every load is
at fp - 8 or fp - 16 with fp strictly inside that stack. A walker that can fault
turns one panic into a recursion (clinics 2 and 3).
user/bttest.cStep 16 of 16 · commit 8: Add bttest
The test asks for the three backtraces in turn and checks what a program can see: the
return values 0, 0, 0 and -1 for an unknown where. bttest N runs only case N,
which is how the clinic runs looked at one stack at a time.
It does not, and cannot, check the addresses: they go to the console, which a program cannot read, and their meaning depends on the build. So the last line says plainly that the addresses must be symbolized on the host, instead of claiming that all is well. The verify section below does that for the recorded run.
$U/_bttest is added to UPROGS in the Makefile, so mkfs puts it in fs.img.
Lab 2 · wrap-up
On the branch, on three harts, before usertests (the gdb run that the reveal follows
printed exactly the same lines):
$ bttest
bttest: from a system call, on this process's kernel stack:
backtrace:
0x0000000080002c46
0x00000000800029f2
0x0000000080002736
bttest: kbacktrace(0) returned 0: OK
bttest: from a timer interrupt during a system call:
backtrace:
0x0000000080002862
0x00000000800057e8
0x00000000800029f2
0x0000000080002736
bttest: kbacktrace(1) returned 0: OK
bttest: from a timer interrupt on a scheduler stack:
backtrace:
0x0000000080002862
0x00000000800057e8
0x0000000080000f66
0x00000000800000c2
bttest: kbacktrace(2) returned 0: OK
bttest: kbacktrace(3) returned -1: OK
bttest: 4 checks OK; the addresses can only be checked by symbolizing them on the host with addr2line
Symbolized on the host with ${TOOLPREFIX}addr2line -e kernel/kernel -f -p, each address
minus one:
| case | lines |
|---|---|
| 0: system call | sys_kbacktrace sysproc.c:128, syscall syscall.c:148, usertrap trap.c:75 |
| 1: across a trap | kerneltrap trap.c:169, kernelvec kernelvec.S:38, syscall syscall.c:148, usertrap trap.c:75 |
| 2: scheduler stack | kerneltrap trap.c:169, kernelvec kernelvec.S:38, main main.c:44, start start.c:44 |
Each is the expected chain: case 0 stops at the top of the kernel stack; case 1 crosses
the kernelvec frame and (as it must) has no line for the interrupted sys_kbacktrace;
case 2 stops at the top of the idle hart’s stack0 slice, after main and the boot-time
return address into start, without reading start’s record.
The rest of the kernel is unharmed, in the same boot:
$ usertests -q
usertests starting
[...]
ALL TESTS PASSED
bttest run again after usertests printed the same eleven addresses and
4 checks OK. No other program calls kbacktrace, so the only cost to an ordinary
kernel is one load of btwant per timer interrupt taken in the kernel.
Keys: ← → step · Home start