cddl/contrib/dtracetoolkit/Examples/php_calltime_example.txt

   1 The following is an example of running php_calltime.d and tracing the elapsed
   2 times for functions.
   3
   4 We run php_calltime.d while running the program Code/Php/func_abc.php.  We can
   5 see that there are three sections in the DTrace output
   6
   7 # php_calltime.d
   8 Tracing... Hit Ctrl-C to end.
   9 ^C
  10
  11 Count,
  12    FILE                 TYPE       NAME                                COUNT
  13    func_abc.php         func       func_a                                  1
  14    func_abc.php         func       func_b                                  1
  15    func_abc.php         func       func_c                                  1
  16    func_abc.php         func       sleep                                   3
  17    -                    total      -                                       6
  18
  19 Exclusive function elapsed times (us),
  20    FILE                 TYPE       NAME                                TOTAL
  21    func_abc.php         func       func_c                                330
  22    func_abc.php         func       func_b                                367
  23    func_abc.php         func       func_a                                418
  24    func_abc.php         func       sleep                             3025644
  25    -                    total      -                                 3026761
  26
  27 Inclusive function elapsed times (us),
  28    FILE                 TYPE       NAME                                TOTAL
  29    func_abc.php         func       func_c                            1010119
  30    func_abc.php         func       func_b                            2020118
  31    func_abc.php         func       sleep                             3025644
  32    func_abc.php         func       func_a                            3026761
  33
  34 Section 1 - Count shows us how many times each function was called in the
  35 Code/Php/func_abc.php program, with the last line giving us a total number of
  36 functions called (in this case, six).
  37
  38 Section 2 - These elapsed times shows us how many microseconds the program
  39 spends in each function.  This does not include the time spent in any
  40 sub-functions called by that particular function.  Again the last line gives
  41 us the total time in microseconds.
  42
  43 Section 3 - These elapsed times are the absolute time from when the function began to
  44 when it completed - which includes off-CPU time due to other system events
  45 such as I/O, scheduling, interrupts, etc. In particular, for this case it has
  46 included the time waiting for the sleep commands.
  47
  48 Elapsed times are useful for identifying where latencies are.
  49 See Notes/ALLelapsed_notes.txt for more details. Also see
  50 Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
  51 detailed explanation of exclusive vs inclusive function time.