2.5.5 Solution to Exercise: Timing All System Calls for cp (calltrace.d)

/* calltrace.d -- Time all system calls for cp */

syscall:::entry
/execname == "cp"/
{
  self->t = timestamp; /* Initialize a thread-local variable */
}

syscall:::return
/self->t != 0/
{
  printf("%s (pid=%d) spent %d microseconds in %s()\n",
  execname, pid, ((timestamp - self->t)/1000), probefunc);

  self->t = 0; /* Reset the variable */
}

Dropping the function name read from the probe specifications matches all instances of entry and return probes for syscall. The following is a check for system calls resulting from running the cp executable:

# dtrace -q -s calltrace.d 
cp (pid=2801) spent 4 microseconds in brk()
cp (pid=2801) spent 5 microseconds in mmap()
cp (pid=2801) spent 15 microseconds in access()
cp (pid=2801) spent 7 microseconds in open()
cp (pid=2801) spent 2 microseconds in newfstat()
cp (pid=2801) spent 3 microseconds in mmap()
cp (pid=2801) spent 1 microseconds in close()
cp (pid=2801) spent 8 microseconds in open()
cp (pid=2801) spent 3 microseconds in read()
cp (pid=2801) spent 1 microseconds in newfstat()
cp (pid=2801) spent 4 microseconds in mmap()
cp (pid=2801) spent 12 microseconds in mprotect()
   ...
cp (pid=2801) spent 183 microseconds in open()
cp (pid=2801) spent 1 microseconds in newfstat()
cp (pid=2801) spent 1 microseconds in fadvise64()
cp (pid=2801) spent 17251 microseconds in read()
cp (pid=2801) spent 80 microseconds in write()
cp (pid=2801) spent 58 microseconds in read()
cp (pid=2801) spent 57 microseconds in close()
cp (pid=2801) spent 85 microseconds in close()
cp (pid=2801) spent 57 microseconds in lseek()
cp (pid=2801) spent 56 microseconds in close()
cp (pid=2801) spent 56 microseconds in close()
cp (pid=2801) spent 56 microseconds in close()
^C