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