1 The following demonstrates the dtruss command - a DTrace version of truss.
2 This version is designed to be less intrusive and safer than running truss.
4 dtruss has many options. Here is the help for version 0.70,
6 USAGE: dtruss [-acdefholL] [-t syscall] { -p PID | -n name | command }
8 -p PID # examine this PID
9 -n name # examine this process name
10 -t syscall # examine this syscall only
11 -a # print all details
12 -c # print syscall counts
13 -d # print relative times (us)
14 -e # print elapsed times (us)
16 -l # force printing pid/lwpid
17 -o # print on cpu times
18 -L # don't print pid/lwpid
19 -b bufsize # dynamic variable buf size
21 dtruss df -h # run and examine "df -h"
22 dtruss -p 1871 # examine PID 1871
23 dtruss -n tar # examine all processes called "tar"
24 dtruss -f test.sh # run test.sh and follow children
28 For example, here we dtruss any process with the name "ksh" - the Korn shell,
31 PID/LWP SYSCALL(args) = return
32 27547/1: llseek(0x3F, 0xE4E, 0x0) = 3662 0
33 27547/1: read(0x3F, "\0", 0x400) = 0 0
34 27547/1: llseek(0x3F, 0x0, 0x0) = 3662 0
35 27547/1: write(0x3F, "ls -l\n\0", 0x8) = 8 0
36 27547/1: fdsync(0x3F, 0x10, 0xFEC1D444) = 0 0
37 27547/1: lwp_sigmask(0x3, 0x20000, 0x0) = 0xFFBFFEFF 0
38 27547/1: stat64("/usr/bin/ls\0", 0x8047A00, 0xFEC1D444) = 0 0
39 27547/1: lwp_sigmask(0x3, 0x0, 0x0) = 0xFFBFFEFF 0
42 The output for each system call does not yet evaluate as much as truss does.
46 In the following example, syscall elapsed and overhead times are measured.
47 Elapsed times represent the time from syscall start to finish; overhead
48 times measure the time spent on the CPU,
51 PID/LWP ELAPSD CPU SYSCALL(args) = return
52 3911/1: 41 26 write(0x2, "l\0", 0x1) = 1 0
53 3911/1: 1001579 43 read(0x0, "s\0", 0x1) = 1 0
54 3911/1: 38 26 write(0x2, "s\0", 0x1) = 1 0
55 3911/1: 1019129 43 read(0x0, " \001\0", 0x1) = 1 0
56 3911/1: 38 26 write(0x2, " \0", 0x1) = 1 0
57 3911/1: 998533 43 read(0x0, "-\0", 0x1) = 1 0
58 3911/1: 38 26 write(0x2, "-\001\0", 0x1) = 1 0
59 3911/1: 1094323 42 read(0x0, "l\0", 0x1) = 1 0
60 3911/1: 39 27 write(0x2, "l\001\0", 0x1) = 1 0
61 3911/1: 1210496 44 read(0x0, "\r\0", 0x1) = 1 0
62 3911/1: 40 28 write(0x2, "\n\001\0", 0x1) = 1 0
63 3911/1: 9 1 lwp_sigmask(0x3, 0x2, 0x0) = 0xFFBFFEFF 0
64 3911/1: 70 63 ioctl(0x0, 0x540F, 0x80F6D00) = 0 0
66 A bash command was in another window, where the "ls -l" command was being
67 typed. The keystrokes can be seen above, along with the long elapsed times
68 (keystroke delays), and short overhead times (as the bash process blocks
69 on the read and leaves the CPU).
73 Now dtruss is put to the test. Here we truss a test program that runs several
74 hundred smaller programs, which in turn generate thousands of system calls.
76 First, as a "control" we run the program without a truss or dtruss running,
85 # time truss ./test 2> /dev/null
92 # time dtruss ./test 2> /dev/null
97 In the above test, truss slowed the program from 38 seconds to 41. dtruss
98 slowed the program from 38 seconds to 46, slightly slower that truss...
100 Now we try follow mode "-f". The test program does run several hundred
101 smaller programs, so now there are plenty more system calls to track,
103 # time truss -f ./test 2> /dev/null
110 # time dtruss -f ./test 2> /dev/null
115 Wow, the difference is huge! truss slows the program from 38 to 148 seconds;
116 but dtruss has only slowed the program from 38 to 56 seconds.