1The following is a demonstration of the dapptrace command,
2
3This is the usage for version 0.60,
4
5   # dapptrace -h
6   USAGE: dapptrace [-acdeholFLU] [-u lib] { -p PID | command }
7   
8             -p PID          # examine this PID
9             -a              # print all details
10             -c              # print syscall counts
11             -d              # print relative times (us)
12             -e              # print elapsed times (us)
13             -F              # print flow indentation
14             -l              # print pid/lwpid
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
19      eg,
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
24
25
26
27The following is an example of the default output. We run dapptrace with
28the "banner hello" command,
29
30   # dapptrace banner hi
31
32    #    #     #
33    #    #     #
34    ######     #
35    #    #     #
36    #    #     #
37    #    #     #
38   
39   CALL(args) 		 = return
40   -> __fsr(0x2, 0x8047D7C, 0x8047D88)		
41   <- __fsr = 122
42   -> main(0x2, 0x8047D7C, 0x8047D88)		
43   -> banner(0x8047E3B, 0x80614C2, 0x8047D38)		
44   -> banset(0x20, 0x80614C2, 0x8047DCC)		
45   <- banset = 36
46   -> convert(0x68, 0x8047DCC, 0x2)		
47   <- convert = 319
48   -> banfil(0x8061412, 0x80614C2, 0x8047DCC)		
49   <- banfil = 57
50   -> convert(0x69, 0x8047DCC, 0x2)		
51   <- convert = 319
52   -> banfil(0x8061419, 0x80614CA, 0x8047DCC)		
53   <- banfil = 57
54   <- banner = 118
55   -> banprt(0x80614C2, 0x8047D38, 0xD27FB824)		
56   <- banprt = 74
57
58The default output shows user function calls. An entry is prefixed
59with a "->", and the return has a "<-".
60
61
62
63Here we run dapptrace with the -F for flow indent option,
64
65   # dapptrace -F banner hi
66   
67    #    #     #
68    #    #     #
69    ######     #
70    #    #     #
71    #    #     #
72    #    #     #
73   
74   CALL(args) 		 = return
75     -> __fsr(0x2, 0x8047D7C, 0x8047D88)		
76     <- __fsr = 122
77     -> main(0x2, 0x8047D7C, 0x8047D88)		
78       -> banner(0x8047E3B, 0x80614C2, 0x8047D38)		
79         -> banset(0x20, 0x80614C2, 0x8047DCC)		
80         <- banset = 36
81         -> convert(0x68, 0x8047DCC, 0x2)		
82         <- convert = 319
83         -> banfil(0x8061412, 0x80614C2, 0x8047DCC)		
84         <- banfil = 57
85         -> convert(0x69, 0x8047DCC, 0x2)		
86         <- convert = 319
87         -> banfil(0x8061419, 0x80614CA, 0x8047DCC)		
88         <- banfil = 57
89       <- banner = 118
90       -> banprt(0x80614C2, 0x8047D38, 0xD27FB824)		
91       <- banprt = 74
92
93The above output illustrates the flow of the program, which functions
94call which other functions.
95
96
97
98Now the same command is run with -d to display relative timestamps,
99
100   # dapptrace -dF banner hi
101   
102    #    #     #
103    #    #     #
104    ######     #
105    #    #     #
106    #    #     #
107    #    #     #
108   
109   RELATIVE CALL(args) 		 = return
110       2512   -> __fsr(0x2, 0x8047D7C, 0x8047D88)		
111       2516   <- __fsr = 122
112       2518   -> main(0x2, 0x8047D7C, 0x8047D88)		
113       2863     -> banner(0x8047E3B, 0x80614C2, 0x8047D38)		
114       2865       -> banset(0x20, 0x80614C2, 0x8047DCC)		
115       2872       <- banset = 36
116       2874       -> convert(0x68, 0x8047DCC, 0x2)		
117       2877       <- convert = 319
118       2879       -> banfil(0x8061412, 0x80614C2, 0x8047DCC)		
119       2882       <- banfil = 57
120       2883       -> convert(0x69, 0x8047DCC, 0x2)		
121       2885       <- convert = 319
122       2886       -> banfil(0x8061419, 0x80614CA, 0x8047DCC)		
123       2888       <- banfil = 57
124       2890     <- banner = 118
125       2892     -> banprt(0x80614C2, 0x8047D38, 0xD27FB824)		
126       3214     <- banprt = 74
127
128The relative times are in microseconds since the program's invocation. Great!
129
130
131
132Even better is if we use the -eo options, to print elapsed times and on-cpu
133times,
134
135   # dapptrace -eoF banner hi
136   
137    #    #     #
138    #    #     #
139    ######     #
140    #    #     #
141    #    #     #
142    #    #     #
143   
144    ELAPSD    CPU CALL(args) 		 = return
145         .      .   -> __fsr(0x2, 0x8047D7C, 0x8047D88)		
146        41      4   <- __fsr = 122
147         .      .   -> main(0x2, 0x8047D7C, 0x8047D88)		
148         .      .     -> banner(0x8047E3B, 0x80614C2, 0x8047D38)		
149         .      .       -> banset(0x20, 0x80614C2, 0x8047DCC)		
150        29      6       <- banset = 36
151         .      .       -> convert(0x68, 0x8047DCC, 0x2)		
152        26      3       <- convert = 319
153         .      .       -> banfil(0x8061412, 0x80614C2, 0x8047DCC)		
154        25      2       <- banfil = 57
155         .      .       -> convert(0x69, 0x8047DCC, 0x2)		
156        23      1       <- convert = 319
157         .      .       -> banfil(0x8061419, 0x80614CA, 0x8047DCC)		
158        23      1       <- banfil = 57
159       309     28     <- banner = 118
160         .      .     -> banprt(0x80614C2, 0x8047D38, 0xD27FB824)		
161       349    322     <- banprt = 74
162
163Now it is easy to see which functions take the longest (elapsed), and 
164which consume the most CPU cycles.
165
166
167
168The following demonstrates the -U option, to trace all libraries,
169
170   # dapptrace -U banner hi
171   
172    #    #     #
173    #    #     #
174    ######     #
175    #    #     #
176    #    #     #
177    #    #     #
178   
179   CALL(args) 		 = return
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
209
210The output was huge, around 4500 lines long. Function names are prefixed 
211with their library name, eg "ld.so.1".
212
213This full output should be used with caution, as it enables so many probes
214it could well be a burden on the system.
215
216