Extension labs · lab 4 · The system-call and trap path · ★★☆☆☆

CPU time accounting and a time command

You teach the kernel to keep, for every process, how much time it spent running in user mode and how much in the kernel, and you add a time command:

$ time cputest spin 1000
real 1.955
user 1.950
sys  0.003

Measuring time sounds simple until you ask the questions this lab is built on. Which clock do you use when every hart takes its own timer interrupt but only one of them counts ticks? Exactly where does a process stop being “in user mode”: at the ecall, or at the first line of C? What happens to its clock while it sleeps, while it waits for a hart, and on the hart it lands on afterwards? Whose time is an interrupt that arrives on behalf of some other process? Who may read a dying process’s numbers, and under which lock? You answer each one, then measure the answers on three harts: the clock you chose against the one you rejected.

Read first: Tour 5: Life of a system call, Tour 11: From a timer tick to a context switch, Tour 13: swtch and the lock handed across a context switch, Tour 21: exit, wait and zombies, Tour 43: A system call, CSR by CSR, Tour 45: One complete time slice on three harts, Tour 50: noff and intena through a sleep, a yield and an interrupt · The stacks of xv6, Locks and interrupt state

What this lab teaches

Every point at which a running process crosses between user mode, the kernel and not running at all, and which C function is the first or last to run on each side of each crossing.
What the timer interrupt in this tree really is (which harts take it, how often, and who counts ticks), and what that means for any statistic built on it.
What time CSR access each privilege mode has in this tree, and how to find the clock’s rate from the machine itself rather than from a comment.
Which lock, if any, per-process counters need, whether a process can race with itself, and when a parent may safely read a dead child’s fields.
What a process’s own kernel time includes and excludes: spinning, sleeping, interrupts for other processes, the scheduler’s work.
How much a system call’s round trip costs on QEMU, and how much of it happens outside the C code.

The reference branch

ext/04-cputime in ShowMeTheStack/xv6-riscv-labs, branched from the frozen commit 06aad25; 7 commits.

git clone https://github.com/ShowMeTheStack/xv6-riscv-labs
cd xv6-riscv-labs
git checkout -b my-cputime 06aad25   # start your own
git diff 06aad25 origin/ext/04-cputime   # only when you want the answer

1. The spec

The accounting. Every process has a user time and a system (kernel) time. User time grows while the process runs in user mode; system time grows while the kernel runs on the process’s behalf (system calls, faults, interrupts taken while it runs). Neither grows while the process is not running: asleep, waiting for a hart, or a zombie. A new process starts at zero.

Children. When a process reaps a child with wait, the child’s user and system time, plus the totals of the child’s own reaped children, are added to the parent’s children totals. Children that have not been reaped do not count.

The system call. int cputime(struct cputime *ct) fills in, in microseconds:

struct cputime {
  uint64 real;   // time since boot
  uint64 utime;  // user time of the calling process
  uint64 stime;  // kernel time of the calling process
  uint64 cutime; // user time of reaped children
  uint64 cstime; // kernel time of reaped children
};

It returns 0, or -1 if ct is not a valid address. The struct lives in a new header, kernel/cputime.h, that user programs include. Successive calls must never see stime go down.

The command. time command args... runs the command and prints, on standard error, the real time it took and the user and system time of the command (including anything the command itself reaped), in seconds with three decimals, like time -p on Unix:

$ time cputest sys 100
real 1.458
user 1.036
sys  0.420

The test. cputest prints OK or FAIL for ten checks, each of which it measures itself (nothing is left to the eye): a CPU-bound loop is mostly user time; system calls add system time; pause(5) takes between 0.3 and 1.5 s of real time (which checks the units) and adds almost no CPU time; a child’s time is not counted before wait and is counted after; a new process starts at almost zero, even in a reused process slot; a grandchild’s time arrives through its parent; three processes spinning on three harts use more CPU time than real time; and four processes calling cputime() for 2 s never see their system time go backwards. It also provides workloads for time: cputest spin N, cputest par N (three spinners at once), cputest sys N and cputest sleep N.

$ cputest
cputest: spin: real 300 ms, user 290 ms, sys 9 ms
cputest: a CPU-bound loop is mostly user time: OK
[...]
cputest: 3 spinning children: real 521 ms, user 1440 ms, sys 59 ms
cputest: on 3 harts, 3 spinners use more CPU time than real time: OK
cputest: 4 processes calling cputime() for 2 s: sys went backwards 0 times
cputest: kernel time never goes backwards: OK
cputest: all 10 checks OK

The three-spinner check assumes three harts (make qemu uses CPUS := 3).

Constraints. usertests -q must still print ALL TESTS PASSED on three harts. Keep the system-call path cheap. Do not change existing system call numbers.

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.

1Which clock?

Before writing anything, decide how the kernel will know how long a process ran. This tree has two clocks you could build on: the timer interrupt, and the time CSR that the timer is programmed from. For each, find out: how often does it tick, on which harts, who can read it, and what would “charge this process” look like? Then pick one.

Check yourself

1warm-upType a number

clockintr asks for the next timer interrupt 1,000,000 ticks of time after it handles one, and time counts at 10 MHz in QEMU’s virt machine. About how many timer interrupts does each hart take per second?

decimal, 0x hex or 0b binary

2solidChoose one

A learner charges 0.1 s of user or system time to myproc() right next to ticks++ in clockintr, inside the if (cpuid() == 0) block. Three processes spin in user mode for 3 s, one on each hart. About how much user time is charged to the three of them together?

0, because a timer interrupt never arrives in user modeAbout 1 sAbout 9 sAbout 3 s

2Where does the process cross between user mode and the kernel?

With the time CSR, each process needs a timestamp for “the current stretch began at”, and at each crossing you add the elapsed time to user or system time and start a new stretch. Name the points where a process goes from user mode into the kernel and back, in the order a system call meets them. Where is the first C code after the trap, and the last C code before the return? What runs in between, and whose time will it be?

Check yourself

1solidPut in order

Put the events of one getpid() round trip in order, in the reference design.

prepare_return adds the stretch since tstamp to system time
uservec saves the registers and installs the kernel page table
userret installs the user page table
usertrap adds the stretch since tstamp to user time
ecall: the hart traps into supervisor mode
sret: back in user mode
syscall runs sys_getpid

2solidTrue or false, and why

True or false: with the kernel-to-user charge at the end of prepare_return, a forked child’s first trip to user mode is also charged, even though the child never passes through usertrap on its way out of fork.

TrueFalse

Why?

False: the scheduler returns the child to user mode directly.True: the child does pass through usertrap, as a copy of the parent’s call.False: kfork charges the child instead.True: forkret calls prepare_return before jumping to userret.

3What happens to the clock while the process is not running?

With only the two charges from the previous question, follow pause(5): the process enters the kernel, sleeps about half a second while other processes run or the harts sit idle, then returns. What would be added to its system time? Where must the clock stop and restart instead? Is there a process for which your restart point never runs?

The reference design

Without a stop, the whole half second (including the time other processes ran and the idle wfi of empty harts) is added as system time when pause returns: clinic 2 recorded pause(5): real 470 ms, user 0 ms, sys 470 ms.

Every way of giving up the hart (yield, sleep, kexit) goes through sched, so sched is the one place to stop the clock: add time - tstamp to system time before swtch, and set tstamp = time after swtch returns. The time in between, on the scheduler stack, in other processes or in wfi, is charged to nobody. So is the kernel work done there: the swtch itself, the scheduler’s scan, interrupts taken in the scheduler loop. The CPU times of all processes therefore add up to less than harts × real time, even on a fully busy machine.

A new process never returns from sched: allocproc set its context.ra to forkret, so its first swtch lands there. If forkret does not set tstamp, the first stretch is measured from whatever tstamp holds, 0 for a cleared slot: the whole time since boot becomes system time (clinic 3).

What this design counts as the process’s system time:

the process is…	counted?
running kernel code for itself	yes
spinning in `acquire` for a spinlock	yes, it is running
asleep waiting for a sleep-lock, a disk read, a child	no
RUNNABLE, waiting for a hart	no
handling an interrupt that arrived while it ran	yes (next question)

Check yourself

1solidChoose all that apply

In the reference design, which of these add to a process’s system time?

The scheduler’s scan of proc[] after the process yieldsBeing RUNNABLE while all three harts run other processesSpinning in acquire while another hart holds the spinlockRunning kexit’s file closing and iputSleeping in acquiresleep while another process holds the sleep-lock

2deepType a number

A learner forgets the line in forkret. freeproc had cleared tstamp to 0. A new child’s first prepare_return reads time = 23,000,000. How many milliseconds of system time is the child charged for that first stretch?

decimal, 0x hex or 0b binary

4Whose time is an interrupt?

Process A is in user mode on hart 1 when hart 1 takes a disk interrupt that completes process B’s read. Later, A is in a system call when hart 1’s timer fires. With your design so far, who is charged for each handler, and as what? Is that fair? What would it take to do better?

Check yourself

1solidChoose one

cat is in user mode on hart 2 when hart 2 takes the disk interrupt that completes sh’s read. In the reference design, the time spent in virtio_disk_intr is charged to:

Nobody, because interrupt handlers do not belong to a processcat’s user timecat’s system timesh’s system time

5Which lock protects the counters?

List every place that writes utime, stime and tstamp, and every place that reads them, including the parent that will collect them and the system call that reports them. For each, which process is it running as, and are interrupts on? Then decide: does any of it need p->lock, or another lock, or something else?

The reference design

where	runs as	interrupts	needs
`usertrap` entry, end of `prepare_return`	the process	off	nothing
`sched`	the process, holding its `p->lock`	off	nothing, and it must not take `p->lock` again (clinic 4)
`forkret`	the new process, holding the `p->lock` the scheduler took	off	nothing
the system call reading its own running clock	the process	on	interrupts off for the read (clinic 5)
the parent reading a ZOMBIE child in `kwait`	the parent	off	the child’s `p->lock`, already held

The fields go in the private section of struct proc, for the reason tracemask did in lab 1: one process, one thread, one hart at a time.

The parent. A child’s last charge happens in sched called from kexit, which holds the child’s p->lock from kernel/proc.c:355 through the switch; the scheduler releases it (kernel/proc.c:463). kwait reads the counters after acquire(&pp->lock) (kernel/proc.c:384) and only if the state is ZOMBIE, so the release/acquire pair orders the child’s last store before the parent’s load. No new lock is needed: the right one is already held.

The race with itself. The system call that reports the times wants stime + (time - tstamp), including the current stretch. Interrupts are on during a system call. If a timer interrupt lands between reading time and reading tstamp and the process yields, sched adds the stretch to stime and moves tstamp forward. The pair read afterwards is inconsistent, and the result is short by the time the process spent switched out. The “other thread” is the same process on the same stack, so mutual exclusion between harts is not what is needed. Turning interrupts off for the three reads (push_off/pop_off) is. Taking p->lock would happen to fix it too, but only because acquire calls push_off: the interrupts being off is what excludes the other party, so the honest tool is push_off itself. It is an easy bug to write, and clinic 5 shows it.

Check yourself

1deepTrue or false, and why

True or false: because only the process itself ever writes its stime and tstamp, a system call can compute stime + (time - tstamp) with interrupts on.

TrueFalse

Why?

True: system calls run with interrupts off.False: a timer interrupt can make the process yield between the reads, and sched, running as the same process, changes both fields.True: 64-bit loads are atomic, so each value is read whole.False: another hart’s scheduler updates the fields while the process runs.

2solidFill in the machine state

A child has called exit. kexit has called sched, which is about to add the final stretch to stime. Fill in the machine state of the hart running it.

Privilege modeActive stackPage table (satp)Interrupts (sstatus.SIE)noffintena

6How does the parent get its child's time?

time must report the CPU time of a command that, by the time time asks, has exited. Where are the child’s counters still readable, by whom, and until when? Should a grandchild’s time count too? Then design the system call time will use.

The reference design

The counters live in the zombie’s struct proc until kwait calls freeproc. kwait is the only code that sees the zombie, it holds the zombie’s lock, and it runs as the parent, so it can add to the parent’s fields without a lock:

p->cutime += pp->utime + pp->cutime;
p->cstime += pp->stime + pp->cstime;

Put it after the exit status copyout succeeds. If the copyout fails, kwait returns -1 and leaves the zombie in place, to be reaped (and counted) by a later call. Adding before it would count the child twice. Including pp->cutime makes the totals recursive, so time sh counts the commands that shell ran, as Unix does.

The interface follows Unix times(): one call, cputime(&ct), that copies out {real, utime, stime, cutime, cstime}. time reads it before fork and after wait and prints the differences. A waitx(&status, &utime, &stime) that returns one child’s times as it reaps it would work as well. The totals generalise better: a parent that waits for many children can still ask “how much did all of that cost”.

Check yourself

1solidClick the line

Here is kwait in the original tree. Click a line right before which the two additions to cutime and cstime can go.

kernel/proc.c

      acquire(&pp->lock);
385
      havekids = 1;
      if (pp->state == ZOMBIE) {
        // Found one.
        pid = pp->pid;
        if (addr != 0 &&
            copyout(p->pagetable, p->sz, addr, (char *)&pp->xstate,
                    sizeof(pp->xstate)) < 0) {
          release(&pp->lock);
          release(&wait_lock);
          return -1;
        }
        pp->parent = 0;
        freeproc(pp);
        release(&pp->lock);
        release(&wait_lock);
        return pid;
      }

Your pick: none yet (click a line in the code)

2deepChoose one

You run time sh, type cputest spin 500 to that inner shell (it takes about 1 s of user time), then Ctrl-D. What does time print as user?

Almost 0, because the inner shell was mostly asleep waiting for inputAbout 1 s, because the inner shell reaped cputest and its totals include itIt depends on whether cputest exited before shAlmost 0, because cputest is not a child of time

7What units cross the boundary, and where does real time come from?

The counters hold ticks of the time CSR. What should the system call hand back: ticks, or something else? How will time know how much real time passed? And how fast does the clock tick? Find out from the machine, not from a comment.

Check yourself

1warm-upType a number

QEMU’s device tree says timebase-frequency = <0x989680>. How many ticks of time are there in one microsecond?

decimal, 0x hex or 0b binary

2solidChoose one

A user program in this tree executes rdtime a1. What happens?

The kernel panicsThe hart traps with an illegal-instruction exception and usertrap kills the processa1 gets the current time, because start.c set mcounterena1 gets 0

3. Build it

Start from the frozen commit, in your own clone of xv6:

git checkout -b my-cputime 06aad25

Work in this order; every step builds and boots.

The fields. tstamp, utime, stime, cutime, cstime (all uint64) in the private part of struct proc; clear them in freeproc. Nothing changes yet.
The trap boundary. Charge user time at the top of usertrap (after p = myproc()) and system time at the end of prepare_return. Still nothing to see: no one reads the counters.
The switch. Stop the clock in sched before swtch, restart it after; start it in forkret.
Children. The two additions in kwait.
The system call. kernel/cputime.h, TIMEBASE, the five registration points from lab 1 (syscall.h, syscall.c twice, usys.pl, user.h), and sys_cputime with its interrupts-off read. Test with a tiny program that spins, calls cputime and prints.
time, then cputest, then usertests -q, then cputest again.

Debugging. Run QEMU on three harts. Print, don’t guess: a temporary printk of pid, utime and stime in kexit shows each process’s final numbers. In gdb (the GNU debugger) the time CSR is readable as $time, so p $time - cpus[$_thread - 1].proc->tstamp is the current stretch of the process on the selected hart (gdb’s thread N is hart N-1). If you set a breakpoint on a line that only calls r_time(), gdb may answer “No compiled code for line 504”: the inlined rdtime is attributed to riscv.h. Break on the instruction instead (grep rdtime kernel/kernel.asm, then break *0x...). Signs to read:

system time about equal to real time for a sleeper: the clock was not stopped at the switch (clinic 2);
system time of seconds for a program that ran for milliseconds: a stretch started at 0 (clinic 3);
panic: acquire right after boot: a lock taken twice (clinic 4);
every time 10 times too large compared with a stopwatch: units (clinic 6).

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 the timer interrupt on hart 0 only

Instead of reading time at the transitions, the learner charges one timer period to the running process next to ticks++ in clockintr. The four transition charges are removed, and the system call reports stime without a running stretch:

     ticks++;
     wakeup(&ticks);
     release(&tickslock);
+
+    // charge one timer period to the running process.
+    struct proc *p = myproc();
+    if (p) {
+      if (r_sstatus() & SSTATUS_SPP)
+        p->stime += 1000000;
+      else
+        p->utime += 1000000;
+    }
   }

What happened when we ran it

$ cputest
cputest: spin: real 300 ms, user 0 ms, sys 0 ms
cputest: a CPU-bound loop is mostly user time: FAIL
cputest: 20000 getpids: real 459 ms, user 0 ms, sys 0 ms
cputest: system calls add kernel time: FAIL
[...]
cputest: 3 spinning children: real 522 ms, user 400 ms, sys 0 ms
cputest: on 3 harts, 3 spinners use more CPU time than real time: FAIL
cputest: 4 processes calling cputime() for 2 s: sys went backwards 0 times
cputest: kernel time never goes backwards: OK
cputest: 3 FAILED
$ time cputest par 1000
real 2.571
user 2.400
sys  0.000
$ time cputest spin 2000
real 5.035
user 4.500
sys  0.000
$ time cputest spin 2000
real 4.732
user 4.700
sys  0.000
$ time cputest spin 2000
real 4.542
user 4.500
sys  0.000

2Forgot to stop the clock at the switch

The transitions in usertrap and prepare_return are charged and forkret starts the clock, but sched is unchanged:

-  // stop this process's clock while it is not running.
-  p->stime += r_time() - p->tstamp;
-
   intena = mycpu()->intena;
   swtch(&p->context, &mycpu()->context);
   mycpu()->intena = intena;
-
-  // running again, perhaps on another hart: restart the clock.
-  p->tstamp = r_time();
 }

What happened when we ran it

$ cputest
[...]
cputest: pause(5): real 470 ms, user 0 ms, sys 470 ms
cputest: pause(5) takes about half a second of real time: OK
cputest: sleeping adds almost no CPU time: FAIL
[...]
cputest: 1 FAILED
$ time cputest sleep 10
real 0.950
user 0.000
sys  0.947
$ time cputest par 1000
real 2.923
user 8.463
sys  2.931

3Forgot that a new process starts in forkret

sched stops and restarts the clock, but forkret does not start it:

   struct proc *p = myproc();

-  // a new process starts running here, not in sched():
-  // start its clock.
-  p->tstamp = r_time();
-
   // Still holding p->lock from scheduler.
   release(&p->lock);

What happened when we ran it

$ cputest
[...]
cputest: child said user 193 ms, sys 1750 ms; parent got user 193 ms, sys 1751 ms
cputest: wait adds the child's time: OK
cputest: new child: user 67 us, sys 1967660 us
cputest: a new process starts with almost no CPU time: FAIL
cputest: a grandchild's time arrives through its parent: OK
cputest: 3 spinning children: real 526 ms, user 1444 ms, sys 6682 ms
[...]
cputest: 1 FAILED
$ time echo hi
hi
real 0.004
user 0.000
sys  4.966
$ time echo hi
hi
real 0.003
user 0.000
sys  5.465

4Protected the counters with p->lock

A learner decides that fields in struct proc need p->lock and routes every update through one helper, called from usertrap, prepare_return and sched:

void
charge(struct proc *p, uint64 *t)
{
  acquire(&p->lock);
  uint64 now = r_time();
  if (t)
    *t += now - p->tstamp;
  p->tstamp = now;
  release(&p->lock);
}

In sched: charge(p, &p->stime); before swtch and charge(p, 0); after it.

What happened when we ran it

xv6 kernel is booting

hart 2 starting
hart 1 starting
panic: acquire

(a second boot of the same kernel, under gdb with a breakpoint on panic:)
Thread 2 hit Breakpoint 1, panic (s=s@entry=0x80007048 "acquire") at kernel/printk.c:139
[...]
  Id   Target Id                    Frame
  1    Thread 1.1 (CPU#0 [halted ]) s_sstatus (x=2) at kernel/riscv.h:67
* 2    Thread 1.2 (CPU#1 [running]) panic (s=s@entry=0x80007048 "acquire") at kernel/printk.c:139
  3    Thread 1.3 (CPU#2 [running]) 0x0000000080000c0a in acquire (lk=lk@entry=0x8000fdd0 <proc>) at kernel/spinlock.c:37
#0  panic (s=s@entry=0x80007048 "acquire") at kernel/printk.c:139
#1  0x0000000080000c28 in acquire (lk=lk@entry=0x8000fdd0 <proc>) at kernel/spinlock.c:26
#2  0x0000000080001e5a in charge (p=p@entry=0x8000fdd0 <proc>, t=t@entry=0x8000ff48 <proc+376>) at kernel/proc.c:517
#3  0x0000000080001ed6 in sched () at kernel/proc.c:503
#4  0x0000000080001fde in sleep () at kernel/proc.c:599
#5  0x0000000080005bf4 in virtio_disk_rw (b=b@entry=0x80016200 <bcache+24>, write=write@entry=0) at kernel/virtio_disk.c:290
#6  0x0000000080002db4 in bread (dev=dev@entry=1, blockno=blockno@entry=1) at kernel/bio.c:98
#7  0x00000000800036cc in readsb (dev=1, sb=0x8001e8a8 <sb>) at kernel/fs.c:35
#8  fsinit (dev=dev@entry=1) at kernel/fs.c:44
#9  0x000000008000196e in forkret () at kernel/proc.c:558
[...]
$1 = 2
$2 = 2
$3 = '\000' <repeats 15 times>
$4 = 1
$5 = {locked = 1, name = 0x80007178 "proc", cpu = 0x8000fa50 <cpus+128>}

5Read the running clock with interrupts on

This version of the system call reads time first, and stime and tstamp later, all with interrupts on:

   struct proc *p = myproc();
+  uint64 now = r_time();
   uint64 tpus = TIMEBASE / 1000000; // ticks per microsecond

   argaddr(0, &addr);
-
-  // the clock is running: include this system call so far. a timer
-  // interrupt here could yield, and sched() would change stime and
-  // tstamp between our reads; so read them with interrupts off.
-  push_off();
-  uint64 now = r_time();
-  ct.stime = (p->stime + (now - p->tstamp)) / tpus;
-  pop_off();
-
   ct.real = now / tpus;
   ct.utime = p->utime / tpus;
+  // the clock is running: include this system call so far.
+  ct.stime = (p->stime + (now - p->tstamp)) / tpus;

What happened when we ran it

$ cputest
[...]
cputest: 4 processes calling cputime() for 2 s: sys went backwards 5 times
cputest: kernel time never goes backwards: FAIL
cputest: 1 FAILED
$ cputest
[...]
cputest: 4 processes calling cputime() for 2 s: sys went backwards 0 times
cputest: kernel time never goes backwards: OK
cputest: all 10 checks OK
$ cputest
[...]
cputest: 4 processes calling cputime() for 2 s: sys went backwards 2 times
cputest: kernel time never goes backwards: FAIL
cputest: 1 FAILED

6Returned raw ticks as microseconds

The learner assumes the time CSR counts microseconds:

-  uint64 tpus = TIMEBASE / 1000000; // ticks per microsecond
+  uint64 tpus = 1; // the time CSR counts microseconds (it does not)

What happened when we ran it

$ cputest
cputest: spin: real 302 ms, user 292 ms, sys 9 ms
cputest: a CPU-bound loop is mostly user time: OK
cputest: 20000 getpids: real 4282 ms, user 3147 ms, sys 1133 ms
cputest: system calls add kernel time: OK
cputest: pause(5): real 4136 ms, user 0 ms, sys 3 ms
cputest: pause(5) takes about half a second of real time: FAIL
[...]
cputest: 3 spinning children: real 1286 ms, user 1448 ms, sys 51 ms
cputest: on 3 harts, 3 spinners use more CPU time than real time: FAIL
[...]
cputest: 2 FAILED
$ time cputest sleep 10
real 9.752
user 0.002
sys  0.023

5. The reference solution

Take the guided tour through the reference solution, one commit at a time, with the machine state at every step:

Open the reveal tour →

Or read the commits

7d7ab2e Add per-process CPU time fields
kernel/proc.c
@@ -166,8 +166,13 @@ freeproc(struct proc *p)
166166 p->name[0] = 0;
167167 p->chan = 0;
168168 p->killed = 0;
169169 p->xstate = 0;
170 p->tstamp = 0;
171 p->utime = 0;
172 p->stime = 0;
173 p->cutime = 0;
174 p->cstime = 0;
170175 p->state = UNUSED;
171176}
172177
173178// Create a user page table for a given process, with no user memory,
kernel/proc.h
@@ -100,5 +100,13 @@ struct proc {
100100 struct context context; // swtch() here to run process
101101 struct file *ofile[NOFILE]; // Open files
102102 struct inode *cwd; // Current directory
103103 char name[16]; // Process name (debugging)
104
105 // CPU time, in time-CSR ticks. Only this process writes them,
106 // so no lock; wait() reads a ZOMBIE child's under its p->lock.
107 uint64 tstamp; // time CSR value when the current stretch began
108 uint64 utime; // time spent in user mode
109 uint64 stime; // time spent in the kernel
110 uint64 cutime; // user time of children reaped by wait()
111 uint64 cstime; // kernel time of children reaped by wait()
104112};
9e60416 Charge user and kernel time at the trap boundary
kernel/trap.c
@@ -47,8 +47,13 @@ usertrap(void)
4747 w_stvec((uint64)kernelvec); //DOC: kernelvec
4848
4949 struct proc *p = myproc();
5050
51 // the process ran in user mode since tstamp; charge it.
52 uint64 now = r_time();
53 p->utime += now - p->tstamp;
54 p->tstamp = now;
55
5156 // save user program counter.
5257 p->trapframe->epc = r_sepc();
5358
5459 if (r_scause() == 8) {
@@ -128,8 +133,14 @@ prepare_return(void)
128133 w_sstatus(x);
129134
130135 // set S Exception Program Counter to the saved user pc.
131136 w_sepc(p->trapframe->epc);
137
138 // the time since tstamp was spent in the kernel; from now
139 // on, the process is (nearly) back in user mode.
140 uint64 now = r_time();
141 p->stime += now - p->tstamp;
142 p->tstamp = now;
132143}
133144
134145// interrupts and exceptions from kernel code go here via kernelvec,
135146// on whatever the current kernel stack is.
4ed25e0 Stop the clock while a process is switched out
kernel/proc.c
@@ -495,11 +495,17 @@ sched(void)
495495 panic("sched RUNNING");
496496 if (intr_get())
497497 panic("sched interruptible");
498498
499 // stop this process's clock while it is not running.
500 p->stime += r_time() - p->tstamp;
501
499502 intena = mycpu()->intena;
500503 swtch(&p->context, &mycpu()->context);
501504 mycpu()->intena = intena;
505
506 // running again, perhaps on another hart: restart the clock.
507 p->tstamp = r_time();
502508}
503509
504510// Give up the CPU for one scheduling round.
505511void
@@ -520,8 +526,12 @@ forkret(void)
520526 extern char userret[];
521527 static int first = 1;
522528 struct proc *p = myproc();
523529
530 // a new process starts running here, not in sched():
531 // start its clock.
532 p->tstamp = r_time();
533
524534 // Still holding p->lock from scheduler.
525535 release(&p->lock);
526536
527537 if (first) {
f4926df Add a reaped child's CPU time to its parent
kernel/proc.c
@@ -398,8 +398,12 @@ kwait(uint64 addr)
398398 release(&pp->lock);
399399 release(&wait_lock);
400400 return -1;
401401 }
402 // the zombie's clock stopped for good in sched(),
403 // before its p->lock (held here) was released.
404 p->cutime += pp->utime + pp->cutime;
405 p->cstime += pp->stime + pp->cstime;
402406 pp->parent = 0;
403407 freeproc(pp);
404408 release(&pp->lock);
405409 release(&wait_lock);
3d2d5be Add the cputime system call
kernel/cputime.h
@@ -0,0 +1,8 @@
1// What cputime() fills in. All times are in microseconds.
2struct cputime {
3 uint64 real; // time since boot
4 uint64 utime; // user time of the calling process
5 uint64 stime; // kernel time of the calling process
6 uint64 cutime; // user time of reaped children
7 uint64 cstime; // kernel time of reaped children
8};
kernel/param.h
@@ -11,4 +11,5 @@
1111#define NBUF (MAXOPBLOCKS * 3) // size of disk block cache
1212#define FSSIZE 2000 // size of file system in blocks
1313#define MAXPATH 128 // maximum file path name
1414#define USERSTACK 1 // user stack pages
15#define TIMEBASE 10000000 // time CSR ticks per second (QEMU virt)
kernel/syscall.c
@@ -102,8 +102,9 @@ extern uint64 sys_unlink(void);
102102extern uint64 sys_link(void);
103103extern uint64 sys_mkdir(void);
104104extern uint64 sys_close(void);
105105extern uint64 sys_sync(void);
106extern uint64 sys_cputime(void);
106107
107108// An array mapping syscall numbers from syscall.h
108109// to the function that handles the system call.
109110static uint64 (*syscalls[])(void) = {
@@ -129,8 +130,9 @@ static uint64 (*syscalls[])(void) = {
129130 [SYS_link] = sys_link,
130131 [SYS_mkdir] = sys_mkdir,
131132 [SYS_close] = sys_close,
132133 [SYS_sync] = sys_sync,
134 [SYS_cputime] = sys_cputime,
133135 // clang-format on
134136};
135137
136138void
kernel/syscall.h
@@ -20,4 +20,5 @@
2020#define SYS_link 19
2121#define SYS_mkdir 20
2222#define SYS_close 21
2323#define SYS_sync 22
24#define SYS_cputime 23
kernel/sysproc.c
@@ -5,8 +5,9 @@
55#include "memlayout.h"
66#include "spinlock.h"
77#include "proc.h"
88#include "vm.h"
9#include "cputime.h"
910
1011uint64
1112sys_exit(void)
1213{
@@ -109,4 +110,33 @@ sys_uptime(void)
109110 xticks = ticks;
110111 release(&tickslock);
111112 return xticks;
112113}
114
115// fill in a struct cputime at the user address in argument 0.
116// the counters are in time-CSR ticks; report microseconds.
117uint64
118sys_cputime(void)
119{
120 uint64 addr;
121 struct cputime ct;
122 struct proc *p = myproc();
123 uint64 tpus = TIMEBASE / 1000000; // ticks per microsecond
124
125 argaddr(0, &addr);
126
127 // the clock is running: include this system call so far. a timer
128 // interrupt here could yield, and sched() would change stime and
129 // tstamp between our reads; so read them with interrupts off.
130 push_off();
131 uint64 now = r_time();
132 ct.stime = (p->stime + (now - p->tstamp)) / tpus;
133 pop_off();
134
135 ct.real = now / tpus;
136 ct.utime = p->utime / tpus;
137 ct.cutime = p->cutime / tpus;
138 ct.cstime = p->cstime / tpus;
139 if (copyout(p->pagetable, p->sz, addr, (char *)&ct, sizeof(ct)) < 0)
140 return -1;
141 return 0;
142}
user/user.h
@@ -1,7 +1,8 @@
11#define SBRK_ERROR ((char *)-1)
22
33struct stat;
4struct cputime;
45
56// system calls
67int fork(void);
78int exit(int) __attribute__((noreturn));
@@ -24,8 +25,9 @@ int getpid(void);
2425char *sys_sbrk(int, int);
2526int pause(int);
2627int uptime(void);
2728int sync(void);
29int cputime(struct cputime *);
2830
2931// ulib.c
3032int stat(const char *, struct stat *);
3133char *strcpy(char *, const char *);
user/usys.pl
@@ -42,4 +42,5 @@ entry("getpid");
4242entry("sbrk");
4343entry("pause");
4444entry("uptime");
4545entry("sync");
46entry("cputime");
08d916a Add the time command
Makefile
@@ -149,8 +149,9 @@ UPROGS=\
149149 $U/_logstress\
150150 $U/_forphan\
151151 $U/_dorphan\
152152 $U/_sync\
153 $U/_time\
153154
154155fs.img: mkfs/mkfs README $(UPROGS)
155156 mkfs/mkfs fs.img README $(UPROGS)
156157
user/time.c
@@ -0,0 +1,47 @@
1// time command args...: run a command, then print how long it took
2// (real) and how much CPU time it used in user mode and in the kernel.
3
4#include "kernel/types.h"
5#include "kernel/cputime.h"
6#include "user/user.h"
7
8// print microseconds as seconds with three decimals.
9static void
10show(char *what, uint64 us)
11{
12 uint64 ms = us / 1000;
13 fprintf(2, "%s %lu.%lu%lu%lu\n", what, ms / 1000, ms / 100 % 10,
14 ms / 10 % 10, ms % 10);
15}
16
17int
18main(int argc, char *argv[])
19{
20 struct cputime t0, t1;
21 int pid, status;
22
23 if (argc < 2) {
24 fprintf(2, "usage: time command [args...]\n");
25 exit(1);
26 }
27
28 cputime(&t0);
29 pid = fork();
30 if (pid < 0) {
31 fprintf(2, "time: fork failed\n");
32 exit(1);
33 }
34 if (pid == 0) {
35 exec(argv[1], argv + 1);
36 fprintf(2, "time: exec %s failed\n", argv[1]);
37 exit(1);
38 }
39 wait(&status);
40 cputime(&t1);
41
42 // the child is reaped, so its times are in our children's totals.
43 show("real", t1.real - t0.real);
44 show("user", t1.cutime - t0.cutime);
45 show("sys ", t1.cstime - t0.cstime);
46 exit(status);
47}
6510ff7 Add cputest
Makefile
@@ -150,8 +150,9 @@ UPROGS=\
150150 $U/_forphan\
151151 $U/_dorphan\
152152 $U/_sync\
153153 $U/_time\
154 $U/_cputest\
154155
155156fs.img: mkfs/mkfs README $(UPROGS)
156157 mkfs/mkfs fs.img README $(UPROGS)
157158
user/cputest.c
@@ -0,0 +1,252 @@
1// cputest: check the kernel's CPU time accounting.
2//
3// cputest run the checks
4// cputest spin N burn CPU in user mode for N*1,000,000 loop turns
5// cputest par N three processes at once, each doing spin N
6// cputest sys N make N*1000 getpid() system calls
7// cputest sleep N sleep for N timer ticks
8//
9// The last four are workloads for the time command.
10
11#include "kernel/types.h"
12#include "kernel/cputime.h"
13#include "user/user.h"
14
15int failed;
16
17void
18check(char *what, int ok)
19{
20 printf("cputest: %s: %s\n", what, ok ? "OK" : "FAIL");
21 if (!ok)
22 failed++;
23}
24
25void
26spin(int n)
27{
28 volatile int x = 0;
29 for (int i = 0; i < n; i++)
30 for (int j = 0; j < 1000000; j++)
31 x++;
32}
33
34void
35syscalls(int n)
36{
37 for (int i = 0; i < n * 1000; i++)
38 getpid();
39}
40
41// burn user time until ms milliseconds of real time have passed.
42void
43spinfor(int ms)
44{
45 struct cputime t0, t;
46 volatile int x = 0;
47
48 cputime(&t0);
49 do {
50 for (int j = 0; j < 100000; j++)
51 x++;
52 cputime(&t);
53 } while (t.real - t0.real < ms * 1000);
54}
55
56// print a line of measurements, in milliseconds.
57void
58show(char *what, struct cputime *a, struct cputime *b)
59{
60 printf("cputest: %s: real %lu ms, user %lu ms, sys %lu ms\n", what,
61 (b->real - a->real) / 1000, (b->utime - a->utime) / 1000,
62 (b->stime - a->stime) / 1000);
63}
64
65// call cputime() for ms milliseconds of real time; return how many
66// times the kernel time went backwards (at most 100).
67int
68backwards(int ms)
69{
70 struct cputime t0, prev, t;
71 int n = 0;
72
73 cputime(&t0);
74 prev = t0;
75 do {
76 cputime(&t);
77 if (t.stime < prev.stime && n < 100)
78 n++;
79 prev = t;
80 } while (t.real - t0.real < ms * 1000);
81 return n;
82}
83
84// a child that spins for ms milliseconds, writes its own final
85// utime and stime to fd, and exits.
86void
87spinchild(int ms, int fd)
88{
89 struct cputime t;
90
91 spinfor(ms);
92 cputime(&t);
93 write(fd, &t.utime, sizeof(t.utime));
94 write(fd, &t.stime, sizeof(t.stime));
95 exit(0);
96}
97
98int
99main(int argc, char *argv[])
100{
101 struct cputime a, b;
102 int fds[2], pid, xs;
103 uint64 cu, cs;
104
105 if (argc == 3 && strcmp(argv[1], "spin") == 0) {
106 spin(atoi(argv[2]));
107 exit(0);
108 }
109 if (argc == 3 && strcmp(argv[1], "par") == 0) {
110 for (int i = 0; i < 3; i++)
111 if (fork() == 0) {
112 spin(atoi(argv[2]));
113 exit(0);
114 }
115 for (int i = 0; i < 3; i++)
116 wait(&xs);
117 exit(0);
118 }
119 if (argc == 3 && strcmp(argv[1], "sys") == 0) {
120 syscalls(atoi(argv[2]));
121 exit(0);
122 }
123 if (argc == 3 && strcmp(argv[1], "sleep") == 0) {
124 pause(atoi(argv[2]));
125 exit(0);
126 }
127 if (argc != 1) {
128 fprintf(2, "usage: cputest [spin N | par N | sys N | sleep N]\n");
129 exit(1);
130 }
131
132 // 1. A CPU-bound loop is user time.
133 cputime(&a);
134 spinfor(300);
135 cputime(&b);
136 show("spin", &a, &b);
137 check("a CPU-bound loop is mostly user time",
138 (b.utime - a.utime) * 2 >= b.real - a.real &&
139 (b.stime - a.stime) * 10 < b.real - a.real);
140
141 // 2. System calls are kernel time.
142 cputime(&a);
143 syscalls(20);
144 cputime(&b);
145 show("20000 getpids", &a, &b);
146 check("system calls add kernel time", b.stime > a.stime);
147
148 // 3. Sleeping is not CPU time, and times are in microseconds.
149 cputime(&a);
150 pause(5);
151 cputime(&b);
152 show("pause(5)", &a, &b);
153 check("pause(5) takes about half a second of real time",
154 b.real - a.real >= 300000 && b.real - a.real <= 1500000);
155 check("sleeping adds almost no CPU time",
156 (b.utime - a.utime) + (b.stime - a.stime) < (b.real - a.real) / 20);
157
158 // 4. A child's time reaches its parent when, and only when, the
159 // parent reaps it.
160 cputime(&a);
161 pipe(fds);
162 if ((pid = fork()) == 0)
163 spinchild(200, fds[1]);
164 read(fds[0], &cu, sizeof(cu));
165 read(fds[0], &cs, sizeof(cs));
166 cputime(&b);
167 check("a child's time is not counted before wait", b.cutime == a.cutime);
168 wait(&xs);
169 cputime(&b);
170 printf("cputest: child said user %lu ms, sys %lu ms; parent got user %lu "
171 "ms, sys %lu ms\n",
172 cu / 1000, cs / 1000, (b.cutime - a.cutime) / 1000,
173 (b.cstime - a.cstime) / 1000);
174 check("wait adds the child's time",
175 b.cutime - a.cutime >= cu && b.cutime - a.cutime < cu + 10000 &&
176 b.cstime - a.cstime >= cs && b.cstime - a.cstime < cs + 10000);
177 close(fds[0]);
178 close(fds[1]);
179
180 // 5. A new process starts from zero, even in a reused slot (the
181 // child above has just been freed).
182 pipe(fds);
183 if ((pid = fork()) == 0) {
184 cputime(&a);
185 write(fds[1], &a, sizeof(a));
186 exit(0);
187 }
188 read(fds[0], &a, sizeof(a));
189 wait(&xs);
190 printf("cputest: new child: user %lu us, sys %lu us\n", a.utime, a.stime);
191 check("a new process starts with almost no CPU time",
192 a.utime + a.stime < 10000 && a.cutime == 0 && a.cstime == 0);
193 close(fds[0]);
194 close(fds[1]);
195
196 // 6. Grandchildren count once their parent has reaped them.
197 cputime(&a);
198 pipe(fds);
199 if ((pid = fork()) == 0) {
200 if (fork() == 0)
201 spinchild(200, fds[1]);
202 wait(&xs);
203 exit(0);
204 }
205 read(fds[0], &cu, sizeof(cu));
206 read(fds[0], &cs, sizeof(cs));
207 wait(&xs);
208 cputime(&b);
209 check("a grandchild's time arrives through its parent",
210 b.cutime - a.cutime >= cu);
211 close(fds[0]);
212 close(fds[1]);
213
214 // 7. Three processes spinning on three harts use about three
215 // times as much CPU time as real time.
216 cputime(&a);
217 for (int i = 0; i < 3; i++)
218 if (fork() == 0) {
219 spinfor(500);
220 exit(0);
221 }
222 for (int i = 0; i < 3; i++)
223 wait(&xs);
224 cputime(&b);
225 printf("cputest: 3 spinning children: real %lu ms, user %lu ms, sys %lu ms\n",
226 (b.real - a.real) / 1000, (b.cutime - a.cutime) / 1000,
227 (b.cstime - a.cstime) / 1000);
228 check("on 3 harts, 3 spinners use more CPU time than real time",
229 (b.cutime - a.cutime) * 2 >= (b.real - a.real) * 3);
230
231 // 8. Kernel time never goes backwards, even when processes are
232 // preempted in the middle of cputime(): four processes on three
233 // harts, so timer interrupts make them yield to each other.
234 int back = 0;
235 for (int i = 0; i < 4; i++)
236 if (fork() == 0)
237 exit(backwards(2000));
238 for (int i = 0; i < 4; i++) {
239 wait(&xs);
240 back += xs;
241 }
242 printf("cputest: 4 processes calling cputime() for 2 s: sys went "
243 "backwards %d times\n",
244 back);
245 check("kernel time never goes backwards", back == 0);
246
247 if (failed)
248 printf("cputest: %d FAILED\n", failed);
249 else
250 printf("cputest: all 10 checks OK\n");
251 exit(failed != 0);
252}

6. Verify and measure

On the branch, three harts, with cputest before and after usertests (one boot):

$ cputest
cputest: spin: real 300 ms, user 290 ms, sys 9 ms
cputest: a CPU-bound loop is mostly user time: OK
cputest: 20000 getpids: real 342 ms, user 244 ms, sys 97 ms
cputest: system calls add kernel time: OK
cputest: pause(5): real 429 ms, user 0 ms, sys 0 ms
cputest: pause(5) takes about half a second of real time: OK
cputest: sleeping adds almost no CPU time: OK
cputest: a child's time is not counted before wait: OK
cputest: child said user 192 ms, sys 7 ms; parent got user 192 ms, sys 8 ms
cputest: wait adds the child's time: OK
cputest: new child: user 112 us, sys 9 us
cputest: a new process starts with almost no CPU time: OK
cputest: a grandchild's time arrives through its parent: OK
cputest: 3 spinning children: real 521 ms, user 1440 ms, sys 59 ms
cputest: on 3 harts, 3 spinners use more CPU time than real time: OK
cputest: 4 processes calling cputime() for 2 s: sys went backwards 0 times
cputest: kernel time never goes backwards: OK
cputest: all 10 checks OK
$ usertests -q
usertests starting
[...]
ALL TESTS PASSED
$ cputest
[...]
cputest: 3 spinning children: real 538 ms, user 1449 ms, sys 52 ms
cputest: on 3 harts, 3 spinners use more CPU time than real time: OK
cputest: 4 processes calling cputime() for 2 s: sys went backwards 0 times
cputest: kernel time never goes backwards: OK
cputest: all 10 checks OK
$ time cputest spin 1000
real 1.955
user 1.950
sys  0.003
$ time cputest par 1000
real 2.053
user 6.018
sys  0.006
$ time cputest sys 100
real 1.458
user 1.036
sys  0.420
$ time cputest sleep 10
real 0.982
user 0.000
sys  0.002

The “child said / parent got” line shows the child’s own last reading and what the parent received through wait. The extra millisecond of system time is what the child did after its last reading: two writes to the pipe and its exit. The new child, in a reused slot, starts at 112 µs. time cputest par 1000 charges three spinners 2.9 times the real time, and a sleeper gets almost nothing. Every commit builds on its own, and usertests -q passes at the branch head.

Precise against sampled, by measurement. A scratch copy of the reference kernel kept four ledgers side by side for every process: the reference (the clock read in C, at the transitions); the clock read inside the trampoline instead (right after uservec saves the registers, right after userret switches satp); one 0.1 s sample per timer interrupt on every hart, by the mode it interrupted; and the same sampling on hart 0 only. A small program ran each workload for 3 s of real time on three harts (seconds, one boot):

workload	real	in C: user / sys	in trampoline: user / sys	sampled, all harts	sampled, hart 0 only
spin, 3 runs	3.000	2.89-2.90 / 0.10-0.11	2.73-2.77 / 0.23-0.27	2.6-2.9 / 0.1-0.4	2.6-2.8 / 0.1-0.4
getpid loop, 3 runs	3.009-3.012	2.16-2.17 / 0.83-0.85	0.22 / 2.79	0.7-1.1 / 1.9-2.3	0.7-1.1 / 1.9-2.1
`pause(30)`, 2 runs	2.930, 2.969	0.000 / 0.001	0.000 / 0.001	0 / 0	0 / 0
3 spinners (sum), 3 runs	3.073-3.074	8.64-8.68 / 0.32-0.36	8.19-8.24 / 0.76-0.80	8.1-8.5 / 0.3-0.7	2.5-2.8 / 0.2-0.5

What it shows:

Hart 0 sees one hart in three. For three spinners, sampling on hart 0 charged 2.5 to 2.8 s against 8.6 to 8.7 s. For a single process, it depends on where the process runs. In this boot the single spinners happened to stay on hart 0. Clinic 1’s runs show the other case, user 0 ms for 300 ms of spinning.
Sampling is coarse. Every sampled number is a multiple of 0.1 s, and the spinner’s sampled sys swings between 0.1 and 0.4 s from run to run, where the precise ledger says 0.10 to 0.11.
Sampling is biased for system-call-heavy code. The trampoline ledger, the truest of the four, says the getpid loop spends about 93% of its time in the kernel; sampling said 63 to 77%. The scratch kernel also counted the user-mode samples whose sepc was exactly the address the process had just returned to. In the three getpid runs that was every user-mode sample (11 of 11, 7 of 7, 9 of 9). A likely explanation (the counts are recorded, the mechanism is reasoned): a timer that fires while prepare_return and userret run with interrupts off is held pending until sret, taken before the first user instruction, and recorded as user time. QEMU delivers interrupts only between translated blocks, which may be why no user sample landed anywhere else.
Where the boundary sits matters on QEMU. With the clock read in C, the getpid loop is “72% user”; with it read at the real mode switch, 7%. The difference is the trampoline (step 5). For computing programs the two user times agree within about 6%.
Sleeping costs nothing in every ledger, as it should.

CPU time against real time. time cputest par 1000 printed real 2.053, user 6.018: three harts, almost three seconds of CPU per second. Three boots of time usertests -q (the first on a build that differed only in sys_cputime’s interrupts-on read; the other two on the final branch, measured while the computer was busy with other work; your times will differ) printed:

real 69.387             real 382.520            real 190.911
user 11.640             user 9.664              user 9.810
sys  40.088             sys  31.647             sys  30.889

Real time varied more than fivefold. CPU time (user plus sys) varied much less: 51.7, 41.3 and 40.7 s, about three quarters of it kernel time. usertests spends most of its real time not running at all (waiting for the disk, for its children, in pause), and how long those waits take depends on what else the computer is doing. On QEMU even CPU time is not clean when the computer is busy, because the guest’s clock keeps running while the host deschedules a vCPU thread. That is why time prints both, and why CPU time on an emulator is only an approximation.

7. Go further

Move the boundary into the trampoline. Read time in uservec after the registers are saved and in userret after satp is switched, store both in spare trapframe slots, and charge from them. The Measure section shows what changes. Teaches what each trampoline instruction is for and which registers are free where.
Account interrupts separately. Read the clock at the start and end of devintr and keep interrupt time per hart, so that sys means work done for the process. Teaches how much of the kernel’s time is not on behalf of anyone in particular.
waitx or getrusage. Return one child’s times as it is reaped, or the caller’s own and its children’s separately, as Unix does. Teaches how much interface design hides in the choice of where totals live.
A top. Let a process read other processes’ CPU time. Now the fields are no longer private to their owner: the reader needs p->lock and a consistent snapshot of a running process (lab 3 does the snapshot). Teaches why the private section exists.
Schedule by CPU time. Use utime + stime to favour processes that have used little CPU (lab 8’s stride scheduler is one way). Teaches why accurate accounting matters beyond reporting.