1 The following is an example of running php_calltime.d and tracing the elapsed
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
8 Tracing... Hit Ctrl-C to end.
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
19 Exclusive function elapsed times (us),
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
27 Inclusive function elapsed times (us),
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
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).
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.
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.
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.