2.5 Timing Events on a System

Determining the time that a system takes to perform different activities is a fundamental technique for analysing its operation and determining where bottlenecks might be occurring.

The following D program (readtrace.d) displays the command name, process ID, and call duration in microseconds whenever a process invokes the read() system call.

Example 2.8 readtrace.d: Display time spent in read() calls

/* readtrace.d -- Display time spent in read() calls */

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

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

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


The variable self->t is thread-local, meaning that it exists only within the scope of execution of a thread on the system. The program records the value of timestamp in self->t when the process calls read(), and subtracts this from the value of timestamp when the call returns. The units of timestamp are nanoseconds so we divide by 1000 to obtain a value in microseconds.

The following is example output from running this program.

# dtrace -q -s readtrace.d
nome-terminal (pid=2774) spent 27 microseconds in read()
gnome-terminal (pid=2774) spent 16 microseconds in read()
hald-addon-inpu (pid=1662) spent 26 microseconds in read()
hald-addon-inpu (pid=1662) spent 17 microseconds in read()
Xorg (pid=2046) spent 18 microseconds in read()
...
^C