Extension labs · lab 1 · The system-call and trap path · ★☆☆☆☆
trace: logging system calls
You add a new system call, trace(mask), and a command, trace MASK command args....
While a process’s mask has bit i set, the kernel prints one line each time system call
number i returns: 3: syscall read -> 1023. Children made by fork inherit the mask, and
exec keeps it, so trace 32 grep hello README shows every read that grep makes.
The feature is small (about fifty lines of kernel code, half of them a table of names), but building it walks you through
every layer a system call crosses, from the three-instruction user stub to the
trapframe and back. You will see every place a new system call must be registered and
why each one exists, where per-process state lives and what fork copies under which lock,
and why the only place that can print the return value is right after the call in
syscall. On three harts, you will also see that printk’s lock keeps trace
lines whole with respect to each other, but not with respect to a user program’s output.
The full path of a system call: the system call stub puts the number in a7, ecall traps, uservec saves every register in the trapframe, usertrap calls syscall, which indexes syscalls[], and the return value travels back to user space through the saved a0.
Every place a new system call must be registered (the number, the stub generator, the user prototype, the kernel table and its prototype) and what breaks, at compile time, link time or run time, when one is missing.
Where per-process state lives in struct proc, which fields need p->lock and which are private to the process, and what kfork copies while it holds the child’s lock.
Why a forked child never passes through syscall on its way back from fork, and why a successful exit never returns to it.
What pr.lock in printk guarantees on three harts (whole lines among kernel messages) and what it does not (it does not exclude user output written through uartwrite).
How argint reads an integer argument from the trapframe, and why pointer arguments need copyin instead.
git clone https://github.com/ShowMeTheStack/xv6-riscv-labs
cd xv6-riscv-labs
git checkout -b my-trace 06aad25 # start your own
git diff 06aad25 origin/ext/01-trace # only when you want the answer
1. The spec
The system call.int trace(int mask) sets the calling process’s trace mask and
returns the previous mask. Bit i of the mask enables tracing of system call number i
(the numbers in kernel/syscall.h; trace itself gets number 23). It never fails.
What gets printed. When a traced system call returns to the process, the kernel prints
one line on the console:
<pid>: syscall <name> -> <return value>
The value is printed as a signed 64-bit number, so a failure shows as -1. A system call
that never returns (a successful exit) prints nothing.
Inheritance. A child created by fork starts with its parent’s mask. exec keeps the
mask. A child changing its own mask does not change its parent’s.
The command.trace MASK command args... sets the mask, then execs the command:
(32 is 1 << 5, and SYS_read is 5. 2147483647 sets every bit up to 30 and traces
everything.)
The test.tracetest checks, and prints OK or FAIL for each: that trace returns
the previous mask, that fork copies the mask to the child, that a child’s change leaves
the parent alone, and that exec keeps the mask. A program cannot read the console, so the
printing itself is checked by eye: between a begin and an end marker only getpid is
traced, the parent and a child each call getpid once (plus untraced uptime, fork and
wait calls, and the child’s exit; the markers themselves are printed outside that
window), and the test then prints the two lines that should have
appeared:
tracetest: begin
3: syscall getpid -> 3
6: syscall getpid -> 6
tracetest: end
tracetest: expected between the markers, and nothing else:
3: syscall getpid -> 3
6: syscall getpid -> 6
tracetest: 4 checks OK; now compare the lines between the markers by eye
The last line deliberately does not claim the printing is right: only your comparison
can say that.
Constraints. Untraced processes must behave exactly as before, and usertests -q must
still print ALL TESTS PASSED on three harts. Do not change any existing system call’s
number.
2. Think first
Answer each question in your head (or on paper) before opening a hint. Hints get more specific; the reference answer comes last.
1Where must a new system call be registered?
List every file you must touch before a user program can call trace(32) and reach a
kernel function sys_trace. For each, say what would go wrong without it: a compile
error, a link error, or a failure at run time.
Hint 1.
Follow write through the tree: grep for SYS_write, for sys_write and for
write in user/usys.pl and user/user.h. Then look at how the Makefile builds
user/usys.S and fs.img.
Hint 2.
The kernel and user programs are compiled separately and share nothing at run time
except the number in a7. So the number must come from one header both sides
include, and each side needs its own declaration of the function it uses.
Hint 3.
Five places in the source, plus the Makefile for the new user program: a #define
in kernel/syscall.h; an entry("trace") in user/usys.pl; a prototype in
user/user.h; an extern prototype and a [SYS_trace] = sys_trace entry in
kernel/syscall.c; and the function itself, in kernel/sysproc.c.
The reference design
Where
What it provides
Without it
kernel/syscall.h: #define SYS_trace 23
the one number both sides agree on; the kernel table and the generated stub both include this header
the kernel table and the stub both use the name SYS_trace, so neither builds
user/usys.pl: entry("trace")
generates the stub trace: li a7, SYS_trace; ecall; ret in user/usys.S
the C compiler is happy (user.h declares trace), but the linker (ld) finds no symbol trace: undefined reference to 'trace' (clinic 4)
user/user.h: int trace(int);
tells the C compiler the stub’s type
-Werror turns the implicit declaration into a compile error
kernel/syscall.c: extern uint64 sys_trace(void);
lets the table refer to a function defined in another file
compile error in the table
kernel/syscall.c: [SYS_trace] = sys_trace,
maps 23 to the handler; syscall dispatches only through this table
builds fine, but every call prints unknown sys call 23 and returns -1
kernel/sysproc.c: sys_trace
the handler
link error in the kernel
Makefile: $U/_trace in UPROGS
builds the program and puts it in fs.img
exec trace failed from the shell (clinic 6)
The table uses designated initializers ([SYS_trace] =),
so the order of the lines does not matter and a missing entry is a null pointer that
syscall checks for (kernel/syscall.c:143). The user side never sees the kernel’s
function names at all: the only thing that crosses the boundary is the number in a7.
Check yourself
1warm-upMatch the pairs
Match each change to what it provides.
2How do the number and the mask reach sys_trace?
The trace program calls trace(32). Trace the two values, 23 and 32, from that call
to the moment sys_trace holds 32 in a local variable. Name the register each value
travels in, where it is saved, and who reads it back.
ecall changes no general-purpose register. Whatever is in a0 and a7 at the
ecall is what the kernel sees, and it sees it in the trapframe, not in the
registers, because C code in the kernel reuses every register.
Hint 3.
a0 = 32 by the calling convention; a7 = 23 by the stub; uservec stores
both in the trapframe (offsets 112 and 168); syscall() reads trapframe->a7;
argint(0, ...) reads trapframe->a0 through argraw.
The reference design
The C call trace(32) puts 32 in a0: the first argument register.
The stub runs li a7,23 (in this build at address 0x3c0 of the program) and
ecall.
ecall switches to supervisor mode and jumps to uservec; a0 and a7 still
hold 32 and 23.
uservec saves all 31 user registers in the process’s trapframe: a0 at offset 112
(through sscratch, kernel/trampoline.S:72), a7 at offset 168. Then it
switches to the kernel stack and page table and jumps to usertrap.
usertrap sees scause 8, adds 4 to the saved epc, turns interrupts on, and calls
syscall.
syscall() reads num = p->trapframe->a7 (kernel/syscall.c:142), checks it is
in range and calls syscalls[23], which is sys_trace.
sys_trace calls argint(0, &mask), which reads p->trapframe->a0 through
argraw: 32.
The way back is the mirror image: syscall() stores the result in trapframe->a0,
and userret reloads a0 from the trapframe last (kernel/trampoline.S:149), so
trace() returns that value in a0.
Check yourself
1solidPut in order
Put the steps of trace(32) in the order they happen.
argint reads trapframe->a0
The compiler’s call puts 32 in a0
usertrap adds 4 to the saved epc and turns interrupts on
uservec saves a0 and a7 in the trapframe
ecall: the hart enters supervisor mode at uservec
The stub executes li a7,23
syscall() reads trapframe->a7 and calls syscalls[23]
2solidFill in the machine state
sys_trace is running its first line, argint(0, &mask). Fill in the machine state
of the hart running it.
3Why is argint enough here?
sys_trace reads its argument with one call to argint and never checks it. Is that
safe? What would you have to do differently if the argument were a pointer, say
trace(int *mask)?
What could go wrong with an int value? With a pointer value, whose page table
gives it meaning, and which page table is installed while sys_trace runs?
Hint 3.
For an int, nothing to check. For a pointer, fetch it with argaddr and copy the
value with copyin(p->pagetable, ...), which checks the address against the process’s
page table and returns -1 instead of faulting.
The reference design
argint copies the saved a0 out of the trapframe (kernel/syscall.c:58). The
trapframe is kernel memory that uservec filled, so reading it is always safe, and any
32-bit value is a valid mask: bit 30, for example, matches no system call and is never
tested. So sys_trace needs no check and cannot fail.
A pointer argument is a different matter. The value in a0 would be a user virtual
address: meaningless under the kernel page table, and possibly pointing at nothing or
at the guard page. The kernel never dereferences it. It fetches it with argaddr and
copies through copyin, which translates the address with the process’s page table
(refusing pages without PTE_U), allocates a lazily allocated page only if the address
is below the process’s size, and otherwise returns -1. See Tour 6: System-call arguments and user pointers and Tour 28: Crossing the user/kernel boundary in memory.
Check yourself
1solidChoose one
Suppose trace took int *mask and sys_trace did argaddr(0, &a); mask = *(int *)a;.
What is wrong?
4Where does the mask live, and who may touch it?
The mask belongs to a process. Which structure gets the new field, in which section,
and which lock (if any) must be held to read or write it? Consider the three places
that will touch it: sys_trace, syscall() and kfork.
Hint 1.
Read the comments inside struct proc in kernel/proc.h: the fields are grouped
by the lock that protects them.
Hint 2.
A field needs a lock only if two threads can touch it at the same time. xv6
processes have one thread each. Who else, apart from the process itself, could
ever read or write its mask?
Hint 3.
Only the process itself reads and writes its own mask, so it goes in the “private to
the process” section with sz, ofile and name, with no lock. The one exception,
kfork writing the child’s mask, happens before the child can run.
The reference design
Put int tracemask; in struct proc, in the section headed “these are private to the
process, so p->lock need not be held” (kernel/proc.h:95).
sys_trace and syscall() run as the process, on its kernel stack. A process runs
on one hart at a time, and nothing else reads its mask (not even procdump), so no
lock is needed. If the process is preempted and moves to another hart in between, it
still is the only thread that touches the field.
kfork reads the parent’s mask (the parent is the running process: private) and
writes the child’s. It writes it while it still holds the child’s np->lock, taken by
allocproc, and before np->state = RUNNABLE, so no scheduler can pick the child
and run it. It is the same reasoning that lets kfork write np->sz and
np->ofile[] there.
freeproc clears it with the other fields, under p->lock, when the parent reaps
the child in kwait.
Putting the field under p->lock would work too, but every syscall() would then take
and release a spinlock on the hottest path in the kernel for nothing.
Check yourself
1solidTrue or false, and why
True or false: in kfork, reading the parent’s p->tracemask must be done while
holding the parent’sp->lock.
Why?
5Where exactly do you print?
You need the system call’s number, its name and its return value. Which function is
the one place every system call passes through, and on which line must the print go
so that the return value is known?
Hint 1.
Read syscall (kernel/syscall.c:136). Every system call passes through it. Which
variable holds the number, and which one will hold the result?
Hint 2.
Before line 146 runs, p->trapframe->a0 still holds what the user put in a0: the
first argument. After it, a0 holds the result. And some calls never come back to
this line at all.
Hint 3.
Print right after line 146, inside the if, when p->tracemask & (1 << num) is
nonzero, and print p->trapframe->a0.
Before the call, a0 in the trapframe is still the user’s first argument: a file
descriptor for read, a pointer for exec (clinic 2 shows read -> 3 and
exec -> 16336).
Inside each sys_* function would mean twenty-three edits, and the handler does not
know its own number.
In usertrap after syscall() returns would work for system calls, but usertrap
also handles interrupts and faults, so it would need to remember whether this trap
was a system call.
Two consequences of “after the call”: a successful exit never prints, because
kexit never returns; and trace traces itself with the new mask, because the
check runs after sys_trace installed it. trace 8388608 echo x (bit 23) prints
trace -> 0, and trace(0) called with the trace bit set prints nothing.
%ld prints the full 64-bit a0 as a signed number, so -1 shows as -1 and an
sbrk result shows as an address. 1 << num is an int shift, fine for numbers up to
30; a kernel with more than 31 system calls would need a 64-bit mask and 1L << num.
Check yourself
1warm-upClick the line
Click the line right after which the trace check must go.
Suppose the print is placed before line 146. grep calls read(3, buf, 1023) and
the call returns 1023. What number does the trace line show after ->?
decimal, 0x hex or 0b binary
6What should fork, exec and exit do with the mask?
The spec says children inherit the mask and exec keeps it. Which functions must
change? And when a traced sh forks, how many fork lines should the trace print,
one or two? You know where the print is now (the previous question); use that.
Hint 1.
Read kfork, kexec and freeproc. Which of them builds a new struct proc,
which reuses one, and which clears one?
Hint 2.
exec replaces the memory image but not the process: the struct proc (and
everything in it) stays. A forked child returns from fork without ever having made
a system call itself.
Hint 3.
Copy the mask in kfork next to safestrcpy(np->name, ...), before release(&np->lock).
Clear it in freeproc. Leave kexec alone. The child’s first return to user space
goes through forkret, which never calls syscall().
The reference design
fork: kfork copies np->tracemask = p->tracemask while it holds the child’s
lock (before kernel/proc.c:294). The child slot came from allocproc, whose
fields were cleared by freeproc when the slot was last freed (or are zero from
boot), so without this line the child is untraced (clinic 1).
exec: nothing. kexec builds a new page table and user memory but keeps the
struct proc, so the mask survives. That is exactly what makes the trace command
work: it sets the mask, then execs the command.
exit/wait: freeproc sets tracemask = 0 with the other fields. At this
commit every caller of allocproc either copies a mask (kfork) or runs at boot,
when the table is all zeros (userinit), so this is hygiene rather than a fix, but a
future caller of allocproc would otherwise inherit a stranger’s mask.
One fork line, not two. The parent’s fork returns through syscall and prints
the child’s pid. The child never executed ecall: kfork gave it a copy of the
trapframe with a0 = 0, and allocproc gave it a fresh kernel stack and a
context whose ra is forkret, so its first swtch lands there.
forkret goes straight to prepare_return and userret. The child never
passes through syscall(), so it prints nothing.
Check yourself
1solidChoose one
A shell running with every bit of its mask set forks a child. How many lines
mention fork?
7How do you turn a number into a name?
The output needs read, not 5. Where do the names come from, and how do you make sure
name i really is system call i, even if someone later adds a number in the middle?
Hint 1.
Look at how syscalls[] is written (kernel/syscall.c:109): [SYS_fork] = sys_fork.
Hint 2.
Numbering starts at 1, not 0. A plain list {"fork", "exit", ...} puts “fork” at
index 0.
Hint 3.
Use the same designated initializers: [SYS_read] = "read". Then the index is the
constant itself, and the array has exactly as many slots as syscalls[].
With designated initializers the position in the source
does not matter; slot 0 stays empty, as in syscalls[]; and the array’s length is
SYS_trace + 1, the same as syscalls[], so the range check in syscall covers
both. A plain list starting with "fork" is off by one: read (5) prints the sixth
name, kill, and the last number indexes one slot past the end (clinic 3, which
panicked).
Check yourself
1solidChoose one
The names are written as a plain list, {"fork", "exit", "wait", "pipe", "read", "kill", ...}, in the order of syscall.h. What does trace 32 grep hello README
print?
8Three harts, one console. Will the lines come out whole?
With three harts, two traced processes can return from system calls at the same moment,
and a third process can be writing its own output. What keeps a trace line from being
mixed with another trace line? Is anything keeping it from being mixed with a user
program’s output?
pr.lock is held for a whole printk call. uartwrite holds the sleep-lock
tx_lock for at most 32 bytes at a time. The two paths share the UART but not a lock.
Hint 3.
List the lock each path holds while it writes the UART’s transmit register:
printk’s path holds ?, consolewrite’s path holds ?. A lock excludes only code
that takes the same lock.
The reference design
printk holds pr.lock (a spinlock) from before the first character to after
the last (kernel/printk.c:70, kernel/printk.c:131). Every kernel message takes it
(except while the kernel is panicking), so two printk calls never interleave: a trace line printed on hart 1 and one printed
on hart 2 come out one after the other, in some order. While the lock is held,
interrupts are off on the printing hart (noff 1, then 2 inside uartputc_sync),
and each character is sent by spinning on the UART’s status register.
User output does not take pr.lock. write(1, ...) goes through consolewrite to
uartwrite, which holds the sleep-lock tx_lock for each 32-byte batch. Nothing makes
printk and uartwrite exclude each other, so their characters can alternate at the
UART. That happened in a recorded run of cat README &; trace 65536 echo hello
(see Measure): Behnam and write came out as Bwehritena.
The trace line for one process’s own write always comes after that write’s text,
because the same process prints it after the call returns: hi4: syscall write -> 2 in the recorded run.
(The text has no newline, so the trace line continues it.)
Check yourself
1deepChoose all that apply
Which of these does pr.lock guarantee on three harts?
3. Build it
Start from the frozen commit, in your own clone of xv6 (not this site’s xv6/):
git checkout -b my-trace 06aad25
Work in this order; each milestone can be tested before the next.
The plumbing. Add SYS_trace (23) to kernel/syscall.h, entry("trace") to
user/usys.pl and int trace(int); to user/user.h. Run make. Nothing calls it
yet, but user/usys.S should now contain a trace: stub. Check with
grep -A3 'trace:' user/usys.S.
The mask and the handler. Add int tracemask; to struct proc (in the private
section), write sys_trace in kernel/sysproc.c, add its extern and table entry in
kernel/syscall.c, and clear the field in freeproc. A quick test: a tiny program that
calls trace(5) and prints trace(0) should print 5. Without the table entry you would
see unknown sys call 23 instead.
Inheritance. One line in kfork, before release(&np->lock).
The print. The names table and the printk in syscall(). Now trace works from
a test program: set a mask, make a call, see the line.
The command.user/trace.c (check argc, trace(atoi(argv[1])), exec, print an
error if exec returns) and $U/_trace in UPROGS. Try trace 32 grep hello README
and trace 2147483647 echo hi.
The test.tracetest (or your own), then usertests -q.
Debugging. Run QEMU with three harts (make qemu uses CPUS := 3). If a line is
missing, ask in order: is the bit set (print the mask in sys_trace)? Did the call
come through syscall() (a forked child’s first return does not)? Is the name table
indexed like syscalls[]? For a crash inside the print, attach gdb (the GNU debugger) (make qemu-gdb
in one terminal, ${TOOLPREFIX}gdb kernel/kernel and target remote in another), break panic, and look at bt, p/x $scause, p/x $stval and p/x $sepc: clinic 3 shows
what that looks like. TOOLPREFIX is your RISC-V toolchain’s prefix, the same one xv6’s
Makefile detects (riscv64-unknown-elf-, riscv64-linux-gnu- or riscv64-elf-); set it
with export TOOLPREFIX=riscv64-unknown-elf- or whichever you have. On
Debian/Ubuntu/WSL, gdb-multiarch also works as the debugger.
4. Debugging clinic
Each of these bugs was put into the reference solution on purpose and run on three harts. The symptom is exactly what happened. Try to explain it before revealing why.
1Forgot to copy the mask in kfork
The one line in kfork is missing:
safestrcpy(np->name, p->name, sizeof(p->name));
- // the child inherits the parent's trace mask.
- np->tracemask = p->tracemask;
-
pid = np->pid;
What happened when we ran it
$ tracetest
tracetest: trace returns the previous mask: OK
tracetest: fork copies the mask to the child: FAIL
tracetest: the child's trace(0) leaves the parent alone: OK
tracetest: exec keeps the mask: FAIL
tracetest: begin
3: syscall getpid -> 3
tracetest: end
tracetest: expected between the markers, and nothing else:
3: syscall getpid -> 3
6: syscall getpid -> 6
tracetest: 2 FAILED
$ trace 65536 sh
$ 7: syscall write -> 2
echo hi
hi
$ 7: syscall write -> 2
The child’s struct proc comes from allocproc, and its mask is whatever
freeproc left there: 0. So the child starts untraced. “exec keeps the mask” fails
too, though exec is fine: the test runs exec in a forked child, which had already
lost the mask at the fork. Between the markers only the parent’s getpid is
printed. In the traced shell, sh itself is traced (its write of the two-byte
prompt $ prints write -> 2), but echo, forked by sh, prints hi with no trace
line. Bugs in inheritance are invisible when the traced program never forks: trace 32 grep hello README still works perfectly, because trace execs grep in the same
process.
$ trace 32 grep hello README
3: syscall read -> 3
3: syscall read -> 3
3: syscall read -> 3
3: syscall read -> 3
$ trace 2147483647 echo hi
4: syscall exec -> 16336
4: syscall write -> 1
hi4: syscall write -> 1
4: syscall exit -> 0
$
(a separate boot, same kernel:)
$ tracetest
tracetest: trace returns the previous mask: OK
tracetest: fork copies the mask to the child: OK
tracetest: the child's trace(0) leaves the parent alone: OK
tracetest: exec keeps the mask: OK
tracetest: begin
3: syscall getpid -> 0
6: syscall getpid -> 0
tracetest: end
tracetest: expected between the markers, and nothing else:
3: syscall getpid -> 3
6: syscall getpid -> 6
tracetest: 4 checks OK; now compare the lines between the markers by eye
Before the handler runs, p->trapframe->a0 still holds the user’s a0, saved by
uservec: the first argument. Every read shows the descriptor 3, both writes
show the descriptor 1, and exec shows the address of its path string in trace’s
memory (16336 is 0x3fd0). Three more differences give the bug away: exit now prints
(the line comes out before kexit gets the chance not to return); the trace call
itself is missing, because the mask was still 0 when it was checked; and each write
line comes out before its text, so hi appears in front of the second line instead
of the first.
tracetest’s four checks all pass, because they test only the mask, never the printed
value: only the comparison by eye catches this bug. getpid takes no argument, so the
a0 it shows is whatever the program last left there: in the parent, the 0 returned
by the trace call just before it; in the child, the 0 that fork returned. This is
why the test’s last line asks you to compare instead of claiming that all is well.
3Off-by-one in the names table
The names are a plain list in syscall.h order, without designated initializers:
$ trace 32 grep hello README
3: syscall kill -> 1023
3: syscall kill -> 965
3: syscall kill -> 453
3: syscall kill -> 0
$ trace 2147483647 echo hi
4: syscall panic: acquire
(a second run, fresh boot, `trace 2147483647 echo hi` as the first command,
with gdb attached and a breakpoint on panic, on hart 1:)
#0 panic (s=s@entry=0x80007048 "acquire") at kernel/printk.c:139
#1 0x0000000080000c28 in acquire (lk=lk@entry=0x8000faa8 <pr>) at kernel/spinlock.c:26
#2 0x000000008000057a in printk (fmt=fmt@entry=0x80007350 "scause=0x%lx sepc=0x%lx stval=0x%lx\n") at kernel/printk.c:71
#3 0x0000000080002758 in kerneltrap () at kernel/trap.c:151
#4 0x0000000080005648 in kernelvec () at kernel/kernelvec.S:38
(gdb) p/x $scause
$1 = 0xd
(gdb) p/x $stval
$2 = 0x400000000
(gdb) p/x $sepc
$3 = 0x8000072c
(gdb) x/2wx 0x80007908+23*8
0x800079c0 <first.1>: 0x00000000 0x00000004
The list starts at index 0, but the numbers start at 1. read is 5, and index 5 is the
sixth name, kill. The values are right; only the names are shifted.
The panic is the interesting part. The first traced call is trace itself, number 23,
and a 23-entry list has indices 0 to 22. syscallnames[23] reads the 8 bytes after the
array. In that build the array sits at 0x80007908 and its 184 bytes are followed by
forkret’s static int first (0 by now) and, in the next word, nextpid (address
0x800079c4 from the symbol table; x/2wx showed it held 4), which
together make the “pointer” 0x400000000. printk's %s loop loads from it (the
lbu at 0x8000072c), and the kernel page table maps nothing there: a load page fault
(scause 13) in supervisor mode, so kerneltrap runs. It finds no device
interrupt and calls printk to report scause, and that printk tries to acquire
pr.lock, which this hart already holds, because it faulted in the middle of a
printk. acquire notices that the holder is this very hart and panics
(kernel/spinlock.c:25) before the real report can print. The first run, where
nextpid was 5, faulted the same way at 0x500000000.
4Forgot the usys.pl entry
Everything else is in place (syscall.h, user.h, the kernel side), but user/usys.pl
has no entry("trace");.
What happened when we ran it
${TOOLPREFIX}ld -z max-page-size=4096 -T user/user.ld -o user/_trace user/trace.o user/ulib.o user/usys.o user/printf.o user/umalloc.o
${TOOLPREFIX}ld: user/trace.o: in function `main':
./user/trace.c:12:(.text+0x3e): undefined reference to `trace'
make: *** [user/_trace] Error 1
The compiler is satisfied: user/user.h declares int trace(int), so trace.c
compiles to an object file with an unresolved call. The linker (ld) then looks for a
symbol named trace in ulib.o, usys.o, printf.o and umalloc.o, and nobody
defines it: the only definition would have been the stub that usys.pl generates. The
kernel side builds fine, because the kernel never refers to the user stub. (The line
number in the message is ld’s approximation from the optimized code’s debug
information; the call is on line 15. Your output shows your own toolchain prefix where
this one shows ${TOOLPREFIX}.)
5Declared the mask as a char
A learner saves space in struct proc:
- int tracemask; // bit i set: trace system call i
+ char tracemask; // bit i set: trace system call i
Everything else is unchanged, including p->tracemask & (1 << num).
What happened when we ran it
$ tracetest
tracetest: trace returns the previous mask: FAIL
tracetest: fork copies the mask to the child: FAIL
tracetest: the child's trace(0) leaves the parent alone: FAIL
tracetest: exec keeps the mask: FAIL
tracetest: begin
tracetest: end
tracetest: expected between the markers, and nothing else:
3: syscall getpid -> 3
6: syscall getpid -> 6
tracetest: 4 FAILED
$ trace 32 grep hello README
7: syscall read -> 1023
7: syscall read -> 965
7: syscall read -> 453
7: syscall read -> 0
$ trace 65536 echo hi
hi
$
p->tracemask = mask silently keeps only the low 8 bits (C converts the int to
char without a warning under xv6’s flags). So only system calls 1 to 7 can ever be
traced. read is 5, so trace 32 works perfectly and hides the bug; write is 16,
and 1 << 16 truncates to 0. Every tracetest mask is above bit 7 (uptime is 14,
getpid is 11), so every check fails and nothing prints between the markers.
The shift itself is not the problem here: 1 << num is an int shift and
fine for num up to 30. It would become one if you widened the mask to 64 bits to
support more than 31 system calls: then you need 1L << num, because shifting an
int by 32 or more is undefined in C.
6Forgot to add trace to UPROGS
The program is written, but the Makefile is unchanged:
$U/_sync\
- $U/_trace\
$U/_tracetest\
What happened when we ran it
$ trace 32 grep hello README
exec trace failed
$ tracetest
tracetest: trace returns the previous mask: OK
tracetest: fork copies the mask to the child: OK
tracetest: the child's trace(0) leaves the parent alone: OK
tracetest: exec keeps the mask: OK
tracetest: begin
4: syscall getpid -> 4
7: syscall getpid -> 7
tracetest: end
tracetest: expected between the markers, and nothing else:
4: syscall getpid -> 4
7: syscall getpid -> 7
tracetest: 4 checks OK; now compare the lines between the markers by eye
make builds only the user programs listed in UPROGS, and mkfs copies only those
into fs.img. The kernel is complete, which is why tracetest passes, but there is no
file /trace on the disk. The shell’s child calls exec("trace", ...), kexec's
namei finds nothing and returns -1, and runcmd prints exec trace failed
(user/sh.c:80). The message comes from the shell, not from your program, which never
ran.
5. The reference solution
Take the guided tour through the reference solution, one commit at a time, with the machine state at every step:
On the branch, on three harts (QEMU -smp 3), tracetest passes:
$ tracetest
tracetest: trace returns the previous mask: OK
tracetest: fork copies the mask to the child: OK
tracetest: the child's trace(0) leaves the parent alone: OK
tracetest: exec keeps the mask: OK
tracetest: begin
3: syscall getpid -> 3
6: syscall getpid -> 6
tracetest: end
tracetest: expected between the markers, and nothing else:
3: syscall getpid -> 3
6: syscall getpid -> 6
tracetest: 4 checks OK; now compare the lines between the markers by eye
Compared by eye, the two traced lines are exactly the expected ones, and the untraced uptime, fork and
wait calls in that window printed nothing. And the rest of the kernel is
unharmed:
$ usertests -q
usertests starting
...
test lazy_sbrk: OK
test partial_write: OK
test unlinkcwd: OK
ALL TESTS PASSED
(tracetest run again after usertests passed too, with pids 6653 and 6656.) No process
in usertests sets a mask, so the only cost to an untraced process is a few instructions per
system call in syscall (load the mask, shift, test).
How many system calls does ls make?trace 2147483647 ls in / (26 entries)
printed 808 lines: 1 trace (by the trace program, before the exec), 1 exec, then
ls itself made 65 reads (64 directory entries of 16 bytes and one end-of-file read), 27
opens, 27 fstats, 27 closes (one set for . and one per entry, through stat)
and 660 writes of 1 byte each. User-space printf calls write once per character
(user/printf.c:12), so more than four out of five of the system calls ls makes print one character, each paying
for a full trap, two satp switches and a return.
What does the shell do for one command?trace 2147483647 sh, then echo hi, then
Ctrl-D: 21 lines in all.
For one command, the shell makes 11 calls (8 one-byte reads in gets, fork,
wait, and the prompt’s write), and the child makes 4 visible ones: sbrk, because the
child parses the command and malloc grows the heap; exec; and echo’s two writes. The
open/close pair at the start is the shell making sure descriptors 0 to 2 are open
(user/sh.c:152). Neither exit prints, and neither does the child’s return from fork.
Interleaving on three harts.cat README &; trace 65536 echo hello printed, in the
middle of the README, Marcelo helloArroyo, Hirb3: syscall od Bwehritena -> m, S5il and,
a line later, carlc / 3: syscall write ->lo 1 / ne: the kernel’s trace lines and
cat’s text alternated byte by byte, because printk and uartwrite do not share a lock.
7. Go further
Print the arguments too.read(3, 0x1010, 1023) -> 1023 (0x1010 is grep’s buffer) needs a per-call
description of the arguments (how many, which are strings). Teaches how argstr and
fetchstr copy strings safely from user memory, and why the kernel must copy them
before the call (after exec, the old memory is gone).
Trace other processes.trace -p PID MASK sets another process’s mask. Now the field
is no longer private: it moves to the p->lock section, and both sys_trace and
syscall() must take the lock. Teaches why the private/locked split in struct proc
exists, and what a lock on the hottest path costs.
Keep trace lines out of user output. Make printk and uartwrite exclude each
other, then decide whether a process may sleep holding the lock that printk needs.
Teaches the spinlock/sleep-lock boundary in Locks and interrupt state.
Count instead of print. Keep per-process counters of each system call and print a
summary when the process exits (like strace -c). Teaches where in kexit a process
can still safely print, and what happens to the counters across fork.
More than 31 system calls. Widen the mask to uint64 and fix every shift. Teaches
C’s integer promotion rules and why 1 << 31 is already undefined for an int.