1 The following is a demonstration of the dapptrace command,
3 This is the usage for version 0.60,
6 USAGE: dapptrace [-acdeholFLU] [-u lib] { -p PID | command }
8 -p PID # examine this PID
10 -c # print syscall counts
11 -d # print relative times (us)
12 -e # print elapsed times (us)
13 -F # print flow indentation
15 -o # print CPU on cpu times
16 -u lib # trace this library instead
17 -U # trace all libraries + user funcs
18 -b bufsize # dynamic variable buf size
20 dapptrace df -h # run and examine "df -h"
21 dapptrace -p 1871 # examine PID 1871
22 dapptrace -Fp 1871 # print using flow indents
23 dapptrace -eop 1871 # print elapsed and CPU times
27 The following is an example of the default output. We run dapptrace with
28 the "banner hello" command,
40 -> __fsr(0x2, 0x8047D7C, 0x8047D88)
42 -> main(0x2, 0x8047D7C, 0x8047D88)
43 -> banner(0x8047E3B, 0x80614C2, 0x8047D38)
44 -> banset(0x20, 0x80614C2, 0x8047DCC)
46 -> convert(0x68, 0x8047DCC, 0x2)
48 -> banfil(0x8061412, 0x80614C2, 0x8047DCC)
50 -> convert(0x69, 0x8047DCC, 0x2)
52 -> banfil(0x8061419, 0x80614CA, 0x8047DCC)
55 -> banprt(0x80614C2, 0x8047D38, 0xD27FB824)
58 The default output shows user function calls. An entry is prefixed
59 with a "->", and the return has a "<-".
63 Here we run dapptrace with the -F for flow indent option,
65 # dapptrace -F banner hi
75 -> __fsr(0x2, 0x8047D7C, 0x8047D88)
77 -> main(0x2, 0x8047D7C, 0x8047D88)
78 -> banner(0x8047E3B, 0x80614C2, 0x8047D38)
79 -> banset(0x20, 0x80614C2, 0x8047DCC)
81 -> convert(0x68, 0x8047DCC, 0x2)
83 -> banfil(0x8061412, 0x80614C2, 0x8047DCC)
85 -> convert(0x69, 0x8047DCC, 0x2)
87 -> banfil(0x8061419, 0x80614CA, 0x8047DCC)
90 -> banprt(0x80614C2, 0x8047D38, 0xD27FB824)
93 The above output illustrates the flow of the program, which functions
94 call which other functions.
98 Now the same command is run with -d to display relative timestamps,
100 # dapptrace -dF banner hi
109 RELATIVE CALL(args) = return
110 2512 -> __fsr(0x2, 0x8047D7C, 0x8047D88)
112 2518 -> main(0x2, 0x8047D7C, 0x8047D88)
113 2863 -> banner(0x8047E3B, 0x80614C2, 0x8047D38)
114 2865 -> banset(0x20, 0x80614C2, 0x8047DCC)
116 2874 -> convert(0x68, 0x8047DCC, 0x2)
117 2877 <- convert = 319
118 2879 -> banfil(0x8061412, 0x80614C2, 0x8047DCC)
120 2883 -> convert(0x69, 0x8047DCC, 0x2)
121 2885 <- convert = 319
122 2886 -> banfil(0x8061419, 0x80614CA, 0x8047DCC)
125 2892 -> banprt(0x80614C2, 0x8047D38, 0xD27FB824)
128 The relative times are in microseconds since the program's invocation. Great!
132 Even better is if we use the -eo options, to print elapsed times and on-cpu
135 # dapptrace -eoF banner hi
144 ELAPSD CPU CALL(args) = return
145 . . -> __fsr(0x2, 0x8047D7C, 0x8047D88)
147 . . -> main(0x2, 0x8047D7C, 0x8047D88)
148 . . -> banner(0x8047E3B, 0x80614C2, 0x8047D38)
149 . . -> banset(0x20, 0x80614C2, 0x8047DCC)
151 . . -> convert(0x68, 0x8047DCC, 0x2)
152 26 3 <- convert = 319
153 . . -> banfil(0x8061412, 0x80614C2, 0x8047DCC)
155 . . -> convert(0x69, 0x8047DCC, 0x2)
156 23 1 <- convert = 319
157 . . -> banfil(0x8061419, 0x80614CA, 0x8047DCC)
159 309 28 <- banner = 118
160 . . -> banprt(0x80614C2, 0x8047D38, 0xD27FB824)
161 349 322 <- banprt = 74
163 Now it is easy to see which functions take the longest (elapsed), and
164 which consume the most CPU cycles.
168 The following demonstrates the -U option, to trace all libraries,
170 # dapptrace -U banner hi
180 -> ld.so.1:_rt_boot(0x8047E34, 0x8047E3B, 0x0)
181 -> ld.so.1:_setup(0x8047D38, 0x20AE4, 0x3)
182 -> ld.so.1:setup(0x8047D88, 0x8047DCC, 0x0)
183 -> ld.so.1:fmap_setup(0x0, 0xD27FB2E4, 0xD27FB824)
184 <- ld.so.1:fmap_setup = 125
185 -> ld.so.1:addfree(0xD27FD3C0, 0xC40, 0x0)
186 <- ld.so.1:addfree = 65
187 -> ld.so.1:security(0xFFFFFFFF, 0xFFFFFFFF, 0xFFFFFFFF)
188 <- ld.so.1:security = 142
189 -> ld.so.1:readenv_user(0x8047D88, 0xD27FB204, 0xD27FB220)
190 -> ld.so.1:ld_str_env(0x8047E3E, 0xD27FB204, 0xD27FB220)
191 <- ld.so.1:ld_str_env = 389
192 -> ld.so.1:ld_str_env(0x8047E45, 0xD27FB204, 0xD27FB220)
193 <- ld.so.1:ld_str_env = 389
194 -> ld.so.1:ld_str_env(0x8047E49, 0xD27FB204, 0xD27FB220)
195 <- ld.so.1:ld_str_env = 389
196 -> ld.so.1:ld_str_env(0x8047E50, 0xD27FB204, 0xD27FB220)
197 -> ld.so.1:strncmp(0x8047E53, 0xD27F7BEB, 0x4)
198 <- ld.so.1:strncmp = 113
199 -> ld.so.1:rd_event(0xD27FB1F8, 0x3, 0x0)
200 [...4486 lines deleted...]
201 -> ld.so.1:_lwp_mutex_unlock(0xD27FD380, 0xD27FB824, 0x8047C04)
202 <- ld.so.1:_lwp_mutex_unlock = 47
203 <- ld.so.1:rt_mutex_unlock = 34
204 -> ld.so.1:rt_bind_clear(0x1, 0xD279ECC0, 0xD27FDB2C)
205 <- ld.so.1:rt_bind_clear = 34
206 <- ld.so.1:leave = 210
207 <- ld.so.1:elf_bndr = 803
208 <- ld.so.1:elf_rtbndr = 35
210 The output was huge, around 4500 lines long. Function names are prefixed
211 with their library name, eg "ld.so.1".
213 This full output should be used with caution, as it enables so many probes
214 it could well be a burden on the system.