cddl/contrib/dtracetoolkit/Examples/rb_calltime_example.txt

   1 The following is an example of running rb_calltime.d and tracing the elapsed
   2 times for functions.
   3
   4 We run rb_calltime.d while running the program Code/Ruby/func_abc.rb.  We can
   5 see that there are four sections in the DTrace output
   6
   7 # rb_calltime.d
   8 Tracing... Hit Ctrl-C to end.
   9 ^C
  10
  11 Count,
  12    FILE                 TYPE       NAME                                COUNT
  13    .                    obj-new    NoMemoryError                           1
  14    .                    obj-new    SystemStackError                        1
  15    .                    obj-new    ThreadGroup                             1
  16    .                    obj-new    fatal                                   1
  17    func_abc.rb          func       Object::func_a                          1
  18    func_abc.rb          func       Object::func_b                          1
  19    func_abc.rb          func       Object::func_c                          1
  20    .                    obj-new    Object                                  3
  21    func_abc.rb          func       IO::write                               3
  22    func_abc.rb          func       Module::method_added                    3
  23    func_abc.rb          func       Object::print                           3
  24    func_abc.rb          func       Object::sleep                           3
  25    -                    total      -                                      15
  26
  27 Elapsed times (us),
  28    FILE                 TYPE       NAME                                TOTAL
  29    .                    obj-new    SystemStackError                        3
  30    .                    obj-new    NoMemoryError                           3
  31    .                    obj-new    fatal                                  11
  32    .                    obj-new    ThreadGroup                            13
  33    .                    obj-new    Object                                 26
  34
  35 Exclusive function elapsed times (us),
  36    FILE                 TYPE       NAME                                TOTAL
  37    func_abc.rb          func       Module::method_added                    9
  38    func_abc.rb          func       Object::print                          92
  39    func_abc.rb          func       IO::write                             185
  40    func_abc.rb          func       Object::func_c                        344
  41    func_abc.rb          func       Object::func_a                        379
  42    func_abc.rb          func       Object::func_b                        383
  43    func_abc.rb          func       Object::sleep                     3020597
  44    -                    total      -                                 3021992
  45
  46 Inclusive function elapsed times (us),
  47    FILE                 TYPE       NAME                                TOTAL
  48    func_abc.rb          func       Module::method_added                    9
  49    func_abc.rb          func       IO::write                             185
  50    func_abc.rb          func       Object::print                         277
  51    func_abc.rb          func       Object::func_c                    1009829
  52    func_abc.rb          func       Object::func_b                    2019781
  53    func_abc.rb          func       Object::sleep                     3020597
  54    func_abc.rb          func       Object::func_a                    3021983
  55
  56 The first section, Count, shows us how many times each function associated
  57 with func_abc.rb was called.  It also shows other functions called by the Ruby
  58 engine.
  59
  60 The second section, elapsed times, shows how long each action that was not
  61 calling a function took.
  62
  63 The third section, exclusive function elapsed times, shows us how many
  64 microseconds the program spends in each function.  This does not include the
  65 time spent in any sub-functions called by that particular function.  The last
  66 line gives us the total time in microseconds.
  67
  68 The fourth section, inclusive function elapsed times, are the absolute time
  69 from when the function began to when it completed - which includes off-CPU time
  70 due to other system events such as I/O, scheduling, interrupts, etc. In
  71 particular, for this case it has included the time waiting for the sleep
  72 commands.
  73
  74 Elapsed times are useful for identifying where latencies are.
  75 See Notes/ALLelapsed_notes.txt for more details. Also see
  76 Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
  77 detailed explanation of exclusive vs inclusive function time.