cddl/contrib/dtracetoolkit/Examples/sh_calldist_example.txt

   1 The following are examples of sh_calldist.d.
   2
   3 This script traces the elapsed time of Bourne shell functions and
   4 prints a report containing distribution plots per function. Here it
   5 traces the example program, Code/Shell/func_abc.sh.
   6
   7    # sh_calldist.d
   8    Tracing... Hit Ctrl-C to end.
   9    ^C
  10
  11    Elapsed times (us),
  12
  13       func_abc.sh, builtin, echo
  14               value  ------------- Distribution ------------- count
  15                   8 |                                         0
  16                  16 |@@@@@@@@@@@@@                            1
  17                  32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2
  18                  64 |                                         0
  19
  20       func_abc.sh, cmd, sleep
  21               value  ------------- Distribution ------------- count
  22              262144 |                                         0
  23              524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
  24             1048576 |                                         0
  25
  26    Exclusive function elapsed times (us),
  27
  28       func_abc.sh, func, func_a
  29               value  ------------- Distribution ------------- count
  30                1024 |                                         0
  31                2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  32                4096 |                                         0
  33
  34       func_abc.sh, func, func_b
  35               value  ------------- Distribution ------------- count
  36                1024 |                                         0
  37                2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  38                4096 |                                         0
  39
  40       func_abc.sh, func, func_c
  41               value  ------------- Distribution ------------- count
  42                1024 |                                         0
  43                2048 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  44                4096 |                                         0
  45
  46    Inclusive function elapsed times (us),
  47
  48       func_abc.sh, func, func_c
  49               value  ------------- Distribution ------------- count
  50              262144 |                                         0
  51              524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  52             1048576 |                                         0
  53
  54       func_abc.sh, func, func_b
  55               value  ------------- Distribution ------------- count
  56              524288 |                                         0
  57             1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  58             2097152 |                                         0
  59
  60       func_abc.sh, func, func_a
  61               value  ------------- Distribution ------------- count
  62             1048576 |                                         0
  63             2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  64             4194304 |                                         0
  65
  66 The elapsed times show that the echo builtin takes between 16 and 64 us
  67 to execute.
  68
  69 The exclusive function elapsed times show that each function spent
  70 between 2 and 4 ms. This exclusive time excludes the time spent in
  71 other functions.
  72
  73 The inclusive function elapsed times show that func_c() took between 0.5 and
  74 1.0 seconds, func_b() took between 1.0 and 2.1 seconds, and func_a() took
  75 between 2.1 and 4.2 seconds to execute. This inclusive time includes the
  76 time spent in other functions and commands called, and since func_a()
  77 calls func_b() which calls func_c(), and, each function is calling "sleep 1",
  78 these times make sense.
  79
  80 These elapsed times are the absolute time from when the function began to
  81 when it completed - which includes off-CPU time due to other system events
  82 such as I/O, scheduling, interrupts, etc.
  83
  84 Elapsed times are useful for identifying where latencies are.
  85 See Notes/ALLelapsed_notes.txt for more details. Also see
  86 Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
  87 detailed explanation of exclusive vs inclusive function time.
  88
  89
  90
  91 The following traces the firefox startup script.
  92
  93 # sh_calldist.d
  94 Tracing... Hit Ctrl-C to end.
  95 ^C
  96
  97 Elapsed times (us),
  98
  99    run-mozilla.sh, builtin, return
 100            value  ------------- Distribution ------------- count
 101                0 |                                         0
 102                1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 103                2 |                                         0
 104
 105    run-mozilla.sh, builtin, shift
 106            value  ------------- Distribution ------------- count
 107                0 |                                         0
 108                1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 109                2 |                                         0
 110
 111    run-mozilla.sh, builtin, break
 112            value  ------------- Distribution ------------- count
 113                1 |                                         0
 114                2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 115                4 |                                         0
 116
 117    firefox, builtin, break
 118            value  ------------- Distribution ------------- count
 119                2 |                                         0
 120                4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 121                8 |                                         0
 122
 123    run-mozilla.sh, builtin, export
 124            value  ------------- Distribution ------------- count
 125                0 |                                         0
 126                1 |@@@@@@@@@@@@@                            1
 127                2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2
 128                4 |                                         0
 129
 130    firefox, builtin, export
 131            value  ------------- Distribution ------------- count
 132                1 |                                         0
 133                2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2
 134                4 |@@@@@@@@@@@@@                            1
 135                8 |                                         0
 136
 137    firefox, builtin, :
 138            value  ------------- Distribution ------------- count
 139                0 |                                         0
 140                1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@        5
 141                2 |                                         0
 142                4 |@@@@@@@                                  1
 143                8 |                                         0
 144
 145    firefox, builtin, pwd
 146            value  ------------- Distribution ------------- count
 147               16 |                                         0
 148               32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 149               64 |                                         0
 150
 151    firefox, builtin, test
 152            value  ------------- Distribution ------------- count
 153               16 |                                         0
 154               32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 155               64 |                                         0
 156
 157    firefox, builtin, cd
 158            value  ------------- Distribution ------------- count
 159                4 |                                         0
 160                8 |@@@@@@@@@@@@@                            1
 161               16 |@@@@@@@@@@@@@                            1
 162               32 |@@@@@@@@@@@@@                            1
 163               64 |                                         0
 164
 165    firefox, builtin, [
 166            value  ------------- Distribution ------------- count
 167                0 |                                         0
 168                1 |@@@@@@@                                  3
 169                2 |@@                                       1
 170                4 |@@                                       1
 171                8 |@@@@@@@                                  3
 172               16 |@@@@@@@@@@@                              5
 173               32 |@@@@@@@                                  3
 174               64 |@@@@                                     2
 175              128 |                                         0
 176
 177    run-mozilla.sh, builtin, type
 178            value  ------------- Distribution ------------- count
 179              256 |                                         0
 180              512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 181             1024 |                                         0
 182
 183    run-mozilla.sh, builtin, [
 184            value  ------------- Distribution ------------- count
 185                0 |                                         0
 186                1 |@@@@@@@@                                 4
 187                2 |@@@@@@@@@@                               5
 188                4 |@@@@                                     2
 189                8 |@@@@@@                                   3
 190               16 |@@@@@@@@@@                               5
 191               32 |                                         0
 192               64 |                                         0
 193              128 |                                         0
 194              256 |                                         0
 195              512 |                                         0
 196             1024 |                                         0
 197             2048 |@@                                       1
 198             4096 |                                         0
 199
 200    firefox, builtin, echo
 201            value  ------------- Distribution ------------- count
 202               64 |                                         0
 203              128 |@@@@@@@@@@@@@@@@@@@@                     1
 204              256 |                                         0
 205              512 |                                         0
 206             1024 |                                         0
 207             2048 |@@@@@@@@@@@@@@@@@@@@                     1
 208             4096 |                                         0
 209
 210    firefox, cmd, /usr/lib/firefox/run-mozilla.sh
 211            value  ------------- Distribution ------------- count
 212          2097152 |                                         0
 213          4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 214          8388608 |                                         0
 215
 216    run-mozilla.sh, cmd, /usr/lib/firefox/firefox-bin
 217            value  ------------- Distribution ------------- count
 218          2097152 |                                         0
 219          4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 220          8388608 |                                         0
 221
 222 Exclusive function elapsed times (us),
 223
 224    run-mozilla.sh, func, moz_test_binary
 225            value  ------------- Distribution ------------- count
 226               16 |                                         0
 227               32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 228               64 |                                         0
 229
 230    firefox, func, moz_spc_verbose_echo
 231            value  ------------- Distribution ------------- count
 232                2 |                                         0
 233                4 |@@@@@@@@@@@@@                            2
 234                8 |@@@@@@@@@@@@@                            2
 235               16 |@@@@@@@@@@@@@                            2
 236               32 |                                         0
 237
 238    firefox, func, moz_pis_startstop_scripts
 239            value  ------------- Distribution ------------- count
 240              128 |                                         0
 241              256 |@@@@@@@@@@@@@@@@@@@@                     1
 242              512 |                                         0
 243             1024 |                                         0
 244             2048 |                                         0
 245             4096 |                                         0
 246             8192 |                                         0
 247            16384 |                                         0
 248            32768 |@@@@@@@@@@@@@@@@@@@@                     1
 249            65536 |                                         0
 250
 251    run-mozilla.sh, func, moz_run_program
 252            value  ------------- Distribution ------------- count
 253            65536 |                                         0
 254           131072 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 255           262144 |                                         0
 256
 257 Inclusive function elapsed times (us),
 258
 259    firefox, func, moz_spc_verbose_echo
 260            value  ------------- Distribution ------------- count
 261                4 |                                         0
 262                8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              4
 263               16 |@@@@@@@@@@@@@                            2
 264               32 |                                         0
 265
 266    run-mozilla.sh, func, moz_test_binary
 267            value  ------------- Distribution ------------- count
 268               32 |                                         0
 269               64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 270              128 |                                         0
 271
 272    firefox, func, moz_pis_startstop_scripts
 273            value  ------------- Distribution ------------- count
 274              128 |                                         0
 275              256 |@@@@@@@@@@@@@@@@@@@@                     1
 276              512 |                                         0
 277             1024 |                                         0
 278             2048 |                                         0
 279             4096 |                                         0
 280             8192 |                                         0
 281            16384 |                                         0
 282            32768 |@@@@@@@@@@@@@@@@@@@@                     1
 283            65536 |                                         0
 284
 285    run-mozilla.sh, func, moz_run_program
 286            value  ------------- Distribution ------------- count
 287          2097152 |                                         0
 288          4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 289          8388608 |                                         0
 290
 291
 292 As an example of interpreting the output: the inclusive elapsed time for
 293 the "[" (test) builtin,
 294
 295    firefox, builtin, [
 296            value  ------------- Distribution ------------- count
 297                0 |                                         0
 298                1 |@@@@@@@                                  3
 299                2 |@@                                       1
 300                4 |@@                                       1
 301                8 |@@@@@@@                                  3
 302               16 |@@@@@@@@@@@                              5
 303               32 |@@@@@@@                                  3
 304               64 |@@@@                                     2
 305              128 |                                         0
 306
 307 shows that it was called 17 times (after adding up the counts), 5 of which
 308 took between 16 and 31 microseconds.
 309