Tracing

The following chapter introduces further tools and techniques for tracing at large.

Dtrace is the Solaris framework in question everyone wants to use for queries in any depth. The technology is however rather complex to be learned.

I limited the number of Dtrace scripts to the ones in the Dtrace tool kit. The focus of this primer is to provide tools categorized by problem domain.

There are a number of visual tracing solutions build on top of Dtrace.

• Project D-Light 
• Chime
• Project fishworks as used in the Oracle ZFS appliance (not available on general purpose systems)

truss – First Stop Tool

truss is one of the most valuable tools in Solaris to understand various issues with applications. truss can help understand which files are read and written, which system calls are called and much more. Although, truss is very useful, one has to understand that it is also quite intrusive on the applications traced and can therefore influence performance and timing.

A standard usage scenario for truss is to get a summary of system call activity of a process over a given window of time.

truss – system call summary

As can be seen from the output above, the find process issues large amounts of fstat(2), lstat(2), getdents(2) and fchdir(2) system calls. The getdents(2) system call consumes roughly 45% of the total system time (0.149 seconds of 0.331 seconds of total system time).

Another standard usage scenario of truss, is to get a detailed view of the system calls issued by a given process.

truss – detailed system call activity

The output above shows truss giving out details about the system calls issued and their parameters. Further details can be obtained with the -v option. For example:

• truss -v all -p <pid>

Yet another standard usage scenario is to restrict output of truss to certain system calls:

• truss -t fstat -p <pid>

would limit the output to fstat(2) system call activity.

truss -t – sample output

Finally, combining the -t option with -v, one gets an output like this:

truss -t -v – sample output

plockstat – Report User-Level Lock Statistics

The plockstat utility gathers and displays user-level locking statistics. By default, plockstat monitors all lock contention events, gathers frequency and timing data about those events, and displays the data in decreasing frequency order, so that the most common events appear first. plockstat gathers data until the specified command completes or the process specified with the -p option completes. plockstat relies on DTrace to instrument a running process or a command it invokes to trace events of interest. This imposes a small but measurable performance overhead on the processes being observed . Users must have the dtrace_proc privilege and have permission to observe a particular process with plockstat .

Let's study the output of plockstat by running our sample reader/writer locking program cc_lck. First start cc_lck with the writer blocking for ten microseconds:

• cc_lck 10

Then run the plockstat tool for ten seconds:

• plockstat -A -e 10 -p <pid>

The output should be similar to the screen shot below. From the output, one can observe some contention on the reader/writer lock.

plockstat – sample output

pfilestat [DtraceToolkit] – Trace Time spend in I/O

pfilestat prints I/O statistics for each file descriptor within a process. In particular, the time break down during read() and write() events is measured. This tool helps understanding the impact of I/O on the process.

To study the output of pfilestat , let's start as root the following command:

• dd if=/dev/rdsk/c1d0s0 of=/dev/null bs=1k &

Then in another window, let's start the pfilestat tool with the pid of the dd command as argument:

• pfilestat <pid of dd command>

The output should be similar to the screen shot below:

pfilestat – sample output

The pfilestat breaks down the process time in percentage spend for reading (read), writing (write), waiting for CPU (waitcpu), running on CPU (running), sleeping on read (sleep-r) and sleeping on write (sleep-w).

cputrack/cpustat – Monitor Process/System w/ CPU perf. counters

The cputrack utility allows CPU performance counters to be used to monitor the behavior of a process or family of processes running on the system. The cpustat utility allows CPU performance counters to be used to monitor the overall behavior of the CPUs in the system.

Using cputrack/cpustat requires intimate knowledge of the CPU and system under observation. Please consult the system/CPU documentation for details on the counters available. cpustat or cputrack with the -h option will list all available performance counters.

To observe the output of cputrack , let's run the tool with our sample program cc_usr .

Use the following command (all in one line):

• cputrack -t -c pic0=FP_dispatched_fpu_ops,cmask0=0,umask0=0x7,pic1=FR_retired_x86_instr_w_excp_intr,cmask1=0 cc_usr

The output should look like this:

cputrack – sample output

In the above output, one can see that the cc_usr program executed roughly 600 million instructions per second with roughly 160 million floating point operations per second.

Thomas Bastian was a coauthor of an earlier version of this document. The earlier version of this page has been published in the "The Developers Edge" in 2009.