cddl/contrib/dtracetoolkit/Examples/rb_cpudist_example.txt

   1 The following are examples of rb_cpudist.d.
   2
   3 This script traces the on-CPU time of Ruby functions and prints a report in
   4 the form of a histogram.  Here it traces the example program,
   5 Code/Ruby/func_slow.rb
   6
   7 # rb_cpudist.d
   8 Tracing... Hit Ctrl-C to end.
   9 ^C
  10
  11 On-CPU 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 |@@@@@@@@@@@@@                            1
  42               16 |                                         0
  43
  44
  45 Exclusive function on-CPU times (us),
  46    func_slow.rb, func, Module::method_added
  47            value  ------------- Distribution ------------- count
  48                0 |                                         0
  49                1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
  50                2 |                                         0
  51
  52    func_slow.rb, func, Object::print
  53            value  ------------- Distribution ------------- count
  54                2 |                                         0
  55                4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2
  56                8 |@@@@@@@@@@@@@                            1
  57               16 |                                         0
  58
  59    func_slow.rb, func, IO::write
  60            value  ------------- Distribution ------------- count
  61               16 |                                         0
  62               32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2
  63               64 |@@@@@@@@@@@@@                            1
  64              128 |                                         0
  65
  66    func_slow.rb, func, Object::func_a
  67            value  ------------- Distribution ------------- count
  68           131072 |                                         0
  69           262144 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  70           524288 |                                         0
  71
  72    func_slow.rb, func, Object::func_b
  73            value  ------------- Distribution ------------- count
  74           262144 |                                         0
  75           524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  76          1048576 |                                         0
  77
  78    func_slow.rb, func, Fixnum::<
  79            value  ------------- Distribution ------------- count
  80                0 |                                         0
  81                1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 599556
  82                2 |                                         72
  83                4 |                                         35
  84                8 |                                         128
  85               16 |                                         158
  86               32 |                                         49
  87               64 |                                         3
  88              128 |                                         2
  89              256 |                                         0
  90
  91    func_slow.rb, func, Object::func_c
  92            value  ------------- Distribution ------------- count
  93           524288 |                                         0
  94          1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  95          2097152 |                                         0
  96
  97    func_slow.rb, func, Fixnum::+
  98            value  ------------- Distribution ------------- count
  99                0 |                                         0
 100                1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1199062
 101                2 |                                         138
 102                4 |                                         74
 103                8 |                                         279
 104               16 |                                         344
 105               32 |                                         91
 106               64 |                                         9
 107              128 |                                         0
 108              256 |                                         3
 109              512 |                                         0
 110
 111
 112 Inclusive function on-CPU times (us),
 113    func_slow.rb, func, Module::method_added
 114            value  ------------- Distribution ------------- count
 115                0 |                                         0
 116                1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
 117                2 |                                         0
 118
 119    func_slow.rb, func, IO::write
 120            value  ------------- Distribution ------------- count
 121               16 |                                         0
 122               32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2
 123               64 |@@@@@@@@@@@@@                            1
 124              128 |                                         0
 125
 126    func_slow.rb, func, Object::print
 127            value  ------------- Distribution ------------- count
 128               16 |                                         0
 129               32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2
 130               64 |@@@@@@@@@@@@@                            1
 131              128 |                                         0
 132
 133    func_slow.rb, func, Fixnum::<
 134            value  ------------- Distribution ------------- count
 135                0 |                                         0
 136                1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 599556
 137                2 |                                         72
 138                4 |                                         35
 139                8 |                                         128
 140               16 |                                         158
 141               32 |                                         49
 142               64 |                                         3
 143              128 |                                         2
 144              256 |                                         0
 145
 146    func_slow.rb, func, Fixnum::+
 147            value  ------------- Distribution ------------- count
 148                0 |                                         0
 149                1 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1199062
 150                2 |                                         138
 151                4 |                                         74
 152                8 |                                         279
 153               16 |                                         344
 154               32 |                                         91
 155               64 |                                         9
 156              128 |                                         0
 157              256 |                                         3
 158              512 |                                         0
 159
 160    func_slow.rb, func, Object::func_b
 161            value  ------------- Distribution ------------- count
 162          1048576 |                                         0
 163          2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 164          4194304 |                                         0
 165
 166    func_slow.rb, func, Object::func_c
 167            value  ------------- Distribution ------------- count
 168          1048576 |                                         0
 169          2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 170          4194304 |                                         0
 171
 172    func_slow.rb, func, Object::func_a
 173            value  ------------- Distribution ------------- count
 174          2097152 |                                         0
 175          4194304 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
 176          8388608 |                                         0
 177
 178 You can see that the results are in three sections.
 179
 180 The first section shows us the on-CPU time for actions that were not of the
 181 type 'func'.
 182
 183 The second section, Exclusive function on-CPU times, shows us the time spent
 184 on-CPU by various functions, not including time spent in subroutines.  You can
 185 see here that Object::print had two instances of being on-CPU between 4
 186 microseconds and 7 microseconds, and once instance of being on-CPU between 8
 187 microseconds and 15 microseconds.
 188
 189 The third section, Inclusive function on-CPU times, shows us the time spent
 190 on-CPU by various functions, including that time spent in subroutines called
 191 by those functions.  You can see that here Object::print had two instances
 192 of being on-CPU between 32 microseconds and 63 microseconds, and one instance
 193 of being on-CPU between 64 microseconds and 127 microseconds.
 194
 195 It is important to pay close attention to the third column, "count" as this
 196 will indicate if there were any instances in a particular timeframe, even if
 197 the number is too small to show up on the histogram clearly.  See Inclusive
 198 function on-CPU time for Fixnum::+ for an example.
 199