1 The following are examples of pl_calltime.d.
3 This script traces the elapsed time of Perl subroutines (functions) and
4 prints a report. Here it traces the example program, Code/Perl/func_abc.pl.
7 Tracing... Hit Ctrl-C to end.
12 func_abc.pl sub func_a 1
13 func_abc.pl sub func_b 1
14 func_abc.pl sub func_c 1
17 Exclusive subroutine elapsed times (us),
19 func_abc.pl sub func_a 1006119
20 func_abc.pl sub func_c 1009978
21 func_abc.pl sub func_b 1010273
24 Inclusive subroutine elapsed times (us),
26 func_abc.pl sub func_c 1009978
27 func_abc.pl sub func_b 2020252
28 func_abc.pl sub func_a 3026371
30 In total, 3 subroutines were called, one of each.
32 The exclusive subroutine elapsed times show that each subroutine spent around
33 1.0 seconds of time (~1000000 us) processing code - while not in other
36 The inclusive subroutine elapsed times show that func_a() took around 3.0
37 seconds to execute, followed by func_b() at 2.0 seconds, and func_c() at 1.0.
38 The inclusive time includes the time spent in other subroutines called, and
39 since func_a() called func_b() which called func_c(), these times make
42 These elapsed times are the absolute time from when the subroutine began to
43 when it completed - which includes off-CPU time due to other system events
44 such as I/O, scheduling, interrupts, etc.
46 Elapsed times are useful for identifying where latencies are.
47 See Notes/ALLelapsed_notes.txt for more details. Also see
48 Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
49 detailed explanation of exclusive vs inclusive subroutine time.
51 If you study the func_abc.pl program alongside the above output, the numbers
56 The following traces a Perl network interface statistics tool, "nicstat"
60 Tracing... Hit Ctrl-C to end.
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
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
76 DynaLoader.pm sub BEGIN 2
77 Exporter.pm sub import 2
78 register.pm sub mkMask 2
84 strict.pm sub unimport 4
85 strict.pm sub import 5
86 AutoLoader.pm sub BEGIN 6
88 nicstat sub print_neat 18
91 Exclusive subroutine elapsed times (us),
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
119 Inclusive subroutine elapsed times (us),
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
146 The output showed that the most time was spent in the subroutine find_nets(),
147 with a total exclusive elapsed time of 55.7 ms. This also matches the
148 total inclusive time, suggesting that find_nets() didn't call other