1N/AThe following demonstrates the dtruss command - a DTrace version of truss.
1N/AThis version is designed to be less intrusive and safer than running truss.
1N/Adtruss has many options. Here is the help for version 0.70,
1N/A USAGE: dtruss [-acdefholL] [-t syscall] { -p PID | -n name | command }
1N/A -p PID # examine this PID
1N/A -n name # examine this process name
1N/A -t syscall # examine this syscall only
1N/A -a # print all details
1N/A -c # print syscall counts
1N/A -d # print relative times (us)
1N/A -e # print elapsed times (us)
1N/A -f # follow children
1N/A -o # print on cpu times
1N/A -b bufsize # dynamic variable buf size
1N/A dtruss df -h # run and examine "df -h"
1N/A dtruss -p 1871 # examine PID 1871
1N/A dtruss -n tar # examine all processes called "tar"
1N/AFor example, here we dtruss any process with the name "ksh" - the Korn shell,
1N/A 27547/1: llseek(0x3F, 0xE4E, 0x0) = 3662 0
1N/A 27547/1: read(0x3F, "\0", 0x400) = 0 0
1N/A 27547/1: llseek(0x3F, 0x0, 0x0) = 3662 0
1N/A 27547/1: write(0x3F, "ls -l\n\0", 0x8) = 8 0
1N/A 27547/1: fdsync(0x3F, 0x10, 0xFEC1D444) = 0 0
1N/A 27547/1: lwp_sigmask(0x3, 0x20000, 0x0) = 0xFFBFFEFF 0
1N/A 27547/1: lwp_sigmask(0x3, 0x0, 0x0) = 0xFFBFFEFF 0
1N/AThe output for each system call does not yet evaluate as much as truss does.
1N/AIn the following example, syscall elapsed and overhead times are measured.
1N/AElapsed times represent the time from syscall start to finish; overhead
1N/Atimes measure the time spent on the CPU,
1N/A 3911/1: 41 26 write(0x2, "l\0", 0x1) = 1 0
1N/A 3911/1: 1001579 43 read(0x0, "s\0", 0x1) = 1 0
1N/A 3911/1: 38 26 write(0x2, "s\0", 0x1) = 1 0
1N/A 3911/1: 1019129 43 read(0x0, " \001\0", 0x1) = 1 0
1N/A 3911/1: 38 26 write(0x2, " \0", 0x1) = 1 0
1N/A 3911/1: 998533 43 read(0x0, "-\0", 0x1) = 1 0
1N/A 3911/1: 38 26 write(0x2, "-\001\0", 0x1) = 1 0
1N/A 3911/1: 1094323 42 read(0x0, "l\0", 0x1) = 1 0
1N/A 3911/1: 39 27 write(0x2, "l\001\0", 0x1) = 1 0
1N/A 3911/1: 1210496 44 read(0x0, "\r\0", 0x1) = 1 0
1N/A 3911/1: 40 28 write(0x2, "\n\001\0", 0x1) = 1 0
1N/A 3911/1: 9 1 lwp_sigmask(0x3, 0x2, 0x0) = 0xFFBFFEFF 0
1N/A 3911/1: 70 63 ioctl(0x0, 0x540F, 0x80F6D00) = 0 0
1N/AA bash command was in another window, where the "ls -l" command was being
1N/Atyped. The keystrokes can be seen above, along with the long elapsed times
1N/A(keystroke delays), and short overhead times (as the bash process blocks
1N/Aon the read and leaves the CPU).
1N/ANow dtruss is put to the test. Here we truss a test program that runs several
1N/Ahundred smaller programs, which in turn generate thousands of system calls.
1N/AFirst, as a "control" we run the program without a truss or dtruss running,
1N/AIn the above test, truss slowed the program from 38 seconds to 41. dtruss
1N/Aslowed the program from 38 seconds to 46, slightly slower that truss...
1N/ANow we try follow mode "-f". The test program does run several hundred
1N/Asmaller programs, so now there are plenty more system calls to track,
1N/AWow, the difference is huge! truss slows the program from 38 to 148 seconds;
1N/Abut dtruss has only slowed the program from 38 to 56 seconds.