Where does a program spend its time? A sampling profiler answers without changing the
program: every so often, it stops the program, writes down where it was, and lets it go
on. After a few hundred samples, the places that come up most are the places where the
time goes. In this lab you build one for xv6. A process asks the kernel to sample it, the
kernel counts the interrupted program counters in a histogram of address buckets, and a
new command, prof grep ..., prints the hottest functions of any program.
The hardware already stops every program ten times a second: the timer interrupt that
drives the scheduler. The design questions are about using that interrupt well. Which
piece of code sees every tick on every hart, and which register says where the
program was? Where should a histogram live, who may touch it while an interrupt handler
is updating it, and what happens to it across fork, exec and exit? A program run
under the profiler does not know it is being profiled: how do the samples get out? And
when you point the same machinery at the kernel itself, what can it see, and what is it
structurally unable to see?
The reference solution is eight small commits. It finds the inner loop of grep’s regular
expression matcher from 61 samples, and its kernel profile of usertests turns up a
surprise about which kernel code a timer-driven profiler can see at all.
How a timer interrupt reaches the kernel on every hart, which code runs for it when the hart was in user mode and when it was in the kernel, and what the sepc register holds at that moment.
How to attach per-process state with an interesting lifetime to struct proc: what fork, exec, exit and wait each do to it, and which of these places may sleep.
When an interrupt handler can update data without a lock, and when it cannot.
What a sample count means statistically: how many samples a second a process gets, and how long a run must be before a percentage means something.
What a profiler driven by interrupts can and cannot see inside the kernel, and where the time it cannot see ends up.
git clone https://github.com/ShowMeTheStack/xv6-riscv-labs
cd xv6-riscv-labs
git checkout -b my-profiler 06aad25 # start your own
git diff 06aad25 origin/ext/07-profiler # only when you want the answer
1. The spec
The system calls.
int profile(uint64 lo, uint64 hi, int shift) starts sampling the calling process into a
new, empty histogram. Its buckets cover the addresses [lo, hi), each bucket
1 << shift bytes, at most 1016 buckets. At every timer interrupt that finds the process
running in user mode, the interrupted user pc is counted in its bucket, or as “outside”
if it is not in [lo, hi). profile(0, 0, 0) stops sampling and discards the histogram;
a second profile replaces the first. Bad arguments (an empty range, a negative or huge
shift, too many buckets) return -1.
int profget(struct prof *buf) copies the calling process’s histogram to buf; -1 if
it has none.
struct prof is defined in kernel/prof.h, which user programs include too: the range,
the shift, the number of buckets, a count of all samples, a count of samples outside the
range, and the buckets. It is exactly one page.
Lifetime.fork does not pass the profile to the child. exec keeps it (the profile
belongs to the process, not to the program). When a profiled process exits, the kernel
writes its histogram to the file prof.out in the process’s current directory.
Kernel mode. If lo >= KERNBASE, the histogram is a kernel profile: it counts the
kernel pc at every timer interrupt taken in supervisor mode, on all harts, whatever is
running. Only one kernel profile can exist at a time.
The command.prof command args... profiles the command’s executable segment and prints
where the samples landed, by function (named from the program’s .sym file, which the
Makefile now copies into fs.img) and by bucket. prof -k command profiles the kernel’s
text while the command runs; prof -k 0xLO 0xHI command only [LO, HI). The report goes to
the standard error, so the command’s output can be redirected:
The test.proftest prints one line per check: bad arguments are refused and
profile(0, 0, 0) stops; a 30-tick hot loop gets at least 10 samples and at least 90% of
the in-range ones fall inside the loop’s function; fork does not pass the profile on and
exec keeps it; a child that spins for 20 ticks and exits while profiling leaves its
histogram in prof.out;
only one kernel profile may exist, and an idle second of the kernel yields at least 10
samples, none outside the profiled range; 20 profiled children leak no page. Everything
it reports, it checks.
The leak check counts free pages, so run it on an otherwise idle system.
$ proftest
proftest: arguments, and profile(0, 0, 0) stops: OK
proftest: hot loop: 30 samples, 30 in range, 30 in hot()
proftest: most samples in the hot loop: OK
[...]
proftest: no leaks: OK
proftest: ALL OK
Constraints. A process that never calls profile must behave exactly as before, and
usertests -q must still print ALL TESTS PASSED on three harts. The sampling path runs
at every tick on every hart, so keep it short.
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 can you catch every tick?
The profiler needs code that runs once per timer interrupt while the profiled process
is in user mode, on whichever of the three harts it happens to be running. Where in the
kernel is that? And is the global ticks counter a good clock for it?
In usertrap, in the branch for which_dev == 2, before yield()
(kernel/trap.c:85). devintr returns 2 for a supervisor timer interrupt
(scause0x8000000000000005), and usertrap only runs for traps from user mode, so
this one spot sees exactly “a timer tick while some process was in user mode”, and p
is that process.
Every hart has its own timer. timerinit sets each hart’s first stimecmp in
start, and clockintr re-arms it on every interrupt with
stimecmp = time + 1000000: a tenth of a second at QEMU’s 10 MHz timebase. So a running
process is interrupted about ten times a second of its own running time, whichever
hart it is on. In the recorded runs on the branch, proftest’s hot loop, spinning for
30 ticks, got between 28 and 30 samples every time.
clockintr is the wrong place, for two reasons. Its ticks++ runs only on hart 0
(if (cpuid() == 0)), because ticks is a wall-clock counter, not a per-hart one: tie
sampling to it and a process on hart 1 or 2 is never sampled (clinic 1 measured
runs with 0 samples). And clockintr is shared by both trap paths, so it does not know
by itself whether the interrupted pc is a user or a kernel address.
Check yourself
1warm-upChoose one
A learner samples in clockintr, inside its if (cpuid() == 0) block, next to
ticks++. On three harts, a CPU-bound process runs its hot loop for 3 seconds. What
does its profile most likely show?
2solidType a number
The timer comparator is set to time + 1000000 and QEMU’s time counts at 10 MHz.
A process spins in user mode, alone on a hart, for 3 seconds. About how many samples
does a correct profiler take of it?
decimal, 0x hex or 0b binary
2Which register says where the program was?
You are now in the right spot in usertrap. Which value is the address of the user
instruction the timer interrupted, why is it exactly that instruction, and can you read
it at any time during usertrap?
An interrupt arrives between two instructions: one has finished, the next has not
started. sepc must let the kernel resume the program correctly. Now ask what else
can write sepc while usertrap is still running.
Hint 3.
What did usertrap do with sepc before anything else could run?
The reference design
The trap hardware writes sepc with the address of the instruction that was
interrupted, the one that has not executed yet; returning with sret to sepc runs
it as if nothing had happened. That is what makes it the right sample: it is exactly
where the program was. (For an ecall it is the ecall itself, which is why the
system-call path adds 4.) usertrap saves it at once in p->trapframe->epc
(kernel/trap.c:52) for a reason the comment at kernel/trap.c:64 spells out: any
later trap on this hart overwrites sepc.
So the sample is p->trapframe->epc, taken before yield(). After yield() the live
sepc belongs to whatever trapped on this hart in the meantime: another process’s user
pc, or the kernel pc of an interrupt taken in the scheduler. Clinic 2 samples
r_sepc() after yield(): with three CPU hogs running, only 12 of 30 samples landed in
the hot loop, 8 were outside the program’s range, and 10 were inside it but outside the
hot loop, at addresses proftest was not executing.
A gdb stop at the sample in the recorded run: hart 1, pid 3 (proftest), sepc and
trapframe->epc both 0x112, which is the mulw at the top of the hot loop’s inner
loop.
Check yourself
1solidDecode the bits
gdb stopped at the sample in usertrap (timer interrupt from user mode) and printed
sstatus. Decode three of its bits.
Value: 0x200000020
2solidTrue or false, and why
True or false: in usertrap, r_sepc() called right after yield() returns
still holds the interrupted user pc of this process.
Why?
3Where does the histogram live, and for how long?
A histogram needs about a thousand counters. Where do you keep it, and what must fork,
exec, exit and wait each do to it? Decide each case, then say where the memory is
freed.
Hint 1.
Look at how the trapframe is allocated and freed: allocproc and freeproc. Then
look at what kfork copies, what kexec replaces, and when freeproc runs.
Hint 2.
struct proc is in a static array of 64 entries; a few kilobytes each would cost a
lot for the processes that never profile. Think about the command you will write:
it must set up profiling and then run some other program in the same process.
Hint 3.
Something allocated on demand and pointed to from struct proc; then one decision
per event, each justified by what that event does to the struct proc itself.
The reference design
One page, kalloc’d when the process calls profile and pointed to by p->prof, a new
field in the section of struct proc that is private to the process. struct prof is
exactly one page: a 32-byte header and 1016 four-byte buckets. Processes that never
profile pay 8 bytes.
fork gives the child nothing: allocproc hands out a slot that freeproc
cleared, so p->prof is 0. Copying would make two processes write two copies of a
histogram that describes one program, and both would write prof.out.
exec keeps it, because kexec replaces the memory image but keeps the
struct proc. That is what lets prof call profile and then exec the command:
the samples are the new program’s. (The range must describe the new program, so
prof reads it from the command’s ELF headers before the exec.)
exit writes it out (question 5) but cannot free the slot’s other resources yet.
wait reaps the slot: freeproc frees the page with the trapframe and sets
p->prof = 0. Clearing the pointer matters as much as freeing the page: clinic 4
freed it on exec only, left the pointer in the slot, and the next process to use
that slot started life with a stranger’s histogram (observed in another run of
clinic 4: a later proftest failed fork does not inherit the profile).
Check yourself
1solidMatch the pairs
Match each event to what the reference design does with the histogram page.
4Does the sampling path need a lock?
The sample is taken in an interrupt handler, the histogram is shared memory, and there
are three harts. Does the increment in the sample path need a spinlock? Who else could
be reading or writing the same histogram at that instant?
Hint 1.
List every piece of code that touches p->prof or the page it points to so far:
the sample in usertrap, profile, profget, freeproc. (Wherever the
histogram is saved at exit, ask the same question of that code.)
Hint 2.
Each of them runs either as the process or on a zombie nobody runs. A process runs
on at most one hart at a time. And while the process is in usertrap for the
timer, it is not in a system call.
Hint 3.
Ask, for each pair, whether they can overlap in time. If no pair can, the field is
private, exactly like p->sz.
The reference design
No lock. The user histogram is touched only by its own process: the sample in
usertrap runs on the hart that was running the process, with interrupts off
(sstatus showed SIE 0 in the recorded stop), and the system calls run as the same
process on its kernel stack. A process is never in a system call and in the timer path
at the same time, so the increment cannot race with profile freeing the page. The
process can move to another hart, but only by yield(), which happens after the sample.
freeproc touches the page only after the process is a zombie.
The state at the sample in the recorded run: hart 1, supervisor mode, kernel page table,
proftest’s kernel stack with only usertrap and profsample on it, interrupts off,
noff 0. A lock here would cost an atomic swap, a fence and an interrupt-state push and
pop per tick, and protect nothing.
This changes for the kernel profile (the last question): there, three harts’ interrupt
handlers write one histogram.
Check yourself
1solidFill in the machine state
A timer interrupt from user mode has brought proftest into usertrap, which is
about to count the sample. Fill in the machine state of that hart.
5How do the samples get out?
prof grep hello README will run grep, which knows nothing about profiling and will
never call profget. When grep exits, its histogram must reach prof. Where in the
exit/wait sequence can the kernel hand it over, and what rules out the other places?
Hint 1.
Read the exit and wait path from top to bottom (Tour 21: exit, wait and zombies): the exiting process’s
side, then the parent’s. At each line, ask: which locks are held, and could this code
sleep?
Hint 2.
A simple hand-over is a file. Writing one needs the log (begin_op), path lookup
relative to the current directory, and sleep-locks on inodes and buffers. All of
them may sleep, and releasing a sleep-lock calls wakeup. Look at what wakeup
acquires.
Hint 3.
The write must happen while the exiting process still has its current directory and
holds no spinlock.
The reference design
In kexit, at its top, before the files are closed and before iput(p->cwd) (line
338 of kernel/proc.c on the branch): profdump creates (or reuses) prof.out in the
process’s current directory and writes the page with writei inside one log
transaction. At that point the process holds no lock and may sleep, exactly like a
system call.
freeproc would be the tidy place, next to the free, but it runs in the parent’s
kwait holding wait_lock and the child’s p->lock. File-system code there breaks
in a way that is instructive: releasing an inode’s sleep-lock calls wakeup, which
acquires every process’s p->lock in turn, including the zombie’s, which this hart
already holds. Clinic 5 ran it: panic: acquire, with wakeup → releasesleep →
iunlock → namex → create → profdump → freeproc → kwait on the stack.
The parent reads the file after wait returns, by which time the write is complete:
kexit finished it before the child became a zombie.
Check yourself
1deepChoose one
A learner moves the write-out into freeproc (called from kwait). What
happens the first time a profiled child is reaped?
6How long must you sample?
prof grep .*.*.*z README runs for about a second and reports matchstar 70%. Run it
again and you may see 62% or 87%. How many samples do you need before a percentage is
trustworthy to a few points, and how long is that in seconds of the program’s run?
Hint 1.
Each sample is a draw: it lands in function F with probability p, F’s true share of
the running time. The number in F after n samples is binomial.
Hint 2.
The standard error of a binomial proportion is sqrt(p(1-p)/n). And you know the
sampling rate from the first question.
Hint 3.
Solve sqrt(p(1-p)/n) = target for n, then divide by ten samples a second.
The reference design
With n samples, a share p comes out with a standard error of about sqrt(p(1-p)/n).
For p = 0.7:
samples
standard error
at 10 a second
8
16 points
under a second
60
6 points
6 seconds
2,100
1 point
3.5 minutes
The recorded runs agree. Six runs of grep .*.*.*z README (7 to 10 samples each) gave
matchstar 87%, 100%, 50%, 70%, 71% and 62%. Two runs on eight times the input
(60 and 61 samples) gave 65% and 78%.
Two more things limit accuracy. A process gets about ten samples a second of its own
running time: a program that mostly waits gets almost none, however long it takes
(prof wc on 937 KB of text took 55 ticks and got 1 sample; see Measure). And a sample
attributes the tick to the instruction the interrupt landed in front of; with 4-byte
buckets that is close to exact, but a bucket that straddles two functions is labelled
with the first one.
Check yourself
1solidType a number
You want a function’s share, about 50%, to within one standard error of 2
percentage points. How many samples do you need? (Use sqrt(p(1-p)/n).)
decimal, 0x hex or 0b binary
7What would a kernel profile see?
Now point the same idea at the kernel: count the kernel pc at timer interrupts taken in
supervisor mode. Where do you take the sample, does it need a lock now, and, most
interesting, which kernel code can such a profile never catch, and where will that
time show up instead?
A pending timer interrupt is not lost while SIE is 0; it is taken at the first
instruction after SIE becomes 1. Find every instruction in the kernel that sets SIE.
Hint 3.
Count the writers of a kernel histogram. Then, for the blind spot, ask two things of
each place in the kernel: is SIE on there, and if not, where is the next instruction
that turns it back on?
The reference design
Sample sepc in kerneltrap when which_dev == 2. Unlike the user histogram, this
one is written by every hart’s interrupt handler at once, so it needs a lock
(kproflock, taken in interrupt context, like tickslock), and there can be only one
kernel profile at a time. It can never deadlock: it is never held with interrupts on,
and nothing that runs in interrupt context is acquired while holding it. (It is not a
leaf, though: profget holds it across a copyout that may call kalloc.) Before the page is freed or written out, it must
be unhooked under the lock, so no hart is still adding to it.
The blind spot: a supervisor-mode interrupt is taken only when SIE is 1, and SIE is 0
whenever noff > 0 (Locks and interrupt state): inside every spinlock critical
section, every push_off region, the trap entry before intr_on, the scheduler’s scan.
None of that code can ever be sampled. The time is not lost, though: the interrupt
stays pending and is taken at the first instruction after SIE comes back on. So all
the time spent in critical sections is billed to the instruction after csrsi sstatus,2 in pop_off, the entry time of a system call to the one after
usertrap's intr_on, and the scheduler’s time (idle waiting, but also its scans
and context switches) to the one after the scheduler’s intr_on. Ticks that arrive
during other traps from user mode, or on the way back to user mode, stay pending until
the hart is in user mode again and never reach the kernel profile at all.
Measured over usertests -q: of 4,003 kernel samples, the 642 bytes holding kalloc,
kfree, acquire, release, push_off and pop_off got 242, and 240 of
them sat on one instruction, 0x80000c50 in pop_off. The other two were on the first
instructions of kalloc and push_off, before interrupts go off. Not one sample
landed between a push_off and its pop_off.
Check yourself
1deepChoose all that apply
A kernel profile samples sepc in kerneltrap on timer interrupts. Which of these
kernel instructions can never be the sampled pc?
3. Build it
Start.
git checkout -b my-prof 06aad25
Milestones.
The plumbing. Two system-call numbers (23 and 24), the stubs in user/usys.pl, the
prototypes in user/user.h, the table entries in kernel/syscall.c, and
kernel/prof.h with struct prof. Put the handlers in a new kernel/prof.c (add
$K/prof.o to OBJS) and have them return -1. Test: it builds, and a call returns -1.
The page.p->prof, profile allocating and filling in the header, profile(0, 0, 0) freeing, freeproc freeing and clearing. Test: usertests -q (nothing samples
yet).
The sample. One if in usertrap's timer branch and the counting function.
profget. A copyout of the page. Now write a test program with a hot loop:
profile your own text, spin for a few seconds, profget, print the buckets. You should
see about ten samples a second, all in the loop.
Exit. The write-out in kexit. Test: a profiled child exits; the parent reads
prof.out.
The command.prof: read the ELF header, choose the shift, fork, profile,
exec, wait, read prof.out, print. Copy the .sym files into fs.img and name the
buckets. Inputs must run for seconds, not milliseconds: README is grepped in less
than one tick. Build a bigger file inside xv6 with cat README README ... > b1, and use
a pattern that makes grep’s matcher backtrack (.*.*.*z).
Kernel mode (optional): a sample in kerneltrap, a lock, one owner at a time.
After each milestone: usertests -q on three harts.
Debugging. Run QEMU with -smp 3, as make qemu does. To see a sample being taken:
start QEMU halted with make qemu-gdb (it adds -S and a gdb port of its own, which it
writes into .gdbinit), run ${TOOLPREFIX}gdb kernel/kernel in another terminal,
break profsample (or your name for it) before the first continue, run your
test, then bt, p/x $sepc, p/x $sstatus and p cpus[$tp].noff. If a process gets no
samples, check which hart it runs on (info threads). If the kernel faults in your sample
function, print the computed index: a pc outside the range is the usual cause (clinic 3).
To check for leaks, count free pages before and after with an sbrk loop, on an otherwise
idle system. 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.
1Sampled on hart 0’s tick, in clockintr
The sample moves from usertrap into clockintr, next to ticks++. The learner
even checks that the interrupt came from user mode:
if (cpuid() == 0) {
acquire(&tickslock);
ticks++;
+ // a tick: sample the running process, if it was in user mode.
+ struct proc *p = myproc();
+ if (p && p->prof && p->prof->lo < KERNBASE &&
+ (r_sstatus() & SSTATUS_SPP) == 0)
+ profsample(p->prof, r_sepc());
wakeup(&ticks);
release(&tickslock);
}
and the profsample call in usertrap is gone.
What happened when we ran it
$ proftest
proftest: arguments, and profile(0, 0, 0) stops: OK
proftest: hot loop: 30 samples, 30 in range, 30 in hot()
proftest: most samples in the hot loop: OK
[...]
proftest: ALL OK
$ proftest
proftest: arguments, and profile(0, 0, 0) stops: OK
proftest: hot loop: 0 samples, 0 in range, 0 in hot()
proftest: most samples in the hot loop: FAIL
[...]
proftest: 1 FAILED
$ proftest
proftest: arguments, and profile(0, 0, 0) stops: OK
proftest: hot loop: 11 samples, 11 in range, 11 in hot()
proftest: most samples in the hot loop: OK
proftest: fork does not inherit the profile: OK
proftest: exec keeps the profile: OK
proftest: prof.out: 0 samples, 0 in range, 0 in hot()
proftest: exit writes prof.out: FAIL
[...]
proftest: 1 FAILED
$ proftest
proftest: arguments, and profile(0, 0, 0) stops: OK
proftest: hot loop: 0 samples, 0 in range, 0 in hot()
proftest: most samples in the hot loop: FAIL
[...]
proftest: prof.out: 0 samples, 0 in range, 0 in hot()
proftest: exit writes prof.out: FAIL
[...]
proftest: 2 FAILED
Four runs of proftest in one boot, three harts. The code is right in every detail but
one: the block it sits in runs only on hart 0. ticks is the kernel’s wall clock, so
only one hart advances it (kernel/trap.c:169); the other two harts take their timer
interrupts just as often but skip the block.
A CPU-bound process mostly stays on the hart it started on, because when it yields at
a tick, that hart’s scheduler finds it RUNNABLE again before the idle harts wake from
wfi (reasoned from the scheduler’s code). So the count is anywhere from 0 to about
30, depending on how much of the run was on hart 0: 30, 0, 11 and 0 in this boot; 23,
29, 26 and 0 in a second boot. Nothing crashes, and a run that happens to land on hart
0 looks perfect.
A sampling profiler must use the event that every hart sees: its own timer interrupt,
on the trap path of the hart running the process.
2Read sepc after yield
The sample is taken after yield(), from the live register:
if (which_dev == 2) {
- // first record where the program was. (a kernel
- // profile is fed by kerneltrap instead.)
- if (p->prof && p->prof->lo < KERNBASE)
- profsample(p->prof, p->trapframe->epc);
yield();
+ // record where the program was.
+ if (p->prof && p->prof->lo < KERNBASE)
+ profsample(p->prof, r_sepc());
}
What happened when we ran it
$ proftest
proftest: arguments, and profile(0, 0, 0) stops: OK
proftest: hot loop: 30 samples, 30 in range, 30 in hot()
proftest: most samples in the hot loop: OK
[...]
proftest: ALL OK
$ grep .*.*.*z b1 > o1 &
$ grep .*.*.*z b1 > o2 &
$ grep .*.*.*z b1 > o3 &
$ proftest
proftest: arguments, and profile(0, 0, 0) stops: OK
proftest: hot loop: 30 samples, 22 in range, 12 in hot()
proftest: most samples in the hot loop: FAIL
proftest: fork does not inherit the profile: OK
proftest: exec keeps the profile: OK
proftest: prof.out: 10 samples, 9 in range, 5 in hot()
proftest: exit writes prof.out: FAIL
[...]
proftest: free pages 32440 before, 32470 after
proftest: no leaks: FAIL
proftest: 3 FAILED
Alone on the machine, the bug is invisible: proftest yields at a tick, its own
hart’s scheduler runs it again at once, nothing else traps on that hart in between,
and sepc still holds its pc. Every check passes.
With three CPU hogs (grep with a backtracking pattern) and three harts, proftest
shares the harts. When yield() returns, the process may have spent time switched out
and may be back on another hart. sepc is a per-hart register that every trap
overwrites: it holds the pc of the last trap taken on that hart, which may have been a
grep’s timer interrupt (a user pc, mostly inside [0, 0x1000), the range proftest
profiles) or an interrupt in the scheduler’s idle loop (a kernel pc, counted as
outside). The run shows both: of 30 samples, 8 outside the range and 10 inside it but
not in hot(). Only 12 of 30 were right. That attribution of samples to the wrong
program and the kernel is reasoned from the code; the counts are from the log.
The reference samples p->trapframe->epc, saved at the top of usertrap
(kernel/trap.c:52), before anything can trap or switch. The same experiment on the
reference (three hogs, then proftest) gave hot loop: 30 samples, 30 in range, 30 in hot().
(no leaks: FAIL here is not this bug: the greps were still running, holding memory,
when proftest first counted free pages, and had exited by the second count. The
reference failed that check the same way in the same experiment, which is why the spec
says to run proftest on an idle system.)
With a user profile made by prof this changes nothing: prof profiles the whole
executable segment, and a user program’s pc is always in it. The bug shows with a
kernel profile of part of the kernel, where most samples are outside the range.
For a pc outside [lo, hi) the index is garbage, and what the garbage does depends on
the shift.
2-byte buckets (shift 1). With hi = 0x80000d00 only 256 buckets are in use.
For pc > hi the index is (pc - lo) / 2: up to 0x800012f0 it lands in the page’s
own unused buckets, beyond that up to tens of kilobytes after the histogram page. For pc < lo, pc - lo wraps around to nearly 2^64; shifted right by
one and multiplied by 4 (the size of a uint) for the address, it wraps around again
and lands 2 * (lo - pc) bytes before the bucket array: in the header for the last
16 bytes below lo, in a neighbouring page further down. The idle samples, the large majority, all hit one
word: the scheduler’s pc 0x80001e22 gives an offset of 32 + 2 * 0x1322 = 0x2664
bytes, two pages above the histogram. The run counted 3,565 samples, 0 outside
(nothing counts them now), and only 237 in the 256 buckets in use. Of the other 3,328
increments, nearly all went into memory the profiler does not own: the idle ones
alone are most of them, and the whole-kernel profile suggests that only about ten
samples in such a run fall in the page’s unused buckets. usertests -q still passed and proftest after it
passed. Whatever those pages held, nothing that ran noticed. That is the worst kind of
bug: the profile looks plausible, the system looks healthy, and memory is being
changed behind everyone’s back. Had the word been a free page’s next pointer or a
page-table entry, the failure would have appeared much later, somewhere else.
8-byte buckets (shift 3, a range of 7,936 bytes). Now the wrapped index is shifted
by 3 and multiplied by 4, so the factor 2^64 no longer cancels: for pc < lo the
address is the histogram plus about 2^63. The first sample below lo faulted:
scause 13 (load page fault) at sepc0x8000577a, the lw that reads the bucket
in profsample, with stval0x8000000087f04e48. That value fits exactly a sample
at 0x80000c50 (the hot instruction in pop_off, 0x3b0 below lo) and a histogram
page at 0x87f05000: 0x87f05000 + 32 + 4 * (2^61 - 0x76) = 0x8000000087f04e48
(inferred from the arithmetic; gdb was not attached). The fault happened inside
kerneltrap, with interrupts off, so it trapped again into kerneltrap, which found
no device and panicked.
The range check is two comparisons per tick and it is the only thing between a sample
and an arbitrary memory write.
4Freed the histogram on exec, not on exit
The learner reasons that a profile belongs to a program, so exec should end it, and
leaves freeproc alone:
// kernel/exec.c, kexec, after the old image is freed
proc_freepagetable(oldpagetable, oldsz);
+
+ // the profile belonged to the old program.
+ if (p->prof) {
+ kfree((void *)p->prof);
+ p->prof = 0;
+ }
// kernel/proc.c, freeproc
- if (p->prof)
- kfree((void *)p->prof);
- p->prof = 0;
What happened when we ran it
$ proftest
proftest: arguments, and profile(0, 0, 0) stops: OK
proftest: hot loop: 30 samples, 30 in range, 29 in hot()
proftest: most samples in the hot loop: OK
proftest: fork does not inherit the profile: OK
proftest: exec keeps the profile: FAIL
proftest: prof.out: 10 samples, 10 in range, 10 in hot()
proftest: exit writes prof.out: OK
proftest: only one kernel profile at a time: OK
proftest: kernel: 30 samples, 0 outside [0x80000000, 0x8000FE00)
proftest: kernel samples, all in the kernel's text: OK
proftest: free pages 32470 before, 32469 after
proftest: no leaks: FAIL
proftest: 2 FAILED
$ prof grep .*.*.*z README > o
prof: 9 ticks
prof: no prof.out
(another boot, same kernel: gdb attached after proftest finished)
s_sstatus (x=2) at kernel/riscv.h:67
warning: 67 kernel/riscv.h: No such file or directory
proc[0] pid 1 state 2 prof (nil) name init
proc[1] pid 2 state 2 prof (nil) name sh
proc[2] pid 0 state 0 prof (nil) name
proc[3] pid 0 state 0 prof 0x8002e000 name
proc[4] pid 0 state 0 prof (nil) name
[...]
(the same mistake, another fresh boot:)
$ prof -k echo hi
hi
prof: 0 ticks
prof: no prof.out
$ prof -k echo hi
prof: profile failed
prof: 0 ticks
prof: no prof.out
$ proftest
[...]
proftest: a kernel profile: FAIL
[...]
$ usertests -q
[...]
ALL TESTS PASSED
$ proftest
proftest: arguments, and profile(0, 0, 0) stops: OK
proftest: hot loop: 29 samples, 29 in range, 29 in hot()
proftest: most samples in the hot loop: OK
proftest: fork does not inherit the profile: FAIL
proftest: exec keeps the profile: FAIL
[...]
(In the first run the kernel check prints under an older name, “all in the kernel’s
text”; the current proftest calls it “none outside the profiled range”, which is
what it tests.)
Three failures, and the last two are worse than “a leak”.
exec keeps the profile: FAIL and prof: no prof.out are the design error: prof
sets the profile and then execs the command, so a profile that dies at exec is gone
before the command runs a single instruction. The profile has to belong to the
process.
The leak is only one page, although 20 profiled children exited without exec. The
gdb listing shows why: slot 3 is UNUSED (state 0) and still points at a histogram page.
freeproc neither freed the page nor cleared the pointer, so the slot carries it to
the next process that allocproc puts there. The 20 children were allocated one
after another, each in the slot the previous one had just left; each called profile,
which frees the old p->prof before installing a new one, so each freed its
predecessor’s page. Only the last stays behind, and it stays until a later process in
slot 3 calls profile or exec (in a second run in another boot, the next proftest
started again from 32,470 free pages). That last part is reasoned from the code.
Worse than the leak: a process that lands in that slot inherits a stranger’s
histogram. Between its fork and its exec, it is sampled into that page; if it
exits without exec, kexit writes the stranger’s profile to its prof.out. The
second run above shows it: after usertests, a proftest child started with a profile
it never asked for (fork does not inherit the profile: FAIL). A pointer left in a
recycled slot is a bug in its own right, which is why the reference freeproc both
frees and clears (p->prof = 0).
Worst of all, under prof -k. The kfree in exec skips profdetach, so the freed
page stays published in kprof: every hart keeps incrementing a page that the
allocator has already handed to someone else, a use-after-free on three harts at ten
ticks a second. And because kprof is never cleared, every later kernel profile is
refused: the second prof -k echo hi printed prof: profile failed, and proftest
reported a kernel profile: FAIL. (The first prof -k got no prof.out for the
design reason above.) Freeing anything a lock-protected global still points to must
go through the code that unhooks it.
5Wrote prof.out from freeproc
The learner keeps all the profile’s end-of-life code together, in freeproc:
// kexit
- if (p->prof)
- profdump(p);
// freeproc
- if (p->prof)
+ if (p->prof) {
+ profdump(p); // save the profile before freeing it
kfree((void *)p->prof);
+ }
What happened when we ran it
$ proftest
proftest: arguments, and profile(0, 0, 0) stops: OK
proftest: hot loop: 29 samples, 29 in range, 29 in hot()
proftest: most samples in the hot loop: OK
proftest: fork does not inherit the profile: OK
panic: acquire
(another boot, gdb attached with a breakpoint on panic:)
Thread 2 hit Breakpoint 1, panic (s=s@entry=0x80007048 "acquire") at kernel/printk.c:139
[...]
#0 panic (s=s@entry=0x80007048 "acquire") at kernel/printk.c:139
#1 0x0000000080000c28 in acquire (lk=lk@entry=0x80010240 <proc+1104>) at kernel/spinlock.c:26
#2 0x0000000080001fd8 in wakeup (chan=chan@entry=0x8001e110 <itable+40>) at kernel/proc.c:586
#3 0x000000008000406a in releasesleep (lk=lk@entry=0x8001e110 <itable+40>) at kernel/sleeplock.c:42
#4 0x0000000080003340 in iunlock (ip=ip@entry=0x8001e100 <itable+24>) at kernel/fs.c:328
#5 0x0000000080003988 in namex (path=0x80007640 "", path@entry=0x80007638 "prof.out", nameiparent=nameiparent@entry=1, name=name@entry=0x3fffff9ec0 "prof.out") at kernel/fs.c:713
#6 0x0000000080003b20 in nameiparent (path=path@entry=0x80007638 "prof.out", name=name@entry=0x3fffff9ec0 "prof.out") at kernel/fs.c:740
#7 0x000000008000503a in create (path=path@entry=0x80007638 "prof.out", type=type@entry=2, major=major@entry=0, minor=minor@entry=0) at kernel/sysfile.c:264
#8 0x0000000080005976 in profdump (p=p@entry=0x80010240 <proc+1104>) at kernel/prof.c:145
#9 0x0000000080001b00 in freeproc (p=p@entry=0x80010240 <proc+1104>) at kernel/proc.c:162
#10 0x0000000080002220 in kwait (addr=24492) at kernel/proc.c:403
#11 0x00000000800029bc in sys_wait () at kernel/sysproc.c:36
#12 0x000000008000292a in syscall () at kernel/syscall.c:150
#13 0x000000008000268c in usertrap () at kernel/trap.c:69
#14 0x0000003ffffff09c in ?? ()
$1 = (void *) 0x1
$2 = 4
$3 = 1
$4 = 3
$5 = "proftest\000\000\000\000\000\000\000"
[...]
The first profiled child to be reaped is the one proftest execs to check that exec
keeps the profile. Its parent, proftest (pid 3, $4), reaps it in kwait, which
holds wait_lock and the zombie’s p->lock (the slot at proc+1104), and calls
freeproc, which now calls profdump.
create looks up prof.out in the parent’s current directory, /. namex locks
the directory inode and unlocks it again (iunlock), which is a sleep-lock release:
releasesleep calls wakeup for anyone waiting on that inode. wakeup walks the
whole process table and acquires each p->lock to look at the process. At
proc+1104 it reaches the zombie, whose lock this hart already holds, and acquire
panics rather than spin forever (frame #1). noff was 4 ($2): wait_lock, the
zombie’s lock, the inode’s inner spinlock, and the push_off that acquire does before
it checks.
Had it got past that, the first disk read would have slept with spinlocks held and
sched would have panicked with sched locks. Any code that may sleep, and anything
that releases a sleep-lock, must run with no spinlock held. The reference writes the
file in kexit, as the exiting process, before it takes wait_lock, and leaves
freeproc only the kfree, which takes nothing but kmem.lock.
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 (ext/07-profiler, 8 commits), built with the project toolchain and run on
three harts (-smp 3 -m 128M), in one boot: proftest four times, usertests -q, then
proftest four more times. All eight proftest runs printed ALL OK. The first one and
the one right after usertests:
$ proftest
proftest: arguments, and profile(0, 0, 0) stops: OK
proftest: hot loop: 30 samples, 30 in range, 30 in hot()
proftest: most samples in the hot loop: OK
proftest: fork does not inherit the profile: OK
proftest: exec keeps the profile: OK
proftest: prof.out: 20 samples, 20 in range, 20 in hot()
proftest: exit writes prof.out: OK
proftest: only one kernel profile at a time: OK
proftest: kernel: 30 samples, 0 outside [0x80000000, 0x8000FE00)
proftest: kernel samples, none outside the profiled range: OK
proftest: free pages 32470 before, 32470 after
proftest: no leaks: OK
proftest: ALL OK
[...]
$ usertests -q
usertests starting
[...]
ALL TESTS PASSED
$ proftest
proftest: arguments, and profile(0, 0, 0) stops: OK
proftest: hot loop: 30 samples, 30 in range, 30 in hot()
proftest: most samples in the hot loop: OK
proftest: fork does not inherit the profile: OK
proftest: exec keeps the profile: OK
proftest: prof.out: 20 samples, 20 in range, 19 in hot()
proftest: exit writes prof.out: OK
proftest: only one kernel profile at a time: OK
proftest: kernel: 30 samples, 0 outside [0x80000000, 0x8000FE00)
proftest: kernel samples, none outside the profiled range: OK
proftest: free pages 32470 before, 32470 after
proftest: no leaks: OK
proftest: ALL OK
Over the eight runs the 30-tick hot loop got 30 samples every time, all inside hot(),
and the 20-tick child that leaves prof.out got 19 or 20. (A tick-driven count can
always come out one short: a 10-tick child required to get at least 10 samples was seen
to get 9, which is why this child spins for 20.) The idle second of
the kernel gave 30 to 33 samples: three harts, ten ticks each. usertests -q passing (its
usertrap() lines, trimmed here, are the expected kills of kernmem and friends) shows
that processes that never profile are unaffected, and the equal free-page counts show
that profiled processes leave no page behind. usertests -q also passed under prof -k
(in both kernel runs of Measure), with the kernel profile active on all three harts
throughout. In the same build, /prof /grep .*.*.*z /README and /prof -k /echo hi run
from a subdirectory found their .sym files, which prof opens from /.
Every commit builds on its own with make kernel/kernel fs.img (only the two existing
warnings about RWX segments).
User profiles of real programs.b1 is README eight times (19,528 bytes), b2 is
b1 eight times (156,224 bytes), both made with cat inside xv6.
The pattern makes grep’s recursive matcher backtrack, and the profile finds the loop:
the bucket at matchstar+0x24 holds one instruction, bnez a0 at 0x26, the first one
after matchstar’s call to matchhere returns, inside its do ... while. Two thirds of
all samples landed there. That concentration is partly QEMU’s doing: QEMU executes
guest code in translated blocks and takes pending interrupts between blocks, so samples
land on block entry points such as this return address (and proftest’s 0x112, a loop
head). A test confirms it: with a loop whose body is about a hundred
instructions with no branch inside, over three runs, 248 of 249 samples landed in the loop-head bucket,
where an interrupt that could be taken anywhere would have spread them over the body. It
also shifts time between functions: the time of a block of matchhere that ends in ret
is charged to matchstar’s return address. On real hardware the samples would spread
over the instructions actually executing, and the split between matchstar and
matchhere could differ (reasoned, not measured). 61 samples in 72 ticks: grep was in
user mode for most of its run.
wc on 937 KB took 5.5 seconds and got one user sample. The kernel profile of the same
run explains it: 156 of the 159 hart-ticks (3 harts × 53) were kernel samples, and 151 of
them were idle schedulers. wc spends its time asleep, waiting for the disk (the buffer
cache holds 30 blocks, b2 is 153). A sampling profiler measures where the CPU goes, and
an I/O-bound program barely uses one.
Statistics. Six runs of prof grep .*.*.*z README (the three that printed a tick count
took 9 to 12 ticks) gave 7 to 10 samples each; matchstar’s share came out as 87%, 100%, 50%, 70%, 71% and 62%. Two runs
on b1 (60 and 61 samples) gave 65% and 78%. That is the spread sqrt(p(1-p)/n) predicts
(16 points at n = 8, 6 at n = 60). The hot loop in proftest got 28 to 30 samples for 30
ticks in every run on the branch, including one with three CPU-bound greps competing for
the three harts.
The kernel profile of usertests -q, all of the kernel’s text, 32-byte buckets:
The pop_off+0x18 bucket covers 0x80000c40–0x80000c5f, which contains 0x80000c50;
the usertrap+0x92 bucket contains 0x80002690, the instruction after usertrap’s
csrsi sstatus,2. In 1,173 ticks the three harts took about 3,519 timer
interrupts (3 × 1,173, assuming one per hart per tick); 3,467 of them found the hart in the kernel, and 3,110 of those in the idle
scheduler. Under QEMU, usertests mostly waits for its disk. Almost all the non-idle
kernel samples are on three instructions, each the first after interrupts come back on:
in pop_off (time spent in critical sections), in usertrap after intr_on() (trap
entry), and in the scheduler (idle). The release bucket at 0x80000ca0 is really
memset’s loop at 0x80000cbc, which shares the 32-byte bucket.
The blind spot at instruction resolution: the 642 bytes from kfree to the end of
release, 2-byte buckets, over another full usertests -q run:
kalloc, kfree, acquire and release ran throughout, and no sample landed in any of
their critical sections, nor in acquire’s spin loop: every interrupt that arrived there
was delivered at 0x80000c50.
7. Go further
A profiler that sees critical sections. Count, in pop_off, how many timer
interrupts were pending when SIE came back on (sip.STIP), and attribute them to the
lock just released (pass its name down from release). Teaches the difference between
when an event happens and when the kernel notices it, and gives a crude lock-hold-time
profile.
Call stacks, not just pcs. At each sample, walk the user stack’s frame pointers
(xv6 compiles with -fno-omit-frame-pointer) with copyin and count call chains.
Teaches the user stack layout and why the kernel must not trust it.
Profile across fork. Give children a copy of the settings and merge their counts
into the parent’s histogram when kwait reaps them, so prof sh covers a whole
pipeline. Teaches which struct proc fields a parent may touch, and when.
Faster sampling. Program a second, faster stimecmp deadline for profiled
processes only, and measure what a 1 kHz profile costs in time and gains in precision.
Teaches what clockintr really controls and why the scheduler quantum and the sampling
period need not be the same.