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