Chapter 4: Viewing Trace Files

This chapter shows you the differences between various verbosity levels in the trace files which are generated. We'll also look at the way stack traces are presented when using the -U and -G options.

First, we'll create a simple scenario to run ZFtrace. We'll create a temporary directory and populate it with a few files and then trace the 'ls' command with various different options.

##make the temporary scenario:
# cd /tmp
# mkdir tmp
# touch tmp/mary
# touch tmp/bob
# ln -s tmp/bob tmp/pam
# cd ~

We've created 3 files in the /tmp/tmp directory. Two files (mary and bob) are regular while pam is a symbolic link to bob.

Now we'll trace the 'ls -l tmp' command with a number of different options:
Example 1

# export PATH=/usr/lpp/ZFtrace/bin:$PATH
# zftr -V6 ls -l /tmp/tmp

We'll examine a few of the lines to discuss the way ZFtrace formats output:

open(0x2ff22c77, 0x0:O_RDONLY, oct:114)
         >>0x2ff22c77: "/tmp/tmp"
         ==0x3

The ls program used the open system call. ZFtrace shows the system call name and its 3 parameters. ZFtrace highlights important input parameters with the symbols: >>
In this case it shows that the directory "/tmp/tmp" was opened. ZFtrace highlights the return value (in this case 0x3) with the symbols: ==     ZFtrace supplies decoded information in the parameter list itself. In this case, the second parameter is decoded as the O_RDONLY (the read-only flag), and the 3rd parameter is decoded as the file mode 114.

When practical, ZFtrace decodes all parameters, input, and output highlights on a single line such as in the next several trace entries:

getdirent(3, 0x204e3728, 4096) ==0x54
lseek(3, 0, 0x0:SEEK_SET) ==0x0
kfcntl(3, 0x1:F_GETFD, 0) ==0x0
kfcntl(3, 0x2:F_SETFD, 0x1) ==0x0
getdirent(3, 0x204e3728, 4096) ==0x54

Sometimes it isn't practical to decode a highlighted parameter on a single line because of size. In the Verbosity level 6, maximum decoding is requested. This is evident in the next trace entry, a call to statx. ZFtrace highlights system call result parameters with the symbols: <<     Also, note how ZFtrace treats the structure result parameter by breaking it into its appropirate fields. A structure field value is highlighted with a single = symbol and additional fields use the + symbol:

statx(0x204e4738, 0x2ff21878, 128, 0x9)
         >>0x204e4738: "/tmp/tmp/mary"
         ==0x0
         <<0x2ff21878: Stat:dev=655367+ino=22529+mode=100644+nlinks=1+flag=0+uid=0+gid=0+rdev=0x0+size=0

Verbosity
The best way to understand the verbosity levels of 1 through 6 is to simply view the resultant trace files. Using our simple scenario from above, we provide links to each trace file:

zftr -V6 ls -l /tmp/tmp
zftr -V5 ls -l /tmp/tmp
zftr -V4 ls -l /tmp/tmp
zftr -V3 ls -l /tmp/tmp
zftr -V2 ls -l /tmp/tmp
zftr -V1 ls -l /tmp/tmp
zftr -V0 ls -l /tmp/tmp

Stack Traces
Two different types of stack traces can be generated. Using the -G option, all subroutines and system calls are traced. This produces a single rolling stack trace. In order to make it easier to understand, ZFtrace uses indentation. The output is large. ZFtrace differentiates subroutines from system-calls in the way that return values are highlighted. ZFtrace uses the symbols: -> to highlight return values for normal subroutines.
Using the -U option, a single stack trace is produced at each system call. This gives a considerable amount of program flow detail without the extreme overhead of the -G option. We change our scenario to the program known as "smitty" because its stack traces are more interesting than our simple scenario:

zftr -V6 -G /bin/smitty
zftr -V6 -U /bin/smitty