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 # php_calltime.d 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 Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a detailed explanation of exclusive vs inclusive function time. |