Step 1 of 19 · commit 1: Add the profile and profget system calls

A histogram that fills exactly one page

The story of this tour follows proftest (pid 3, which gdb found on hart 1 when it stopped at a sample) through the reference branch: it asks to be profiled, spins in a hot loop, reads its histogram, and later exits with a profile; at the end, prof -k profiles the kernel while usertests runs. Machine states marked as observed come from gdb stops in recorded runs; the others follow from the code.

The first commit adds the two system calls (numbers 23 and 24, wired up exactly as in lab 1) and this header, which the kernel and user programs share, so profget can copy the page out byte for byte. A 32-byte header records the range [lo, hi), the bucket size 1 << shift, the number of buckets in use, and two counters: every sample, and the samples that fell outside the range. Then 1016 four-byte buckets: 32 + 4 × 1016 = 4096. One page from kalloc holds the whole histogram, and nothing has to be allocated at interrupt time.

Why nout: a sample outside the range is still information (“12% of the time the program was somewhere you did not ask about”), and counting it separately is what lets the sample path refuse an out-of-range index (clinic 3).

Step 2 of 19 · commit 1: Add the profile and profget system calls

Two entries in the system-call table

profile and profget are registered like any system call: an extern prototype and a designated-initializer entry each; SYS_profile is 23 and SYS_profget 24 in kernel/syscall.h, and user/usys.pl generates the two stubs. The handlers live in a new file, kernel/prof.c, added to OBJS in the Makefile, and at this commit both return -1.

The arguments are two 64-bit addresses and an int: argaddr for lo and hi, argint for shift. Addresses, not pointers into user memory: the kernel never dereferences them, it only compares pcs against them, so no copyin is involved. profget is the one call that writes user memory, and it will use copyout.

Step 3 of 19 · commit 2: Give each profiled process a histogram page

profile allocates a page and fills in the header

proftest calls profile(0, 4096, 3): its own first page of text, 8-byte buckets, 512 of them. sys_profile checks the arguments first: a non-empty range, a shift between 0 and 31 (user code computes the bucket size as 1 << shift, an int), and at most PROFBUCKETS buckets. (hi - lo - 1) >> shift is the index of the last byte’s bucket, so the test is exact even when the range is not a multiple of the bucket size.

The page comes from kalloc (which takes and releases kmem.lock: noff 1 for a moment, back to 0), is zeroed, and gets its header. Then the old histogram, if any, is freed and the new one installed. profile(0, 0, 0) takes the same path with pr = 0: stop and free.

No lock anywhere. At this commit only the process itself ever touches p->prof, and it is here, in a system call, so nothing else can be using the page being freed.

Step 4 of 19 · commit 2: Give each profiled process a histogram page

A field in the private part of struct proc

p->prof goes at the end of the section “private to the process, so p->lock need not be held”, next to sz and trapframe. The rule for that section is that only the process itself (or code that runs before it can run, or after it is dead) touches the field. Check it against every user of p->prof on this branch: profile, profget and the exit write-out run as the process; the sample runs in the process’s own trap handler; freeproc runs on a zombie. None of these can overlap.

Eight bytes per slot is the whole cost to processes that never profile. A histogram in the struct itself would have added 4 KiB to each of the 64 slots.

Step 5 of 19 · commit 2: Give each profiled process a histogram page

freeproc frees the page and clears the pointer

Jump ahead: proftest reaps a child that was profiling (the one that checks that exec keeps the profile). kwait holds wait_lock and the zombie’s p->lock, so noff is 2 and interrupts are off; intena is 1 because the first acquire happened in a system call with interrupts on. The page is freed next to the trapframe, and the kfree takes kmem.lock for a moment (noff 3, the deepest nesting in the kernel, which kwait already reached before this lab).

Two decisions sit in these three lines. Where: with the slot’s other resources, when the slot is recycled; not in exec (the profile must survive it) and not at the top of kexit (later commits still need the page there). Clearing the pointer: the slot will be handed out again by allocproc, and that is the only reason a forked child starts with no profile. kfork copies nothing; the child gets 0 because this line wrote it. Clinic 4 shows a slot that kept its pointer.

Step 6 of 19 · commit 3: Sample the user pc on every timer interrupt

The sample, in usertrap, before yield

This is the profiler. A timer interrupt arrived while proftest was in user mode on hart 1; uservec saved the registers and switched to the kernel stack and page table; usertrap saved sepc in p->trapframe->epc (line 52), and devintr saw scause 0x8000000000000005 (supervisor timer), called clockintr to re-arm this hart’s timer, and returned 2. Now, before yield() gives the hart away, one if counts the sample.

Observed (gdb, breakpoint at the sample): thread 2 = hart 1, proftest pid 3, sepc and p->trapframe->epc both 0x112, sstatus 0x200000020 (SIE 0, SPIE 1, SPP 0), noff 0. 0x112 is the mulw at the top of hot()'s inner loop: the instruction that had not run yet when the interrupt arrived. (A loop head is a typical place for a sample under QEMU, which takes interrupts between blocks of translated code.)

Why here: the branch runs exactly once per timer interrupt that found some process in user mode, on every hart, and p is that process. Why trapframe->epc and not r_sepc(): the saved copy belongs to the process; the register belongs to the hart, and after yield() it holds someone else’s pc (clinic 2). Why before yield(): after it, the process may have been switched out for a long time, and the moment being sampled is now.

Interrupts stay off for the whole branch: the trap cleared SIE and this path never calls intr_on.

Step 7 of 19 · commit 3: Sample the user pc on every timer interrupt

Counting one sample

profsample counts the sample, checks the range, and adds one to bucket (pc - lo) >> shift. In the observed stop, pc was 0x112, the range [0, 0x1000) with shift 3, and nsample still 0: the first sample this histogram received. 0x112 >> 3 is bucket 34, which covers 0x110–0x117.

The range check is not optional. pc - lo is unsigned: for a pc below lo it wraps to a number near 2^64, and for a pc above hi the index runs past the buckets in use and soon past the page. Either way the increment can land in memory the profiler does not own. Clinic 3 removed these four lines: thousands of increments went into neighbouring pages of a running system without anyone noticing, and with a different bucket size the kernel faulted on an address near 2^63.

No lock and no atomic instruction: a plain load, add and store. That is safe because this histogram is written only here, by the one hart running its process, with interrupts off; and read only by that same process in a system call, which cannot be running at the same time.

Step 8 of 19 · commit 3: Sample the user pc on every timer interrupt

Why not in clockintr

clockintr looks like the natural home for a profiler: it runs at every tick. But look at the if: the kernel’s notion of time, ticks, is advanced only by hart 0, under tickslock, because it is a single wall clock for pause and uptime. Hart 1, where proftest runs in this story, skips the block and only re-arms its own timer at line 183.

So code placed next to ticks++ sees one hart’s ticks, not the profiled process’s. Clinic 1 did exactly that, carefully checking SPP to keep only user-mode ticks. Its proftest hot loop got 30 samples on hart 0, and 0 on the other harts.

clockintr is also called from kerneltrap, for interrupts that land in the kernel. It cannot tell the two cases apart without reading sstatus itself, while usertrap knows by construction.

Step 9 of 19 · commit 4: Copy the histogram out with profget

profget copies the page out

proftest’s hot loop has spun for 30 ticks; it calls profget(&pr). One copyout of 4096 bytes, translated page by page through proftest’s page table, into its static struct prof pr in .bss. No process without a profile gets anything (-1).

Interrupts are on (this is a system call), so a timer interrupt can arrive in the middle of the copy. It would land in kerneltrap, not usertrap, so it does not touch the histogram being copied; at this commit, nothing samples kernel time.

The test then counts the buckets that fall inside hot(). In the recorded runs on the branch: between 28 and 30 samples per run, and all or all but one of the in-range samples in hot().

Step 10 of 19 · commit 5: Write the profile to prof.out at exit

kexit writes the profile while it still can

A program run under prof never calls profget; it just exits. So kexit saves the histogram first thing, while the process still has everything file I/O needs: no lock held (noff 0), interrupts on, and its current directory, which line 351 is about to give up with iput.

Placement is the whole lesson of this step. Everything after line 355 runs under wait_lock and then p->lock: no sleeping allowed. And freeproc, later, runs in the parent under two spinlocks; clinic 5 put the write there and panicked in acquire on the first reap.

The state is reasoned, not observed. The hart is illustrative: an exiting process can be on any hart.

Step 11 of 19 · commit 5: Write the profile to prof.out at exit

The write itself is ordinary file-system code

profdump does what open("prof.out", O_CREATE|O_WRONLY) and write would, without the file descriptor: inside one log transaction (begin_op / end_op), create (made non-static in sysfile.c for this) finds or creates prof.out relative to the process’s current directory and returns it locked; writei with user_src = 0 copies 4096 bytes from kernel memory; iunlockput drops it.

Four data blocks, an inode, a bitmap block and a directory block fit easily in one transaction. Any of these calls may sleep (log space, a sleep-lock, the disk), which is allowed here and only here in the exit path.

create on an existing prof.out returns the old inode, and the write overwrites its first 4096 bytes from offset 0. The parent can read it as soon as wait returns: the write finished before the child became a zombie. Two caveats. A full disk makes writei stop short: a run on a full disk printed balloc: out of blocks, left a 0-byte prof.out, and prof printed prof: no prof.out, with no hang or panic. And a larger prof.out left by someone else keeps its tail, which prof ignores because it reads only one page.

Step 12 of 19 · commit 6: Add proftest, a test program for the profiler

A test with a hot loop it can find

hot(n) spins for n ticks of uptime(), doing a million multiply-adds between checks. It is noinline so that it has an address of its own; the check is “at least 90% of the in-range samples landed in hot(), and at least 10 samples in all”.

Where does hot() end? The first try used a marker function placed after it in the source, but the compiler placed that marker at address 0, before hot: GCC does not promise source order. hotend() takes the nearest of several known functions above hot instead. In this build hot starts at 0xd0 and the next function at 0x136.

Each check prints OK or FAIL, and the final ALL OK covers only what was checked. The tests also cover the lifetime rules: a forked child’s profget must fail, a child that calls profile and then execs proftest exec must still have it, and 20 children that exit while profiling must not change the free-page count.

Step 13 of 19 · commit 7: Add prof, which runs a command under the profiler

prof finds the command's text and runs it profiled

prof reads the command’s ELF program headers (textrange, above) and takes the loadable segment marked executable: for grep, [0, 0xb71), its text and read-only data. The loop picks the smallest shift, starting at 1, for which the range fits in 1016 buckets: 2-byte buckets would resolve every compressed instruction, but grep would need 1,465 of them, so it gets 4-byte buckets.

Then the fork-profile-exec sequence the lifetime rules were designed for: the child calls profile for itself, then execs the command, which keeps the profile; the parent waits, prints the elapsed ticks, and reads prof.out, written by the child’s kexit. Between profile returning and the exec system call, the child runs a handful of prof’s own instructions; a sample there would be counted at a prof address. That window is far shorter than a tick.

The elapsed ticks are the yardstick for the report: in the recorded grep .*.*.*z b1, 72 ticks and 61 samples. The difference is time grep did not spend in user mode: exec, reading its input, the write-out at exit.

Step 14 of 19 · commit 7: Add prof, which runs a command under the profiler

Symbol files on the disk

The Makefile already writes user/grep.sym for every program: objdump -t reduced to “address name” lines. These lines copy them into fs.img (mkfs strips the user/ prefix, so the file is /grep.sym; the longest name, usertests.sym, fits in DIRSIZ). forktest is linked by its own rule and has none. The empty pattern rule tells make that a .sym file is produced by linking its program.

prof names a bucket by the function with the highest address at or below the bucket’s start. With 4-byte buckets that is nearly exact. With coarse buckets a bucket can straddle two functions and is named after the first: in the 32-byte kernel profile in Measure, the bucket at release+0x30 is almost all memset’s loop.

Step 15 of 19 · commit 8: Add a kernel profile, fed by kerneltrap on every hart

kerneltrap feeds the kernel profile

The last commit points the same idea at the kernel. A profile whose lo is at or above KERNBASE is a kernel profile, fed from kerneltrap: on every timer interrupt taken in supervisor mode, on every hart, sepc (read at the top, line 146) is the kernel pc the interrupt landed in front of.

Observed (gdb, prof -k grep .*.*.*z README > o, breakpoint on kprofsample once the profile existed): hart 1, no process (cpus[1].proc was 0), pc 0x80001e22, sstatus 0x200000120 (SPP 1: from supervisor mode; SPIE 1; SIE 0), noff 0. Hart 1 was idle: 0x80001e22 is the csrci sstatus,2 of scheduler's intr_off(), the instruction right after intr_on(). An idle hart sleeps in wfi with interrupts off; the timer wakes it, the loop turns interrupts on, and the pending interrupt is taken at once, in front of that one instruction. Every idle tick of every hart lands there.

This is the important difference from the user path: a kernel interrupt is taken only where the kernel had SIE on. More on that in the last step.