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