Step 1 of 17 · commit 1: Add the trace system call number and user stub

A number both sides agree on

The story for this tour: you type trace 2147483647 sh at a fresh shell, then echo hi, then Ctrl-D. That run was recorded on three harts. The trace program is pid 3, running on hart 1; it becomes sh by exec, forks echo as pid 4, and the first shell (pid 2) and init (pid 1) are asleep in wait meanwhile.

The first commit adds the number. SYS_trace is 23, the next free one. This header is the only thing the kernel and user programs share about system calls: the kernel’s table is indexed by these constants, and the generated user/usys.S includes this same file, so its li a7, SYS_trace assembles to li a7,23. The same commit adds int trace(int); to user/user.h so that C programs can call it.

At this commit, a call to trace gets as far as syscall and no further: there is no handler yet.

Step 2 of 17 · commit 1: Add the trace system call number and user stub

The stub that makes the trap

entry("trace") makes this Perl script emit three instructions into user/usys.S:

trace:
 li a7, SYS_trace
 ecall
 ret

In the built trace program the stub is at address 0x3c0, and its first instruction is the 2-byte li a7,23. When main calls trace(2147483647), the calling convention has already put the mask in a0; the stub adds the number in a7 and executes ecall. From here the path is the one Tour 5: Life of a system call follows in detail: uservec saves every register in the trapframe, switches to the kernel stack and page table, and jumps to usertrap.

Forget this line and the C compiler still accepts trace(...) (the prototype is in user.h), but the linker finds no trace symbol anywhere (clinic 4).

Step 3 of 17 · commit 1: Add the trace system call number and user stub

usertrap hands the call to syscall()

Nothing in the trap path changes for a new system call. usertrap saw scause 8, added 4 to the saved epc so the process will resume after the ecall, and turned interrupts back on (line 66). Then it calls syscall.

That intr_on matters for everything trace adds. From here on, a timer interrupt can arrive between any two instructions, and kerneltrap may yield: the process can stop in the middle of sys_trace or the print, and continue on hart 0 or hart 2. So any state the new code uses must belong to the process (its struct proc, its trapframe), never to the hart.

The stack is trace’s kernel stack. It was empty when the trap arrived (every return to user space resets kernel_sp to the top), and uservec loaded it at kernel/trampoline.S:76; see The stacks of xv6.

Step 4 of 17 · commit 1: Add the trace system call number and user stub

Without a table entry, 23 is unknown

syscall reads the number from the saved a7: 23. At commit 1, syscalls[] has 23 slots (0 to 22), so num < NELEM(syscalls) fails, and the else branch prints the message and stores -1 in the saved a0. (The trace command does not exist yet at this commit. A run of a commit-1 kernel with a tiny test program called t1 that calls trace(5) printed 3 t1: unknown sys call 23, and the program saw -1.)

This is the kernel’s only defence against a bad number, and it is enough: a program can put anything in a7, but the kernel only ever indexes the table after this range check and the null check. Notice also line 146: whatever a handler returns goes into p->trapframe->a0. That one line is how every system call returns a value, and the print we add later must come after it.

Step 5 of 17 · commit 2: Add a trace mask to struct proc and sys_trace

The mask is private to the process

The mask is state of one process, so it lives in struct proc. The struct is divided by lock: fields that other processes or interrupt handlers read or write (state, chan, killed, xstate, pid) need p->lock; parent needs wait_lock; the rest are “private to the process”: only the process itself uses them, so no lock is needed.

tracemask goes in the private section, next to name. Only two pieces of code ever touch a process’s own mask, sys_trace and syscall(), and both run as that process. An xv6 process has one thread and runs on at most one hart at a time, so there is never a second party. The exceptions are kfork (which writes a child’s mask before the child can run) and freeproc (which clears it, under p->lock, when the process is gone), both coming up.

The state shown is for the moment sys_trace uses the field, two steps from now.

Step 6 of 17 · commit 2: Add a trace mask to struct proc and sys_trace

sys_trace swaps the mask

The handler is four lines. argint fetches argument 0, the mask, from the trapframe; the old mask is saved and the new one installed; the old one is returned, and syscall stores it in p->trapframe->a0.

Returning the previous mask costs nothing and makes the feature testable: a program cannot read the console, but it can call trace(m) twice and check that the second call returns m. tracetest is built on that.

Compare sys_uptime just above it: it takes tickslock, because ticks is shared with the timer interrupt on hart 0. sys_trace takes no lock, for the reason in the last step. If the timer fires between lines 123 and 124 and the process resumes on hart 2, nothing is lost: the values are in sys_trace’s frame on the process’s kernel stack, which moves with it.

Step 7 of 17 · commit 2: Add a trace mask to struct proc and sys_trace

argint reads the saved a0

argint is a one-line wrapper around argraw, which picks the saved register out of the trapframe: argument 0 is p->trapframe->a0, the value uservec saved from the user’s a0, here 2147483647. The assignment to int keeps the low 32 bits.

No check is needed, because every int is a meaningful mask: bits that match no system call are simply never tested. That is a luxury. Look at argaddr just below: it fetches a pointer the same way and, as its comment says, does not check it. A user pointer means something only in the user’s page table; the kernel copies through it with copyin or copyout, which translate and check every page (Tour 28: Crossing the user/kernel boundary in memory). trace takes an int precisely so that none of that is needed.

Step 8 of 17 · commit 2: Add a trace mask to struct proc and sys_trace

Registering the handler

Two lines make the kernel side reachable: an extern prototype (the function is defined in sysproc.c) and [SYS_trace] = sys_trace in the table of function pointers.

The table uses designated initializers: the index is written out, so the order of the lines does not matter, an unused slot (0) is a null pointer, and the array’s size is the highest index plus one, now 24. The range check on line 145 therefore lets 23 through, and line 148 calls sys_trace. The trace call now returns the old mask (0) instead of -1, with no message.

Step 9 of 17 · commit 2: Add a trace mask to struct proc and sys_trace

freeproc clears the mask

Jump ahead in the story: echo (pid 4) has exited, and sh (pid 3, the old trace process) reaps it in kwait. kwait holds wait_lock and the child’s p->lock when it calls freeproc, so noff is 2 and interrupts are off; intena is 1 because the first acquire happened with interrupts on, inside a system call.

freeproc returns the slot to UNUSED and resets its fields, and the commit adds the mask to the list. Strictly, nothing at this commit needs it: allocproc has two callers, kfork, which will overwrite the field, and userinit, which runs at boot when every slot is zero. But a field left behind is a trap for the next person who calls allocproc: a brand-new process would start out traced by a stranger’s mask.

Step 10 of 17 · commit 3: Inherit the trace mask in kfork

kfork copies the mask while it holds the child's lock

sh has read echo hi and forks. allocproc found an UNUSED slot and returned it with np->lock held: one spinlock, noff 1, interrupts off. kfork keeps it through the copying (uvmcopy, the trapframe, filedup, idup, the name) and now the mask, then releases it on line 298.

Reading p->tracemask needs no lock: p is sh, the process running this code, and the field is private to it. Writing np->tracemask is safe for two reasons at once: the child is still USED, not RUNNABLE, so no scheduler will run it, and its lock is held anyway. This is exactly the reasoning that lets kfork set np->sz and np->ofile[] here.

exec needs no change at all. kexec builds a new address space but keeps the struct proc, so the mask set by trace before exec("sh", ...) is still there when sh starts, and here it passes to echo.

Step 11 of 17 · commit 4: Print traced system calls as they return

A names table indexed like the handler table

The output needs read, not 5. The names table uses the same designated initializers as syscalls[], so name i is the name of system call i by construction, slot 0 is empty in both, and both arrays have 24 slots. The range check in syscall protects both indexings.

Written as a plain list starting with "fork", the table would be one slot early everywhere and one slot short at the end. Clinic 3 ran that mistake: read printed as kill, and the first lookup of number 23 read the 8 bytes after the array as a pointer and brought the kernel down.

Both the strings and, in this build, the array itself land in .rodata (syscallnames at 0x80007908, right after syscalls): the compiler sees that nothing writes the array, even though it is not declared const. Nothing ever writes either, so three harts can read them with no lock.

Step 12 of 17 · commit 4: Print traced system calls as they return

Print after the call, when the result is known

The heart of the feature: one if guarding a printk, right after line 177. When the handler returns, its result is in p->trapframe->a0; if bit num of the mask is set, one printk reports pid, name and that value. In the recorded run, sh reading echo hi one byte at a time printed 3: syscall read -> 1 eight times, then 3: syscall fork -> 4.

Why here and nowhere else: this is the one function every system call passes through, and line 177 is the first moment the return value exists. One line earlier, a0 still holds the first argument (clinic 2 printed read -> 3, the descriptor).

Three consequences of “after”: a successful exit prints nothing, because kexit never returns here; trace traces itself under the new mask; and a call that slept (a read from the console, a wait) prints when it finally returns, perhaps on a different hart from the one it started on. p stays correct across that move, because it names the process, not the hart.

%ld prints the 64-bit a0 as signed, so -1 reads as -1; 1 << num is an int shift, fine for numbers below 31.

Step 13 of 17 · commit 4: Print traced system calls as they return

Inside printk, pr.lock keeps the line whole

printk acquires pr.lock for the whole line. acquire first called push_off: interrupts are off and noff is 1, with intena 1 because they were on when the system call started. Each character goes through consputc to uartputc_sync, which pushes one level deeper (noff 2) and spins until the UART can take the byte. So a trace line of about 25 characters means about 25 waits on a device register with interrupts off; at the 38,400 baud that uartinit programs, a real UART would need about 6.5 milliseconds for it.

What the lock guarantees: no other printk (another trace line, a usertrap message from another hart) can put a character between these characters. What it does not guarantee: user output does not take pr.lock. See the next box.

Step 14 of 17 · commit 4: Print traced system calls as they return

The value reaches user space in a0

The way back is unchanged by this lab, and it is where the printed value goes next. usertrap called prepare_return (which turned interrupts off), then returned the user satp in a0 to uservec’s jalr (kernel/trampoline.S:98), which falls straight into userret. userret installed that satp at line 111: the user page table is now in use.

userret reloads every register from the trapframe, and a0 last (line 149), because a0 held the trapframe’s address until then. The value it loads is the one line 177 of syscall.c stored and the trace line printed. So the number in the trace line is, by construction, exactly what the program receives: read returns 1 in a0, gets stores the byte, and the shell goes on reading.

Here sp holds sh’s user stack pointer again (since line 118), but the hart is still in supervisor mode, which cannot use user pages: no usable stack until sret (The stacks of xv6).

Step 15 of 17 · commit 4: Print traced system calls as they return

The child returns from fork without syscall()

Why does the recorded run show 3: syscall fork -> 4 and no line for the child? Here, on hart 2 in this story, the scheduler picked echo (pid 4) and swtch landed on the ra that allocproc set: forkret, on a fresh, empty kernel stack. forkret released the p->lock the scheduler handed over; that lock was acquired with interrupts off (intena 0), so they stay off. It then goes straight to prepare_return and userret.

The child never made a system call: it has no ecall, no usertrap, no syscall() frame. Its “return value” 0 was written into its copy of the trapframe by kfork. So there is no point at which the trace check could run for it. Its first traced line is its own next call: 4: syscall sbrk -> 20480 (the shell’s child allocates memory while parsing the command), then 4: syscall exec -> 2.

Step 16 of 17 · commit 5: Add the trace user program

The trace command is set-mask-then-exec

The command is ten lines of logic, and all the work is done by where the mask lives. trace(atoi(argv[1])) sets the mask of this process; exec(argv[2], &argv[2]) replaces this process’s program but keeps its struct proc, mask included. So the command runs traced from its first instruction, and so does every child it forks.

If exec returns at all, it failed, so the program reports it and exits. atoi accepts only decimal digits, which is why the usage check looks at the first character; 2147483647 (bits 0 to 30) is the way to say “everything”.

In the recorded run, the first two lines come from this program before and during the exec: 3: syscall trace -> 0 (the trace bit is set, and the check runs after the new mask is installed) and 3: syscall exec -> 1, printed by the kernel as exec returns, when the process’s memory already holds sh (which has not run an instruction yet) and the return value is its argc, 1.

Step 17 of 17 · commit 6: Add tracetest

The test checks what a program can see

A user program cannot read the console, so tracetest tests through trace’s return value. Lines 64 to 69: set a mask and read it back; fork a child that reads it with trace(0) and reports through its exit status; check the child’s trace(0) did not touch the parent; fork a child that execs tracetest exec, which checks the mask and exits 0 or 1. Each check prints OK or FAIL.

Lines 74 to 89 cover the printing, checked by eye: only getpid (bit 11) is traced, and while the mask is set the parent calls getpid, uptime, fork, wait and finally trace(0) (bit 23 is clear), and the child calls getpid and exit; only the two getpids print. The markers are printed outside that window. The parent waits for the child before trace(0), so the order is fixed. Then it prints the lines that should have appeared.

$U/_trace and $U/_tracetest are in UPROGS, so mkfs puts both in fs.img.