cddl/contrib/dtracetoolkit/Examples/dapptrace_example.txt

   1 The following is a demonstration of the dapptrace command,
   2
   3 This 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
  27 The following is an example of the default output. We run dapptrace with
  28 the "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
  58 The default output shows user function calls. An entry is prefixed
  59 with a "->", and the return has a "<-".
  60
  61
  62
  63 Here 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
  93 The above output illustrates the flow of the program, which functions
  94 call which other functions.
  95
  96
  97
  98 Now 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
 128 The relative times are in microseconds since the program's invocation. Great!
 129
 130
 131
 132 Even better is if we use the -eo options, to print elapsed times and on-cpu
 133 times,
 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
 163 Now it is easy to see which functions take the longest (elapsed), and
 164 which consume the most CPU cycles.
 165
 166
 167
 168 The 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
 210 The output was huge, around 4500 lines long. Function names are prefixed
 211 with their library name, eg "ld.so.1".
 212
 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.
 215