cddl/contrib/dtracetoolkit/Examples/rb_flowtime_example.txt

   1 The following are examples of rb_flowtime.d.
   2
   3 This is a simple script to trace the flow of Ruby methods.
   4 Here it traces the example program, Code/Ruby/func_abc.rb
   5
   6 # rb_flowtime.d
   7   C TIME(us)         FILE             DELTA(us) -- CLASS::METHOD
   8   0 3066547402640    func_abc.rb              2 -> Module::method_added
   9   0 3066547402662    func_abc.rb             22 <- Module::method_added
  10   0 3066547402683    func_abc.rb             20 -> Module::method_added
  11   0 3066547402693    func_abc.rb              9 <- Module::method_added
  12   0 3066547402707    func_abc.rb             14 -> Module::method_added
  13   0 3066547402716    func_abc.rb              9 <- Module::method_added
  14   0 3066547402729    func_abc.rb             12 -> Object::func_a
  15   0 3066547402740    func_abc.rb             10   -> Object::print
  16   0 3066547402759    func_abc.rb             18     -> IO::write
  17   0 3066547402860    func_abc.rb            101     <- IO::write
  18   0 3066547402871    func_abc.rb             10   <- Object::print
  19   0 3066547402881    func_abc.rb             10   -> Object::sleep
  20   0 3066548410630    func_abc.rb        1007749   <- Object::sleep
  21   0 3066548410660    func_abc.rb             30   -> Object::func_b
  22   0 3066548410679    func_abc.rb             18     -> Object::print
  23   0 3066548410689    func_abc.rb             10       -> IO::write
  24   0 3066548410730    func_abc.rb             40       <- IO::write
  25   0 3066548410740    func_abc.rb              9     <- Object::print
  26   0 3066548410749    func_abc.rb              9     -> Object::sleep
  27   0 3066549420724    func_abc.rb        1009974     <- Object::sleep
  28   0 3066549420755    func_abc.rb             30     -> Object::func_c
  29   0 3066549420773    func_abc.rb             18       -> Object::print
  30   0 3066549420783    func_abc.rb             10         -> IO::write
  31   0 3066549420825    func_abc.rb             41         <- IO::write
  32   0 3066549420835    func_abc.rb              9       <- Object::print
  33   0 3066549420844    func_abc.rb              9       -> Object::sleep
  34   0 3066550430611    func_abc.rb        1009766       <- Object::sleep
  35   0 3066550430635    func_abc.rb             24     <- Object::func_c
  36   0 3066550430645    func_abc.rb             10   <- Object::func_b
  37   0 3066550430655    func_abc.rb              9 <- Object::func_a
  38 ^C
  39
  40 The fifth column is indented by 2 spaces to show when a new method begins.
  41 This shows which method is calling which.
  42
  43 The TIME(us) column shows time since boot.
  44
  45 The DELTA(us) column shows time from that line to the previous line, and
  46 so can be a bit tricky to read. For example, the seventh line of data output
  47 (skipping the header) reads as "the time from func_a beginning to
  48 calling the print method was 10 microseconds".
  49
  50 The FILE column shows file that was being executed.
  51
  52 If the output looks shuffled, check the CPU "C" and "TIME" columns, and
  53 post sort based on TIME if necessary.
  54
  55 See Notes/ALLflow_notes.txt for important notes about reading flow outputs.
  56