Step 1 of 16 · commit 1: Add per-process CPU time fields

Five counters in the private part of struct proc

The story for this tour: on a fresh boot with three harts you type time cputest spin 200. The shell forks pid 3, which execs time; time forks pid 4, which execs cputest, spins for about 0.36 s and exits. The run was recorded under gdb (the GNU debugger) with breakpoints at every new line, so harts, pids, lock states and time values below come from it (the breakpoints slow the run, so absolute durations are inflated). It printed real 0.380, user 0.360, sys 0.015. The state shown here is the first time these fields are used, two steps from now.

Five uint64s, all in ticks of the time CSR: tstamp, when the current stretch of running began, and four sums. They sit with sz, ofile and name in the section “private to the process, so p->lock need not be held” (kernel/proc.h:95). While it lives, only the process itself writes them, from the code it runs in the kernel; freeproc clears them once it is gone (next step). The parent reads a dead child’s counters, but only under the child’s p->lock, which it holds at that moment anyway (step 11).

uint64 because the clock is 64 bits wide and counts 10,000,000 a second: a 32-bit counter would wrap after seven minutes.

Step 2 of 16 · commit 1: Add per-process CPU time fields

freeproc gives the next process a clean slate

Jump to the end of the story: time (pid 3) is reaping cputest (pid 4) in kwait, which holds wait_lock and the child’s p->lock (noff 2; intena 1 because the first acquire happened inside a system call with interrupts on). The gdb run stopped here on hart 2.

freeproc returns the slot to UNUSED, and the five new lines zero the counters. This matters more than the similar line in lab 1, because fork never writes these fields. A child starts with whatever the slot holds. A kernel without these five lines (a separate experiment) showed it: cputest reported new child: user 194152 us, sys 7106 us for a process that had run for microseconds, exactly the previous occupant’s time. Three runs of time cputest spin 100 in a row printed user 1.970, user 2.202 and user 2.439 for about 0.2 s of real time each, as the same slot kept accumulating.

Step 3 of 16 · commit 2: Charge user and kernel time at the trap boundary

The first C after a trap ends the user stretch

time has just executed the ecall in its cputime stub (sepc 0x4f2) and uservec has brought it here. As soon as usertrap knows the process (line 49) it reads the clock: everything since tstamp was user time. In the gdb run now was 5,191,317 and tstamp 5,190,271, so 1,046 ticks (104.6 µs) went to utime: the time from exec’s return to this first system call.

Interrupts are still off: the trap turned them off, and line 71 turns them back on only for system calls. No timer can interrupt these three lines. The same holds wherever the counters are written; the one place that reads them with interrupts on is step 14’s problem.

Every trap from user mode comes through here: system calls, device and timer interrupts, page faults. So every one of them ends the user stretch, which settles the question “whose time is an interrupt?”. The interrupted process pays, as system time.

Step 4 of 16 · commit 2: Charge user and kernel time at the trap boundary

The last C before the return ends the kernel stretch

The system call is done. prepare_return turned interrupts off at line 113 and set up stvec, the trapframe, sstatus and sepc. Its last act now is to add the kernel stretch to stime and start a new user stretch. In the gdb run this was the return from that first cputime call: now 5,193,745, tstamp 5,191,317, so 2,428 ticks of system time, inflated by the breakpoint stop inside the call.

prepare_return is called from two places: usertrap, and forkret for a process’s very first return. So one charge here covers both roads to user mode. What it does not cover is what follows. usertrap returns the user satp to uservec’s jalr (kernel/trampoline.S:98), which falls into userret. All of that is now counted as user time. The next step looks at how much that is.

Step 5 of 16 · commit 2: Charge user and kernel time at the trap boundary

Between the C code and the mode switch

This file did not change, and that is the point. Between the charge at the end of prepare_return and the sret that really enters user mode, the hart still returns through usertrap and then runs fence.i (line 107), sfence.vma (110), csrw satp (111), another sfence.vma, 31 loads and sret. On the way in, uservec ran 31 stores, two sfence.vma and a csrw satp before usertrap's first line. The reference charges all of it as user time.

How much is that? A scratch copy of the kernel also read time in the trampoline itself (right after uservec saves the registers, and right after userret switches satp) and kept a second ledger with the boundary there. For a loop of getpid calls, 3 s of real time:

On QEMU about two thirds of a system call’s time is spent in these few dozen instructions. A likely explanation, not measured instruction by instruction: QEMU emulates the TLB in software, and changing satp and fencing are expensive for it; real hardware has different proportions. For a program that mostly computes the difference is small (the spinner: 2.89 to 2.90 s against 2.73 to 2.77 s of user time). Moving the boundary into the trampoline is one of the stretch goals.

Step 6 of 16 · commit 3: Stop the clock while a process is switched out

sched stops the clock before the switch

time has forked cputest and called wait. kwait found no zombie, and sleep took time’s own p->lock, set SLEEPING and called sched. Every way a process gives up a hart (yield, sleep, kexit) comes through here, holding exactly its own p->lock with interrupts off (the checks on lines 490-497 insist on both). So this is the one place to stop the clock: line 500 adds the kernel stretch up to the switch. In the gdb run, time was 5,198,020 and tstamp 5,197,263, so 757 ticks were added.

From the swtch on line 503 until the process comes back, nothing is charged to it: not the scheduler’s scan, not other processes, not an idle hart’s wfi. Without these lines that whole interval would be added at the next charge (clinic 2: pause(5) came out as sys 470 ms).

Writing stime needs no extra lock, and taking one here would be fatal: this hart already holds p->lock, and acquiring it again panics (clinic 4).

Step 7 of 16 · commit 3: Stop the clock while a process is switched out

Running again, perhaps on another hart

swtch has returned, on a different hart. In the gdb run pid 4 (still called time, because exec renames a process only when it succeeds) was inside exec on hart 2 when hart 2’s timer fired. kerneltrap called yield, and sched stopped the clock (gdb read time = 5,293,746 at the breakpoint just before the rdtime). The process switched out, and hart 0’s scheduler picked it up. Line 507 restarts the clock (gdb read 5,295,602 at that breakpoint). The 1,856 ticks in between, with pid 4 RUNNABLE and not running, are charged to nobody.

The kernel never subtracts these two numbers: it closed the stretch on hart 2 and opens a new one on hart 0, so every stretch is measured on one hart. The 1,856-tick figure means something only because the harts’ clocks are synchronized; the accounting itself would not need that. The intena restored by line 504 is 0, the value sched saved: this process gave up the hart from inside an interrupt handler, where interrupts were off (Locks and interrupt state). (gdb could not unwind past kernelvec; the earlier stops of this run place pid 4 inside kexec, reading the program from disk.)

The interrupt itself, and the yield up to line 500, were inside pid 4’s kernel stretch: they are its system time, although the timer interrupt was not “for” it any more than for anyone else.

Step 8 of 16 · commit 3: Stop the clock while a process is switched out

A timer interrupt from user mode

Now cputest is spinning in user mode, and the timer fires on its hart. The trap ended the user stretch at the top of usertrap (step 3); devintr and clockintr ran in a new kernel stretch; now yield will go through sched, which stops the clock, and restart it when the scheduler picks cputest again.

With three harts and nothing else to run, that happens at once. In the gdb run cputest resumed from such a yield on hart 2 at time 6,296,818, with utime at 942,834 ticks. An earlier recorded run of the same command caught two of these yields, 0.1 s apart. Both stopped and resumed on hart 0, 0.2 ms later. A spinner is preempted every 0.1 s, but it loses only the scheduler’s scan. Interrupts are off here (they are turned on in usertrap only for system calls), so the acquire in yield records intena 0.

Compare the sampling design from the first question. It would charge this whole 0.1 s period at this moment, to whatever mode the interrupt found.

Step 9 of 16 · commit 3: Stop the clock while a process is switched out

A new process starts its clock in forkret

pid 4’s first swtch landed here, not after the swtch in sched: allocproc set context.ra to forkret (kernel/proc.c:146). The gdb run stopped on this line with tstamp 0, as freeproc left it, and time 5,198,418. Line 532 starts the clock there.

Without it, the first charge, in the prepare_return this function calls (line 554), would be time - 0: the time since boot (clinic 3 printed sys 4.966 for echo hi). With it, that first charge was 227 ticks (22.7 µs): forkret and the return preparation.

The process still holds the p->lock its scheduler acquired, taken with interrupts off, so intena is 0 and the release on line 535 leaves them off. Setting tstamp before or after that release makes no difference: no one else touches it.

Step 10 of 16 · commit 3: Stop the clock while a process is switched out

The zombie's last charge

kexit did not change, but it now ends with a charge. It took the process’s p->lock on line 360, set ZOMBIE, released wait_lock (line 365) and calls sched, which adds the final kernel stretch, the time spent closing files and in kexit itself, before switching away for ever. A second gdb run (another boot, same command, which printed real 0.435) stopped in sched for this zombie on hart 2: noff 1, intena 1, stime 153,287 ticks before the addition, with 7,016 ticks since tstamp.

The lock is the whole point. It is held from line 360 through the charge and the switch, and released by hart 2’s scheduler after swtch returns there. Any parent that wants to read these counters must acquire it first, so it cannot read them before this last addition. In that second run the parent read stime 160,720, a little more than 153,287 + 7,016, because the clock ran on between the breakpoint and the rdtime.

Step 11 of 16 · commit 4: Add a reaped child's CPU time to its parent

wait passes the child's time to the parent

Back to the first run. time (pid 3) woke up in kwait, found its child a ZOMBIE under the child’s lock (line 389), and copied out the exit status. Now it adds the child’s counters, and the child’s own children totals, to its own cutime and cstime. In the gdb run the child had utime 3,600,731 and stime 158,327 ticks: time printed them as user 0.360 and sys 0.015.

Why exactly here:

• after the copyout succeeded: if it fails, kwait returns -1 and leaves the zombie to be reaped later, and counting now would count it twice;
• before freeproc (line 407), which zeroes the counters;
• under pp->lock, which orders this read after the child’s last charge (previous step).

The parent’s own fields need no lock: p is the process running this code.

Step 12 of 16 · commit 5: Add the cputime system call

One struct crosses the boundary

The system call copies out one struct, defined in a header that both the kernel and user programs include, as kernel/stat.h is for fstat. All five values are microseconds: the kernel converts, so user programs need not know the clock’s rate.

real is there because user mode cannot read the clock itself. A test program that executed rdtime was killed: usertrap(): unexpected scause 0x2 pid=3, an illegal instruction, because scounteren is 0. uptime() would give only hart 0’s 0.1 s ticks.

The commit also does the registration from lab 1: SYS_cputime 23 in syscall.h, the extern and table entry in syscall.c, entry("cputime") in usys.pl, and int cputime(struct cputime *); (with struct cputime; declared) in user.h.

Step 13 of 16 · commit 5: Add the cputime system call

The clock's rate, from the machine

10,000,000 is QEMU’s number, not xv6’s: the virt machine’s device tree says timebase-frequency = <0x989680> (dumped with -machine virt,dumpdtb= and dtc). xv6 never reads the device tree. The only other place that depends on the rate is clockintr, whose comment calls 1,000,000 “about a tenth of a second”. Naming the rate once means the conversion has one place to be right (clinic 6 got it wrong: every number came out 10 times too large).

Step 14 of 16 · commit 5: Add the cputime system call

Reading the running clock with interrupts off

stime alone would leave out the current stretch: the time since this system call began. So the call computes stime + (time - tstamp). In the gdb run, at line 131, tstamp was 5,191,317 (the trap, step 3) and time 5,192,249.

This is the one place that reads the counters with interrupts on, and the reason for push_off. A timer interrupt between the clock read and the field reads could yield, and sched, running as this same process, would add to stime and move tstamp. The result would come out short by the time spent switched out. The writer is this process on this hart, so what excludes it is turning interrupts off on this hart for three loads (an acquire would do the same only because it calls push_off). gdb showed noff 1 and SIE 0 at this line. Clinic 5 is the version without it: cputest saw stime go backwards.

utime, cutime and cstime need no such care. Only usertrap's entry and kwait change them, and the process is in neither right now. Each division by tpus (10) turns ticks into microseconds. copyout checks the user address, as for fstat.

Step 15 of 16 · commit 6: Add the time command

time reads the totals before and after

time asks for the totals before fork and after wait and prints the differences. After the wait, the child (and anything it reaped) is in time’s own children totals. Subtracting the “before” values is not strictly needed for a fresh time process, whose totals start at 0, but it keeps the program correct anywhere. real is the difference of two readings of the same clock.

In the gdb run the system calls were cputime (trap at 0x4f2), fork (0x442), wait (0x452), and cputime again, all on hart 2; the child exec’d from 0x482.

show prints whole milliseconds as seconds with three decimals by hand, because the user printf has no field widths or zero padding.

Step 16 of 16 · commit 7: Add cputest

The test measures what a program can see

Each of the ten checks compares numbers the program obtains itself. Nothing is left to the eye, so the last line may say all 10 checks OK. Two of them guard against mistakes that look plausible in a review.

• Check 7 (lines 214-229): three children spin for 0.5 s each on three harts, and their total user time must be at least 1.5 times the real time. Sampling on hart 0 only (clinic 1) gave user 400 ms for real 522 ms.
• Check 8 (lines 231-245): four processes, one more than there are harts, call cputime() as fast as they can for 2 s and count the times stime went down. More processes than harts means timer interrupts make them yield in the middle of system calls, which is exactly the race of the previous step. The count comes back as the exit status. Clinic 5’s kernel failed it in two of three runs. A race this narrow can slip through one run, so the check says what it measured, not that the code is race-free.

Check 3 compares with hart 0’s ticks through pause(5), the one clock the accounting did not produce, which is what catches a units mistake (clinic 6).