2.5.1 Example: Monitoring read() System Call Duration (readtrace.d)

The following is an example of the D program, readtrace.d.

/* 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 */
}

In the example, the readtrace.d program displays the command name, process ID, and call duration in microseconds whenever a process invokes the read() system call. 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 value from the value of timestamp when the call returns. The units of timestamp are nanoseconds, so you divide by 1000 to obtain a value in microseconds.

The following is output from running this program:

# dtrace -q -s readtrace.d
NetworkManager (pid=878) spent 10 microseconds in read()
NetworkManager (pid=878) spent 9 microseconds in read()
NetworkManager (pid=878) spent 2 microseconds in read()
in:imjournal (pid=815) spent 63 microseconds in read()
gdbus (pid=878) spent 7 microseconds in read()
gdbus (pid=878) spent 66 microseconds in read()
gdbus (pid=878) spent 63 microseconds in read()
irqbalance (pid=816) spent 56 microseconds in read()
irqbalance (pid=816) spent 113 microseconds in read()
irqbalance (pid=816) spent 104 microseconds in read()
irqbalance (pid=816) spent 91 microseconds in read()
irqbalance (pid=816) spent 61 microseconds in read()
irqbalance (pid=816) spent 63 microseconds in read()
irqbalance (pid=816) spent 61 microseconds in read()
irqbalance (pid=816) spent 61 microseconds in read()
irqbalance (pid=816) spent 61 microseconds in read()
irqbalance (pid=816) spent 61 microseconds in read()
irqbalance (pid=816) spent 61 microseconds in read()
irqbalance (pid=816) spent 61 microseconds in read()
sshd (pid=10230) spent 8 microseconds in read()
in:imjournal (pid=815) spent 6 microseconds in read()
sshd (pid=10230) spent 7 microseconds in read()
in:imjournal (pid=815) spent 5 microseconds in read()
sshd (pid=10230) spent 7 microseconds in read()
in:imjournal (pid=815) spent 6 microseconds in read()
sshd (pid=10230) spent 7 microseconds in read()
in:imjournal (pid=815) spent 5 microseconds in read()
^C