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