cddl/contrib/dtracetoolkit/Examples/php_calldist_example.txt

   1 The following are examples of php_calldist.d.
   2
   3 This script traces the elapsed time of PHP functions and prints a report
   4 containing distribution plots per subroutine. Here it traces the example program
   5 Code/Php/func_abc.php.
   6
   7 # php_calldist.d
   8 Tracing... Hit Ctrl-C to end.
   9 ^C
  10
  11 Exclusive function elapsed times (us),
  12    func_abc.php, func, func_a
  13            value  ------------- Distribution ------------- count
  14              128 |                                         0
  15              256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  16              512 |                                         0
  17
  18    func_abc.php, func, func_b
  19            value  ------------- Distribution ------------- count
  20              128 |                                         0
  21              256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  22              512 |                                         0
  23
  24    func_abc.php, func, func_c
  25            value  ------------- Distribution ------------- count
  26              128 |                                         0
  27              256 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  28              512 |                                         0
  29
  30    func_abc.php, func, sleep
  31            value  ------------- Distribution ------------- count
  32           262144 |                                         0
  33           524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
  34          1048576 |                                         0
  35
  36
  37 Inclusive function elapsed times (us),
  38    func_abc.php, func, func_c
  39            value  ------------- Distribution ------------- count
  40           262144 |                                         0
  41           524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  42          1048576 |                                         0
  43
  44    func_abc.php, func, func_b
  45            value  ------------- Distribution ------------- count
  46           524288 |                                         0
  47          1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  48          2097152 |                                         0
  49
  50    func_abc.php, func, sleep
  51            value  ------------- Distribution ------------- count
  52           262144 |                                         0
  53           524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
  54          1048576 |                                         0
  55
  56    func_abc.php, func, func_a
  57            value  ------------- Distribution ------------- count
  58          1048576 |                                         0
  59          2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
  60          4194304 |                                         0
  61
  62 In total, 3 subroutines were called, one each of func_a(), func_b() and
  63 func_c(), and sleep was called 3 times.  You can see this reflected in the
  64 "count" column on the right.
  65
  66 The exclusive subroutine elapsed times show that each subroutine spent
  67 between 256 and 512 microseconds. This time excludes the time spent in
  68 other subroutines.
  69
  70 The inclusive subroutine elapsed times show that func_c() took between 0.5
  71 seconds and 1 second, func_b() took between 1 second and 2.1 seconds, and
  72 func_a() took between 2.1 seconds and 4.2 seconds to execute. This time
  73 includes the time spent in other subroutines called, and since func_a() called
  74 func_b() which called func_c(), these times make sense.
  75
  76 These elapsed times are the absolute time from when the subroutine began to
  77 when it completed - which includes off-CPU time due to other system events
  78 such as I/O, scheduling, interrupts, etc.
  79
  80 Elapsed times are useful for identifying where latencies are.
  81 See Notes/ALLelapsed_notes.txt for more details. Also see
  82 Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
  83 detailed explanation of exclusive vs inclusive subroutine time.
  84