1*e137d3e0SchristosThe following are examples of pl_calltime.d. 2*e137d3e0Schristos 3*e137d3e0SchristosThis script traces the elapsed time of Perl subroutines (functions) and 4*e137d3e0Schristosprints a report. Here it traces the example program, Code/Perl/func_abc.pl. 5*e137d3e0Schristos 6*e137d3e0Schristos # pl_calltime.d 7*e137d3e0Schristos Tracing... Hit Ctrl-C to end. 8*e137d3e0Schristos ^C 9*e137d3e0Schristos 10*e137d3e0Schristos Count, 11*e137d3e0Schristos FILE TYPE NAME COUNT 12*e137d3e0Schristos func_abc.pl sub func_a 1 13*e137d3e0Schristos func_abc.pl sub func_b 1 14*e137d3e0Schristos func_abc.pl sub func_c 1 15*e137d3e0Schristos - total - 3 16*e137d3e0Schristos 17*e137d3e0Schristos Exclusive subroutine elapsed times (us), 18*e137d3e0Schristos FILE TYPE NAME TOTAL 19*e137d3e0Schristos func_abc.pl sub func_a 1006119 20*e137d3e0Schristos func_abc.pl sub func_c 1009978 21*e137d3e0Schristos func_abc.pl sub func_b 1010273 22*e137d3e0Schristos - total - 3026371 23*e137d3e0Schristos 24*e137d3e0Schristos Inclusive subroutine elapsed times (us), 25*e137d3e0Schristos FILE TYPE NAME TOTAL 26*e137d3e0Schristos func_abc.pl sub func_c 1009978 27*e137d3e0Schristos func_abc.pl sub func_b 2020252 28*e137d3e0Schristos func_abc.pl sub func_a 3026371 29*e137d3e0Schristos 30*e137d3e0SchristosIn total, 3 subroutines were called, one of each. 31*e137d3e0Schristos 32*e137d3e0SchristosThe exclusive subroutine elapsed times show that each subroutine spent around 33*e137d3e0Schristos1.0 seconds of time (~1000000 us) processing code - while not in other 34*e137d3e0Schristossubroutines. 35*e137d3e0Schristos 36*e137d3e0SchristosThe inclusive subroutine elapsed times show that func_a() took around 3.0 37*e137d3e0Schristosseconds to execute, followed by func_b() at 2.0 seconds, and func_c() at 1.0. 38*e137d3e0SchristosThe inclusive time includes the time spent in other subroutines called, and 39*e137d3e0Schristossince func_a() called func_b() which called func_c(), these times make 40*e137d3e0Schristosperfect sense. 41*e137d3e0Schristos 42*e137d3e0SchristosThese elapsed times are the absolute time from when the subroutine began to 43*e137d3e0Schristoswhen it completed - which includes off-CPU time due to other system events 44*e137d3e0Schristossuch as I/O, scheduling, interrupts, etc. 45*e137d3e0Schristos 46*e137d3e0SchristosElapsed times are useful for identifying where latencies are. 47*e137d3e0SchristosSee Notes/ALLelapsed_notes.txt for more details. Also see 48*e137d3e0SchristosNotes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a 49*e137d3e0Schristosdetailed explanation of exclusive vs inclusive subroutine time. 50*e137d3e0Schristos 51*e137d3e0SchristosIf you study the func_abc.pl program alongside the above output, the numbers 52*e137d3e0Schristosshould make sense. 53*e137d3e0Schristos 54*e137d3e0Schristos 55*e137d3e0Schristos 56*e137d3e0SchristosThe following traces a Perl network interface statistics tool, "nicstat" 57*e137d3e0Schristosversion 0.99, 58*e137d3e0Schristos 59*e137d3e0Schristos# pl_calltime.d 60*e137d3e0SchristosTracing... Hit Ctrl-C to end. 61*e137d3e0Schristos^C 62*e137d3e0Schristos 63*e137d3e0SchristosCount, 64*e137d3e0Schristos FILE TYPE NAME COUNT 65*e137d3e0Schristos Config.pm sub DESTROY 1 66*e137d3e0Schristos Config.pm sub TIEHASH 1 67*e137d3e0Schristos Config.pm sub import 1 68*e137d3e0Schristos DynaLoader.pm sub bootstrap 1 69*e137d3e0Schristos DynaLoader.pm sub dl_load_flags 1 70*e137d3e0Schristos Std.pm sub getopts 1 71*e137d3e0Schristos nicstat sub fetch_net_data 1 72*e137d3e0Schristos nicstat sub find_nets 1 73*e137d3e0Schristos register.pm sub import 1 74*e137d3e0Schristos warnings.pm sub BEGIN 1 75*e137d3e0Schristos Config.pm sub BEGIN 2 76*e137d3e0Schristos DynaLoader.pm sub BEGIN 2 77*e137d3e0Schristos Exporter.pm sub import 2 78*e137d3e0Schristos register.pm sub mkMask 2 79*e137d3e0Schristos vars.pm sub import 2 80*e137d3e0Schristos Kstat.pm sub BEGIN 3 81*e137d3e0Schristos nicstat sub BEGIN 3 82*e137d3e0Schristos vars.pm sub BEGIN 3 83*e137d3e0Schristos Config.pm sub FETCH 4 84*e137d3e0Schristos strict.pm sub unimport 4 85*e137d3e0Schristos strict.pm sub import 5 86*e137d3e0Schristos AutoLoader.pm sub BEGIN 6 87*e137d3e0Schristos strict.pm sub bits 6 88*e137d3e0Schristos nicstat sub print_neat 18 89*e137d3e0Schristos - total - 72 90*e137d3e0Schristos 91*e137d3e0SchristosExclusive subroutine elapsed times (us), 92*e137d3e0Schristos FILE TYPE NAME TOTAL 93*e137d3e0Schristos DynaLoader.pm sub dl_load_flags 2 94*e137d3e0Schristos Config.pm sub TIEHASH 3 95*e137d3e0Schristos Config.pm sub DESTROY 9 96*e137d3e0Schristos register.pm sub mkMask 11 97*e137d3e0Schristos Config.pm sub import 12 98*e137d3e0Schristos Config.pm sub FETCH 17 99*e137d3e0Schristos strict.pm sub import 38 100*e137d3e0Schristos Config.pm sub BEGIN 38 101*e137d3e0Schristos strict.pm sub bits 49 102*e137d3e0Schristos vars.pm sub import 59 103*e137d3e0Schristos strict.pm sub unimport 65 104*e137d3e0Schristos AutoLoader.pm sub BEGIN 70 105*e137d3e0Schristos Std.pm sub getopts 78 106*e137d3e0Schristos register.pm sub import 86 107*e137d3e0Schristos Exporter.pm sub import 112 108*e137d3e0Schristos warnings.pm sub BEGIN 680 109*e137d3e0Schristos DynaLoader.pm sub BEGIN 1131 110*e137d3e0Schristos DynaLoader.pm sub bootstrap 1221 111*e137d3e0Schristos nicstat sub print_neat 2450 112*e137d3e0Schristos vars.pm sub BEGIN 2608 113*e137d3e0Schristos Kstat.pm sub BEGIN 3171 114*e137d3e0Schristos nicstat sub BEGIN 3963 115*e137d3e0Schristos nicstat sub fetch_net_data 45424 116*e137d3e0Schristos nicstat sub find_nets 55737 117*e137d3e0Schristos - total - 117047 118*e137d3e0Schristos 119*e137d3e0SchristosInclusive subroutine elapsed times (us), 120*e137d3e0Schristos FILE TYPE NAME TOTAL 121*e137d3e0Schristos DynaLoader.pm sub dl_load_flags 2 122*e137d3e0Schristos Config.pm sub TIEHASH 3 123*e137d3e0Schristos Config.pm sub DESTROY 9 124*e137d3e0Schristos register.pm sub mkMask 11 125*e137d3e0Schristos Config.pm sub import 12 126*e137d3e0Schristos Config.pm sub FETCH 17 127*e137d3e0Schristos strict.pm sub import 46 128*e137d3e0Schristos strict.pm sub bits 49 129*e137d3e0Schristos vars.pm sub import 59 130*e137d3e0Schristos Config.pm sub BEGIN 64 131*e137d3e0Schristos strict.pm sub unimport 87 132*e137d3e0Schristos register.pm sub import 97 133*e137d3e0Schristos Std.pm sub getopts 112 134*e137d3e0Schristos Exporter.pm sub import 112 135*e137d3e0Schristos AutoLoader.pm sub BEGIN 140 136*e137d3e0Schristos warnings.pm sub BEGIN 680 137*e137d3e0Schristos DynaLoader.pm sub bootstrap 1224 138*e137d3e0Schristos nicstat sub print_neat 2450 139*e137d3e0Schristos vars.pm sub BEGIN 3412 140*e137d3e0Schristos DynaLoader.pm sub BEGIN 4656 141*e137d3e0Schristos Kstat.pm sub BEGIN 8020 142*e137d3e0Schristos nicstat sub BEGIN 13313 143*e137d3e0Schristos nicstat sub fetch_net_data 45424 144*e137d3e0Schristos nicstat sub find_nets 55737 145*e137d3e0Schristos 146*e137d3e0SchristosThe output showed that the most time was spent in the subroutine find_nets(), 147*e137d3e0Schristoswith a total exclusive elapsed time of 55.7 ms. This also matches the 148*e137d3e0Schristostotal inclusive time, suggesting that find_nets() didn't call other 149*e137d3e0Schristossubroutines. 150*e137d3e0Schristos 151