The following is an example of running php_calltime.d and tracing the elapsed
times for functions.
We run php_calltime.d while running the program Code/Php/func_abc.php. We can
see that there are three sections in the DTrace output
Tracing... Hit Ctrl-C to end.
^C
Count,
FILE TYPE NAME COUNT
func_abc.php func func_a 1
func_abc.php func func_b 1
func_abc.php func func_c 1
func_abc.php func sleep 3
- total - 6
Exclusive function elapsed times (us),
FILE TYPE NAME TOTAL
func_abc.php func func_c 330
func_abc.php func func_b 367
func_abc.php func func_a 418
func_abc.php func sleep 3025644
- total - 3026761
Inclusive function elapsed times (us),
FILE TYPE NAME TOTAL
func_abc.php func func_c 1010119
func_abc.php func func_b 2020118
func_abc.php func sleep 3025644
func_abc.php func func_a 3026761
Section 1 - Count shows us how many times each function was called in the
Code/Php/func_abc.php program, with the last line giving us a total number of
functions called (in this case, six).
Section 2 - These elapsed times shows us how many microseconds the program
spends in each function. This does not include the time spent in any
sub-functions called by that particular function. Again the last line gives
us the total time in microseconds.
Section 3 - These elapsed times are the absolute time from when the function began to
when it completed - which includes off-CPU time due to other system events
such as I/O, scheduling, interrupts, etc. In particular, for this case it has
included the time waiting for the sleep commands.
Elapsed times are useful for identifying where latencies are.
See Notes/ALLelapsed_notes.txt for more details. Also see
detailed explanation of exclusive vs inclusive function time.