1*c29d5175SchristosThe following are examples of pl_cputime.d. 2*c29d5175Schristos 3*c29d5175SchristosThis script traces the on-CPU time of Perl subroutines (functions) and 4*c29d5175Schristosprints a report. Here it traces the example program, Code/Perl/func_slow.pl. 5*c29d5175Schristos 6*c29d5175Schristos # pl_cputime.d 7*c29d5175Schristos Tracing... Hit Ctrl-C to end. 8*c29d5175Schristos ^C 9*c29d5175Schristos 10*c29d5175Schristos Count, 11*c29d5175Schristos FILE TYPE NAME COUNT 12*c29d5175Schristos func_slow.pl sub func_a 1 13*c29d5175Schristos func_slow.pl sub func_b 1 14*c29d5175Schristos func_slow.pl sub func_c 1 15*c29d5175Schristos - total - 3 16*c29d5175Schristos 17*c29d5175Schristos Exclusive subroutine on-CPU times (us), 18*c29d5175Schristos FILE TYPE NAME TOTAL 19*c29d5175Schristos func_slow.pl sub func_a 264193 20*c29d5175Schristos func_slow.pl sub func_b 538498 21*c29d5175Schristos func_slow.pl sub func_c 798961 22*c29d5175Schristos - total - 1601653 23*c29d5175Schristos 24*c29d5175Schristos Inclusive subroutine on-CPU times (us), 25*c29d5175Schristos FILE TYPE NAME TOTAL 26*c29d5175Schristos func_slow.pl sub func_c 798961 27*c29d5175Schristos func_slow.pl sub func_b 1337459 28*c29d5175Schristos func_slow.pl sub func_a 1601653 29*c29d5175Schristos 30*c29d5175SchristosIn total, 3 subroutines were called, one each of func_a(), func_b() and 31*c29d5175Schristosfunc_c(). 32*c29d5175Schristos 33*c29d5175SchristosThe exclusive subroutine on-CPU times show that func_a() spent around 264.2 ms 34*c29d5175Schristoson-CPU, func_b() spent 538.5 ms, and func_c() spent 799.0 ms. This exclusive 35*c29d5175Schristostimes excludes time spent in other subroutines. 36*c29d5175Schristos 37*c29d5175SchristosThe inclusive subroutine on-CPU times show that func_c() spent around 799.0 ms 38*c29d5175Schristoson-CPU, func_b() spent around 1.3 seconds, and func_a() spent around 1.6 39*c29d5175Schristosseconds. This inclusive time includes the time spent in other subroutines 40*c29d5175Schristoscalled, and since func_a() called func_b() which called func_c(), these 41*c29d5175Schristostimes make perfect sense. 42*c29d5175Schristos 43*c29d5175SchristosThese on-CPU times are the time the thread spent running on a CPU, from when 44*c29d5175Schristosthe subroutine began to when it completed. This does not include time 45*c29d5175Schristosspent off-CPU time such as sleeping for I/O or waiting for scheduling. 46*c29d5175Schristos 47*c29d5175SchristosOn-CPU times are useful for showing who is causing the CPUs to be busy. 48*c29d5175SchristosSee Notes/ALLoncpu_notes.txt for more details. Also see 49*c29d5175SchristosNotes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a 50*c29d5175Schristosdetailed explanation of exclusive vs inclusive subroutine time. 51*c29d5175Schristos 52*c29d5175SchristosIf you study the func_slow.pl program alongside the above output, the numbers 53*c29d5175Schristosshould make sense. 54*c29d5175Schristos 55*c29d5175Schristos 56*c29d5175Schristos 57*c29d5175SchristosThe following traces a Perl network interface statistics tool, "nicstat" 58*c29d5175Schristosversion 0.99, 59*c29d5175Schristos 60*c29d5175Schristos# pl_cputime.pl 61*c29d5175SchristosTracing... Hit Ctrl-C to end. 62*c29d5175Schristos^C 63*c29d5175Schristos 64*c29d5175SchristosCount, 65*c29d5175Schristos FILE TYPE NAME COUNT 66*c29d5175Schristos Config.pm sub DESTROY 1 67*c29d5175Schristos Config.pm sub TIEHASH 1 68*c29d5175Schristos Config.pm sub import 1 69*c29d5175Schristos DynaLoader.pm sub bootstrap 1 70*c29d5175Schristos DynaLoader.pm sub dl_load_flags 1 71*c29d5175Schristos Std.pm sub getopts 1 72*c29d5175Schristos nicstat sub fetch_net_data 1 73*c29d5175Schristos nicstat sub find_nets 1 74*c29d5175Schristos register.pm sub import 1 75*c29d5175Schristos warnings.pm sub BEGIN 1 76*c29d5175Schristos Config.pm sub BEGIN 2 77*c29d5175Schristos DynaLoader.pm sub BEGIN 2 78*c29d5175Schristos Exporter.pm sub import 2 79*c29d5175Schristos register.pm sub mkMask 2 80*c29d5175Schristos vars.pm sub import 2 81*c29d5175Schristos Kstat.pm sub BEGIN 3 82*c29d5175Schristos nicstat sub BEGIN 3 83*c29d5175Schristos vars.pm sub BEGIN 3 84*c29d5175Schristos Config.pm sub FETCH 4 85*c29d5175Schristos strict.pm sub unimport 4 86*c29d5175Schristos strict.pm sub import 5 87*c29d5175Schristos AutoLoader.pm sub BEGIN 6 88*c29d5175Schristos strict.pm sub bits 6 89*c29d5175Schristos nicstat sub print_neat 18 90*c29d5175Schristos - total - 72 91*c29d5175Schristos 92*c29d5175SchristosExclusive subroutine on-CPU times (us), 93*c29d5175Schristos FILE TYPE NAME TOTAL 94*c29d5175Schristos DynaLoader.pm sub dl_load_flags 2 95*c29d5175Schristos Config.pm sub TIEHASH 2 96*c29d5175Schristos Config.pm sub DESTROY 6 97*c29d5175Schristos Config.pm sub BEGIN 7 98*c29d5175Schristos register.pm sub mkMask 8 99*c29d5175Schristos Config.pm sub import 11 100*c29d5175Schristos Config.pm sub FETCH 12 101*c29d5175Schristos strict.pm sub unimport 17 102*c29d5175Schristos strict.pm sub import 21 103*c29d5175Schristos AutoLoader.pm sub BEGIN 22 104*c29d5175Schristos Std.pm sub getopts 33 105*c29d5175Schristos strict.pm sub bits 40 106*c29d5175Schristos register.pm sub import 51 107*c29d5175Schristos vars.pm sub import 65 108*c29d5175Schristos Exporter.pm sub import 88 109*c29d5175Schristos nicstat sub print_neat 426 110*c29d5175Schristos warnings.pm sub BEGIN 598 111*c29d5175Schristos DynaLoader.pm sub bootstrap 677 112*c29d5175Schristos DynaLoader.pm sub BEGIN 1015 113*c29d5175Schristos Kstat.pm sub BEGIN 2627 114*c29d5175Schristos vars.pm sub BEGIN 2642 115*c29d5175Schristos nicstat sub BEGIN 3033 116*c29d5175Schristos nicstat sub fetch_net_data 42018 117*c29d5175Schristos nicstat sub find_nets 52094 118*c29d5175Schristos - total - 105526 119*c29d5175Schristos 120*c29d5175SchristosInclusive subroutine on-CPU times (us), 121*c29d5175Schristos FILE TYPE NAME TOTAL 122*c29d5175Schristos DynaLoader.pm sub dl_load_flags 2 123*c29d5175Schristos Config.pm sub TIEHASH 2 124*c29d5175Schristos Config.pm sub DESTROY 6 125*c29d5175Schristos register.pm sub mkMask 8 126*c29d5175Schristos Config.pm sub import 11 127*c29d5175Schristos Config.pm sub FETCH 12 128*c29d5175Schristos Config.pm sub BEGIN 19 129*c29d5175Schristos strict.pm sub import 28 130*c29d5175Schristos strict.pm sub unimport 35 131*c29d5175Schristos strict.pm sub bits 40 132*c29d5175Schristos AutoLoader.pm sub BEGIN 51 133*c29d5175Schristos register.pm sub import 59 134*c29d5175Schristos Std.pm sub getopts 63 135*c29d5175Schristos vars.pm sub import 65 136*c29d5175Schristos Exporter.pm sub import 88 137*c29d5175Schristos nicstat sub print_neat 426 138*c29d5175Schristos warnings.pm sub BEGIN 598 139*c29d5175Schristos DynaLoader.pm sub bootstrap 680 140*c29d5175Schristos vars.pm sub BEGIN 3313 141*c29d5175Schristos DynaLoader.pm sub BEGIN 4401 142*c29d5175Schristos Kstat.pm sub BEGIN 7124 143*c29d5175Schristos nicstat sub BEGIN 10916 144*c29d5175Schristos nicstat sub fetch_net_data 42018 145*c29d5175Schristos nicstat sub find_nets 52094 146*c29d5175Schristos 147*c29d5175SchristosThe output showed that the most CPU time was spent in the subroutine 148*c29d5175Schristosfind_nets(), with a total exclusive on-CPU time of 52.1 ms. This also matches 149*c29d5175Schristosthe total inclusive time, suggesting that find_nets() didn't call other 150*c29d5175Schristossubroutines. 151*c29d5175Schristos 152