1 The following are examples of pl_cputime.d.
3 This script traces the on-CPU time of Perl subroutines (functions) and
4 prints a report. Here it traces the example program, Code/Perl/func_slow.pl.
7 Tracing... Hit Ctrl-C to end.
12 func_slow.pl sub func_a 1
13 func_slow.pl sub func_b 1
14 func_slow.pl sub func_c 1
17 Exclusive subroutine on-CPU times (us),
19 func_slow.pl sub func_a 264193
20 func_slow.pl sub func_b 538498
21 func_slow.pl sub func_c 798961
24 Inclusive subroutine on-CPU times (us),
26 func_slow.pl sub func_c 798961
27 func_slow.pl sub func_b 1337459
28 func_slow.pl sub func_a 1601653
30 In total, 3 subroutines were called, one each of func_a(), func_b() and
33 The exclusive subroutine on-CPU times show that func_a() spent around 264.2 ms
34 on-CPU, func_b() spent 538.5 ms, and func_c() spent 799.0 ms. This exclusive
35 times excludes time spent in other subroutines.
37 The inclusive subroutine on-CPU times show that func_c() spent around 799.0 ms
38 on-CPU, func_b() spent around 1.3 seconds, and func_a() spent around 1.6
39 seconds. This inclusive time includes the time spent in other subroutines
40 called, and since func_a() called func_b() which called func_c(), these
41 times make perfect sense.
43 These on-CPU times are the time the thread spent running on a CPU, from when
44 the subroutine began to when it completed. This does not include time
45 spent off-CPU time such as sleeping for I/O or waiting for scheduling.
47 On-CPU times are useful for showing who is causing the CPUs to be busy.
48 See Notes/ALLoncpu_notes.txt for more details. Also see
49 Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
50 detailed explanation of exclusive vs inclusive subroutine time.
52 If you study the func_slow.pl program alongside the above output, the numbers
57 The following traces a Perl network interface statistics tool, "nicstat"
61 Tracing... Hit Ctrl-C to end.
66 Config.pm sub DESTROY 1
67 Config.pm sub TIEHASH 1
68 Config.pm sub import 1
69 DynaLoader.pm sub bootstrap 1
70 DynaLoader.pm sub dl_load_flags 1
72 nicstat sub fetch_net_data 1
73 nicstat sub find_nets 1
74 register.pm sub import 1
75 warnings.pm sub BEGIN 1
77 DynaLoader.pm sub BEGIN 2
78 Exporter.pm sub import 2
79 register.pm sub mkMask 2
85 strict.pm sub unimport 4
86 strict.pm sub import 5
87 AutoLoader.pm sub BEGIN 6
89 nicstat sub print_neat 18
92 Exclusive subroutine on-CPU times (us),
94 DynaLoader.pm sub dl_load_flags 2
95 Config.pm sub TIEHASH 2
96 Config.pm sub DESTROY 6
98 register.pm sub mkMask 8
99 Config.pm sub import 11
100 Config.pm sub FETCH 12
101 strict.pm sub unimport 17
102 strict.pm sub import 21
103 AutoLoader.pm sub BEGIN 22
104 Std.pm sub getopts 33
105 strict.pm sub bits 40
106 register.pm sub import 51
107 vars.pm sub import 65
108 Exporter.pm sub import 88
109 nicstat sub print_neat 426
110 warnings.pm sub BEGIN 598
111 DynaLoader.pm sub bootstrap 677
112 DynaLoader.pm sub BEGIN 1015
113 Kstat.pm sub BEGIN 2627
114 vars.pm sub BEGIN 2642
115 nicstat sub BEGIN 3033
116 nicstat sub fetch_net_data 42018
117 nicstat sub find_nets 52094
120 Inclusive subroutine on-CPU times (us),
122 DynaLoader.pm sub dl_load_flags 2
123 Config.pm sub TIEHASH 2
124 Config.pm sub DESTROY 6
125 register.pm sub mkMask 8
126 Config.pm sub import 11
127 Config.pm sub FETCH 12
128 Config.pm sub BEGIN 19
129 strict.pm sub import 28
130 strict.pm sub unimport 35
131 strict.pm sub bits 40
132 AutoLoader.pm sub BEGIN 51
133 register.pm sub import 59
134 Std.pm sub getopts 63
135 vars.pm sub import 65
136 Exporter.pm sub import 88
137 nicstat sub print_neat 426
138 warnings.pm sub BEGIN 598
139 DynaLoader.pm sub bootstrap 680
140 vars.pm sub BEGIN 3313
141 DynaLoader.pm sub BEGIN 4401
142 Kstat.pm sub BEGIN 7124
143 nicstat sub BEGIN 10916
144 nicstat sub fetch_net_data 42018
145 nicstat sub find_nets 52094
147 The output showed that the most CPU time was spent in the subroutine
148 find_nets(), with a total exclusive on-CPU time of 52.1 ms. This also matches
149 the total inclusive time, suggesting that find_nets() didn't call other