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