cddl/contrib/dtracetoolkit/Examples/rb_cputime_example.txt

   1 The following are examples of rb_cputime.d.
   2
   3 This script traces the on-CPU time of Ruby functions and prints a report.
   4 Here it traces the example program, Code/Ruby/func_slow.rb
   5
   6 # rb_cputime.d
   7 Tracing... Hit Ctrl-C to end.
   8 ^C
   9
  10 Count,
  11    FILE                 TYPE       NAME                                COUNT
  12    .                    obj-new    NoMemoryError                           1
  13    .                    obj-new    SystemStackError                        1
  14    .                    obj-new    ThreadGroup                             1
  15    .                    obj-new    fatal                                   1
  16    func_slow.rb         func       Object::func_a                          1
  17    func_slow.rb         func       Object::func_b                          1
  18    func_slow.rb         func       Object::func_c                          1
  19    .                    obj-new    Object                                  3
  20    func_slow.rb         func       IO::write                               3
  21    func_slow.rb         func       Module::method_added                    3
  22    func_slow.rb         func       Object::print                           3
  23    func_slow.rb         func       Fixnum::<                          600003
  24    func_slow.rb         func       Fixnum::+                         1200000
  25    -                    total      -                                 1800015
  26
  27 Elapsed times (us),
  28    FILE                 TYPE       NAME                                TOTAL
  29    .                    obj-new    SystemStackError                        2
  30    .                    obj-new    NoMemoryError                           2
  31    .                    obj-new    fatal                                  11
  32    .                    obj-new    ThreadGroup                            12
  33    .                    obj-new    Object                                 19
  34
  35 Exclusive function on-CPU times (us),
  36    FILE                 TYPE       NAME                                TOTAL
  37    func_slow.rb         func       Module::method_added                    4
  38    func_slow.rb         func       Object::print                          57
  39    func_slow.rb         func       IO::write                             180
  40    func_slow.rb         func       Object::func_a                     405946
  41    func_slow.rb         func       Fixnum::<                          691125
  42    func_slow.rb         func       Object::func_b                     809970
  43    func_slow.rb         func       Object::func_c                    1225235
  44    func_slow.rb         func       Fixnum::+                         1285200
  45    -                    total      -                                 4417721
  46
  47 Inclusive function on-CPU times (us),
  48    FILE                 TYPE       NAME                                TOTAL
  49    func_slow.rb         func       Module::method_added                    4
  50    func_slow.rb         func       IO::write                             180
  51    func_slow.rb         func       Object::print                         238
  52    func_slow.rb         func       Fixnum::<                          691125
  53    func_slow.rb         func       Fixnum::+                         1285200
  54    func_slow.rb         func       Object::func_c                    2212572
  55    func_slow.rb         func       Object::func_b                    3683688
  56    func_slow.rb         func       Object::func_a                    4417717
  57
  58 You can see the results are printed in four sections.
  59
  60 The first section reports how many times each subroutine was called, and it's
  61 type.
  62
  63 The second section reports on the on-CPU time of anything that was not of type
  64 "func", in this case the only elements reported here are of type obj-new.
  65
  66 The exclusive function on-CPU times shows, amongst other results, that func_a
  67 spent around 0.4 seconds on-CPU.  This time excludes time spent in other
  68 subroutines.
  69
  70 The inclusive function on-CPU times show that func_a spent around 4.4
  71 seconds on-CPU.  This includes the time spent in other subroutines called.
  72
  73 These on-CPU times are the time the thread spent running on a CPU, from when
  74 the subroutine began to when it completed. This does not include time
  75 spent off-CPU time such as sleeping for I/O or waiting for scheduling.
  76
  77 On-CPU times are useful for showing who is causing the CPUs to be busy.
  78 See Notes/ALLoncpu_notes.txt for more details. Also see
  79 Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
  80 detailed explanation of exclusive vs inclusive subroutine time.
  81