21.3 Tracing System Calls

Most Unix-style operating systems offer a "tracing utility" that intercepts and records the system calls that are called by a process and the signals that are received by a process. In this respect it is similar to gdb. The name of each system call, its arguments, and its return value are printed to STDERR or to the specified file.

The tracing utility is a useful diagnostic, instructional, and debugging tool. You can learn a lot about the underlying system while examining traces of the running programs. In the case of mod_perl, tracing improves performance by enabling us to spot and eliminate redundant system calls. It also useful in cases of problem debugging—for example, when some process hangs.

Depending on your operating system, you should have available one of the utilities strace, truss, tusc, ktrace, or similar. In this book we will use the Linux strace utility.

There are two ways to get a trace of the process with strace. One way is to tell strace to start the process and do the tracing on it:

panic% strace perl -le 'print "mod_perl rules"'

Another way is to tell strace to attach to a process that's already running:

panic% strace -p PID

Replace PID with the process number you want to check on.

Many other useful arguments are accepted by strace. For example, you can tell it to trace only specific system calls:

panic% strace -e trace=open,write,close,nanosleep \
    perl -le 'print "mod_perl rules"'

In this example we have asked strace to show us only the calls to open( ), write( ), close( ), and nanosleep( ), which reduces the output generated by strace, making it simpler to understand—providing you know what you are looking for.

The generated traces are too long (unless filtered with trace=tag) to be presented here completely. For example, if we ask for only the write( ) system calls, we get the following output:

panic% strace -e trace=write perl -le 'print "mod_perl rules"'
write(1, "mod_perl rules\n", 15mod_perl rules
)  = 15

The output of the Perl one-liner gets mixed with the trace, so the actual trace is:

write(1, "mod_perl rules\n", 15)  = 15

Note that the newline was automatically appended because of the -l option on the Perl command line.

Each line in the trace contains the system call name, followed by its arguments in parentheses and its return value. In the last example, a string of 15 characters was written to STDOUT, whose file descriptor is 1. And we can see that they were all successfully written, since the write( ) system call has returned a value of 15, the number of characters written.

The strace manpage provides a comprehensive explanation of how to interpret all parts of the traces; you may want to refer to this manpage to learn more about it.