Classic Shell Scripting - Arnold Robbins [196]
sys totals: .04 242 50
usr time: .01
elapsed: .19
When your program takes longer than expected, output like this can help to identify performance bottlenecks arising from system-call overhead. The time command can be useful in identifying candidates for system-call profiling: it reports user time, system-call time, and wall-clock time.
* * *
Tip
One of the most common applications of system-call tracers is for monitoring file access: look for access( ), open( ), stat( ), and unlink( ) call reports in the trace log. On GNU/Linux, use strace -e trace=file to reduce the log volume. File-access traces can be particularly helpful when newly installed software complains that it cannot find a needed configuration file, but fails to tell you the file's name.
* * *
System-call tracers are also helpful in finding the lock-file remnants that we discussed earlier. Here is an example from a Sun Solaris system that shows how to locate the lock file produced by a particular web browser:
$ truss -f -o foo.log mozilla
Trace browser execution
$ grep -i lock foo.log
Search the trace for the word "lock"
...
29028: symlink("192.168.253.187:29028",
"/home/jones/.mozilla/jones/c7rboyyz.slt/lock") = 0
...
29028: unlink("/home/jones/.mozilla/jones/c7rboyyz.slt/lock") = 0
This browser makes a lock file that is a symbolic link to a nonexistent filename containing the local machine's numeric Internet host address and the process number. Had the browser process died prematurely, the unlink( ) system call that removed the lock file might not have been executed. Lock filenames do not always have the word lock in them, so you might have to examine the trace log more closely to identify a lock file.
Here is an abbreviated trace on an SGI IRIX system, where we test whether /bin/sh is executable:
$ /usr/sbin/par /bin/test -x /bin/sh
Trace the test command
...
0mS[ 0] : execve("/bin/test", 0x7ffb7e88, 0x7ffb7e98)
...
6mS[ 0] : access("/bin/sh", X_OK) OK
6mS[ 0] : stat("/bin/sh", 0x7ffb7cd0) OK
...
6mS[ 0] : prctl(PR_LASTSHEXIT) = 1
6mS[ 0] : exit(0)
System call summary :
Average Total
Name #Calls Time(ms) Time(ms)
-----------------------------------------
execve 1 3.91 3.91
open 2 0.11 0.21
access 1 0.17 0.17
stat 1 0.12 0.12
...
prctl 1 0.01 0.01
exit 1 0.00 0.00
Once you know what system call you are interested in, you can reduce clutter by restricting trace output to only that call:
$ /usr/sbin/par -n stat /bin/test -x /bin/sh
Trace only stat system calls
0mS[ 0] (5399999) : was sent signal SIGUSR1
0mS[ 3] : received signal SIGUSR1 (handler 0x100029d8)
6mS[ 3] : stat("/bin/sh", 0x7ffb7cd0) OK
System call summary :
...
The BSD and Mac OS X ktrace commands work a little differently: they write the trace to a binary file, ktrace.out. You then have to run kdump to convert it to text form. Here's a trace from a NetBSD system, testing for execute permission of /bin/sh:
$ ktrace test -x /bin/sh
Trace the test command
$ ls -l ktrace.out
List the trace log
-rw-rw-r-- 1 jones devel 8698 Jul 27 09:44 ktrace.out
$ kdump
Post-process the trace log
...
19798 ktrace EMUL "netbsd"
19798 ktrace CALL execve(0xbfbfc650,0xbfbfcb24,0xbfbfcb34)
19798 ktrace NAMI "/usr/local/bin/test"
...
19798 test CALL access(0xbfbfcc80,0x1)
19798 test NAMI "/bin/sh"
19798 test RET access 0
19798 test CALL exit(0)
The need to post-process the trace log is unfortunate, since it prevents having a dynamic view of the system calls that a process is making. In particular, a hung system call may be hard to identify.
All of the system-call tracers can take a process ID argument instead of a command name, allowing them to trace an already-running process. Only the process owner and root can do that.
There is much more to system-call tracers than we can illustrate here. Consult your local manual pages for details.
* * *
[4] Snapshots are a recent feature of some advanced filesystems: they permit freezing the state of a filesystem, usually in just a few seconds, preserving a view