cddl/contrib/dtracetoolkit/Examples/rb_calldist_example.txt

   1 The following is an example of running rb_calldist.d and tracing the elapsed
   2 times for functions.
   3
   4 We run rb_calldist.d while running the program Code/Ruby/func_abc.rb.  We can
   5 see that there are three sections in the DTrace output
   6
   7 # rb_calldist.d
   8 Tracing... Hit Ctrl-C to end.
   9 ^C
  10
  11 Elapsed times (us),
  12    ., obj-new, NoMemoryError
  13            value  ------------- Distribution ------------- count
  14                1 |                                         0
  15                2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  16                4 |                                         0
  17
  18    ., obj-new, SystemStackError
  19            value  ------------- Distribution ------------- count
  20                1 |                                         0
  21                2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  22                4 |                                         0
  23
  24    ., obj-new, ThreadGroup
  25            value  ------------- Distribution ------------- count
  26                4 |                                         0
  27                8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  28               16 |                                         0
  29
  30    ., obj-new, fatal
  31            value  ------------- Distribution ------------- count
  32                4 |                                         0
  33                8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  34               16 |                                         0
  35
  36    ., obj-new, Object
  37            value  ------------- Distribution ------------- count
  38                1 |                                         0
  39                2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2
  40                4 |                                         0
  41                8 |                                         0
  42               16 |@@@@@@@@@@@@@                            1
  43               32 |                                         0
  44
  45
  46 Exclusive function elapsed times (us),
  47    func_abc.rb, func, Module::method_added
  48            value  ------------- Distribution ------------- count
  49                1 |                                         0
  50                2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2
  51                4 |@@@@@@@@@@@@@                            1
  52                8 |                                         0
  53
  54    func_abc.rb, func, Object::print
  55            value  ------------- Distribution ------------- count
  56                8 |                                         0
  57               16 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2
  58               32 |@@@@@@@@@@@@@                            1
  59               64 |                                         0
  60
  61    func_abc.rb, func, IO::write
  62            value  ------------- Distribution ------------- count
  63               16 |                                         0
  64               32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2
  65               64 |@@@@@@@@@@@@@                            1
  66              128 |                                         0
  67
  68    func_abc.rb, func, Object::func_a
  69            value  ------------- Distribution ------------- count
  70              128 |                                         0
  71              256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  72              512 |                                         0
  73
  74    func_abc.rb, func, Object::func_b
  75            value  ------------- Distribution ------------- count
  76              128 |                                         0
  77              256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  78              512 |                                         0
  79
  80    func_abc.rb, func, Object::func_c
  81            value  ------------- Distribution ------------- count
  82              128 |                                         0
  83              256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  84              512 |                                         0
  85
  86    func_abc.rb, func, Object::sleep
  87            value  ------------- Distribution ------------- count
  88           262144 |                                         0
  89           524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
  90          1048576 |                                         0
  91
  92
  93 Inclusive function elapsed times (us),
  94    func_abc.rb, func, Module::method_added
  95            value  ------------- Distribution ------------- count
  96                1 |                                         0
  97                2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2
  98                4 |@@@@@@@@@@@@@                            1
  99                8 |                                         0
 100
 101    func_abc.rb, func, IO::write
 102            value  ------------- Distribution ------------- count
 103               16 |                                         0
 104               32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2
 105               64 |@@@@@@@@@@@@@                            1
 106              128 |                                         0
 107
 108    func_abc.rb, func, Object::print
 109            value  ------------- Distribution ------------- count
 110               32 |                                         0
 111               64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2
 112              128 |@@@@@@@@@@@@@                            1
 113              256 |                                         0
 114
 115    func_abc.rb, func, Object::func_c
 116            value  ------------- Distribution ------------- count
 117           262144 |                                         0
 118           524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 119          1048576 |                                         0
 120
 121    func_abc.rb, func, Object::func_b
 122            value  ------------- Distribution ------------- count
 123           524288 |                                         0
 124          1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 125          2097152 |                                         0
 126
 127    func_abc.rb, func, Object::sleep
 128            value  ------------- Distribution ------------- count
 129           262144 |                                         0
 130           524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
 131          1048576 |                                         0
 132
 133    func_abc.rb, func, Object::func_a
 134            value  ------------- Distribution ------------- count
 135          1048576 |                                         0
 136          2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 137          4194304 |                                         0
 138
 139 The elapsed times show us that the script spent some small amount of time
 140 processing various events that were not functions.  In this case they were all
 141 obj-new events, and you can see that the slowest of these was a new Object at
 142 between 16 microseconds and 31 microseconds.
 143
 144 The exclusive subroutine elapsed times show that each of our user defined
 145 functions took between 256 and 511 microseconds. This time excludes the time
 146 spent in other subroutines.
 147
 148 The inclusive subroutine elapsed times show that func_c() took between 0.5
 149 seconds and 1 second, func_b() took between 1 second and 2.1 seconds, and
 150 func_a() took between 2.1 seconds and 4.2 seconds to execute. This time
 151 includes the time spent in other subroutines called, and since func_a() called
 152 func_b() which called func_c(), these times make sense.
 153