1 The following are examples of pl_flowtime.d.
3 This is a simple script to trace the flow of Perl subroutines (functions).
4 Here it traces the example program, Code/Perl/func_abc.pl.
7 C TIME(us) FILE DELTA(us) -- SUB
8 0 4201460363351 func_abc.pl 2 -> func_a
9 0 4201461370041 func_abc.pl 1006689 -> func_b
10 0 4201462380038 func_abc.pl 1009997 -> func_c
11 0 4201463390094 func_abc.pl 1010055 <- func_c
12 0 4201463390117 func_abc.pl 23 <- func_b
13 0 4201463390126 func_abc.pl 8 <- func_a
16 As each subroutine is entered, the third column is indented by 2 spaces. This
17 shows which subroutine is calling who - the output above begins by showing that
18 func_a() began, and then called func_b().
20 The DELTA(us) column shows time from that line to the previous line, and
21 so can be a bit tricky to read. For example, the second line of data output
22 (skipping the header) reads as "the time from func_a() beginning to
23 func_b() beginning was 1006689 us, or 1.01 seconds".
25 If the output looks shuffled, check the CPU "C" and "TIME" columns, and
26 post sort based on TIME if necessary.
28 See Notes/ALLflow_notes.txt for important notes about reading flow outputs.
32 The following traces a Perl network interface statistics tool, "nicstat"
36 C TIME(us) FILE DELTA(us) -- SUB
37 0 4201691465151 nicstat 2 -> BEGIN
38 0 4201691465593 strict.pm 441 -> bits
39 0 4201691465625 strict.pm 32 <- bits
40 0 4201691465655 strict.pm 29 -> import
41 0 4201691465676 strict.pm 21 <- import
42 0 4201691465684 nicstat 7 <- BEGIN
43 0 4201691465710 nicstat 25 -> BEGIN
44 0 4201691468038 Exporter.pm 2328 -> import
45 0 4201691468121 Exporter.pm 82 <- import
46 0 4201691468133 nicstat 12 <- BEGIN
47 0 4201691468160 nicstat 26 -> BEGIN
48 0 4201691468367 Kstat.pm 207 -> BEGIN
49 0 4201691468378 strict.pm 10 -> import
50 0 4201691468388 strict.pm 10 <- import
51 0 4201691468396 Kstat.pm 8 <- BEGIN
52 0 4201691468419 Kstat.pm 23 -> BEGIN
53 0 4201691468612 DynaLoader.pm 192 -> BEGIN
54 0 4201691468685 vars.pm 73 -> BEGIN
55 0 4201691468694 vars.pm 8 <- BEGIN
56 0 4201691468727 vars.pm 33 -> BEGIN
57 0 4201691469199 warnings.pm 471 -> BEGIN
58 0 4201691469863 warnings.pm 663 <- BEGIN
59 0 4201691471965 register.pm 2102 -> import
60 0 4201691471986 register.pm 21 -> mkMask
61 0 4201691472000 register.pm 13 <- mkMask
62 0 4201691472052 register.pm 52 -> mkMask
63 0 4201691472063 register.pm 10 <- mkMask
64 0 4201691472074 register.pm 10 <- import
65 0 4201691472081 vars.pm 7 <- BEGIN
66 0 4201691472109 vars.pm 28 -> BEGIN
67 0 4201691472118 strict.pm 8 -> import
68 0 4201691472126 strict.pm 8 -> bits
69 0 4201691472139 strict.pm 12 <- bits
70 0 4201691472148 strict.pm 9 <- import
71 0 4201691472155 vars.pm 7 <- BEGIN
72 0 4201691472450 vars.pm 294 -> import
73 0 4201691472501 vars.pm 51 <- import
74 0 4201691472509 DynaLoader.pm 7 <- BEGIN
75 0 4201691472557 DynaLoader.pm 48 -> BEGIN
76 0 4201691472650 Config.pm 92 -> BEGIN
77 0 4201691472658 strict.pm 8 -> import
78 0 4201691472667 strict.pm 8 <- import
79 0 4201691472675 Config.pm 7 <- BEGIN
80 0 4201691472809 Config.pm 133 -> BEGIN
81 0 4201691472817 strict.pm 8 -> unimport
82 0 4201691472825 strict.pm 8 -> bits
83 0 4201691472852 strict.pm 26 <- bits
84 0 4201691472868 strict.pm 16 <- unimport
85 0 4201691472876 Config.pm 7 <- BEGIN
86 0 4201691473222 Config.pm 345 -> TIEHASH
87 0 4201691473231 Config.pm 9 <- TIEHASH
88 0 4201691473275 Config.pm 43 -> import
89 0 4201691473292 Config.pm 17 <- import
90 0 4201691473301 DynaLoader.pm 8 <- BEGIN
91 0 4201691474650 AutoLoader.pm 1349 -> BEGIN
92 0 4201691474661 strict.pm 10 -> import
93 0 4201691474670 strict.pm 9 <- import
94 0 4201691474679 AutoLoader.pm 8 <- BEGIN
95 0 4201691474701 AutoLoader.pm 21 -> BEGIN
96 0 4201691474709 AutoLoader.pm 8 <- BEGIN
97 0 4201691474797 AutoLoader.pm 88 -> BEGIN
98 0 4201691474810 AutoLoader.pm 12 <- BEGIN
99 0 4201691475186 AutoLoader.pm 376 -> BEGIN
100 0 4201691475195 strict.pm 9 -> unimport
101 0 4201691475203 strict.pm 7 -> bits
102 0 4201691475214 strict.pm 10 <- bits
103 0 4201691475223 strict.pm 8 <- unimport
104 0 4201691475230 AutoLoader.pm 7 <- BEGIN
105 0 4201691475435 AutoLoader.pm 204 -> BEGIN
106 0 4201691475444 strict.pm 8 -> unimport
107 0 4201691475451 strict.pm 7 -> bits
108 0 4201691475462 strict.pm 10 <- bits
109 0 4201691475470 strict.pm 8 <- unimport
110 0 4201691475478 AutoLoader.pm 7 <- BEGIN
111 0 4201691475697 AutoLoader.pm 219 -> BEGIN
112 0 4201691475706 strict.pm 8 -> unimport
113 0 4201691475714 strict.pm 7 -> bits
114 0 4201691475724 strict.pm 10 <- bits
115 0 4201691475732 strict.pm 8 <- unimport
116 0 4201691475739 AutoLoader.pm 7 <- BEGIN
117 0 4201691475842 Config.pm 102 -> FETCH
118 0 4201691475854 Config.pm 11 <- FETCH
119 0 4201691475870 Config.pm 15 -> FETCH
120 0 4201691475879 Config.pm 9 <- FETCH
121 0 4201691475890 Config.pm 10 -> FETCH
122 0 4201691475898 Config.pm 8 <- FETCH
123 0 4201691475909 Config.pm 10 -> FETCH
124 0 4201691475917 Config.pm 8 <- FETCH
125 0 4201691476012 Kstat.pm 94 <- BEGIN
126 0 4201691476041 Kstat.pm 29 -> BEGIN
127 0 4201691476051 vars.pm 9 -> import
128 0 4201691476084 vars.pm 32 <- import
129 0 4201691476091 Kstat.pm 7 <- BEGIN
130 0 4201691476147 DynaLoader.pm 56 -> bootstrap
131 0 4201691476373 DynaLoader.pm 225 -> dl_load_flags
132 0 4201691476383 DynaLoader.pm 9 <- dl_load_flags
133 0 4201691476813 DynaLoader.pm 430 <- bootstrap
134 0 4201691476837 nicstat 23 <- BEGIN
135 0 4201691483648 Std.pm 6811 -> getopts
136 0 4201691483697 Exporter.pm 49 -> import
137 0 4201691483737 Exporter.pm 39 <- import
138 0 4201691483756 Std.pm 19 <- getopts
139 0 4201691483780 nicstat 24 -> find_nets
140 0 4201691539198 nicstat 55418 <- find_nets
141 0 4201691539610 nicstat 411 -> fetch_net_data
142 0 4201691583290 nicstat 43679 <- fetch_net_data
143 0 4201691583781 nicstat 491 -> print_neat
144 0 4201691583930 nicstat 149 <- print_neat
145 0 4201691583996 nicstat 65 -> print_neat
146 0 4201691584165 nicstat 169 <- print_neat
147 0 4201691584174 nicstat 9 -> print_neat
148 0 4201691584298 nicstat 124 <- print_neat
149 0 4201691584308 nicstat 9 -> print_neat
150 0 4201691584432 nicstat 124 <- print_neat
151 0 4201691584473 nicstat 41 -> print_neat
152 0 4201691584597 nicstat 123 <- print_neat
153 0 4201691584607 nicstat 9 -> print_neat
154 0 4201691584730 nicstat 123 <- print_neat
155 0 4201691585091 nicstat 361 -> print_neat
156 0 4201691585217 nicstat 125 <- print_neat
157 0 4201691585226 nicstat 9 -> print_neat
158 0 4201691585379 nicstat 152 <- print_neat
159 0 4201691585389 nicstat 9 -> print_neat
160 0 4201691585512 nicstat 123 <- print_neat
161 0 4201691585521 nicstat 9 -> print_neat
162 0 4201691585644 nicstat 123 <- print_neat
163 0 4201691585653 nicstat 9 -> print_neat
164 0 4201691585825 nicstat 171 <- print_neat
165 0 4201691585834 nicstat 9 -> print_neat
166 0 4201691585988 nicstat 154 <- print_neat
167 0 4201691586274 nicstat 285 -> print_neat
168 0 4201691586434 nicstat 160 <- print_neat
169 0 4201691586443 nicstat 9 -> print_neat
170 0 4201691586567 nicstat 123 <- print_neat
171 0 4201691586576 nicstat 9 -> print_neat
172 0 4201691586731 nicstat 154 <- print_neat
173 0 4201691586740 nicstat 8 -> print_neat
174 0 4201691586892 nicstat 151 <- print_neat
175 0 4201691586901 nicstat 9 -> print_neat
176 0 4201691587025 nicstat 123 <- print_neat
177 0 4201691587034 nicstat 9 -> print_neat
178 0 4201691587157 nicstat 123 <- print_neat
179 0 4201691590909 Config.pm 3751 -> DESTROY
180 0 4201691590938 Config.pm 29 <- DESTROY
182 After initialising Perl libraries and modules, the "nicstat" program ran,
183 the output matching what was expected from the source.
185 The DELTA column shows that most time is spent in the find_nets() and
186 fetch_nets_data() subroutines, with 55.4 ms and 44.7 ms of elapsed
187 function time respectively. Those particular times were easy to interpret,
188 since there were no child subroutines called, and the delta spanned
189 the subroutine entry to its return.
191 Some times get trickier to comprehend. The 2nd last line with a DELTA time
192 of 3751 us, means "the time from the print_neat() subroutine completing
193 to the DESTROY() subroutine starting, took 3751 us.". What is happening
194 during this time? It is hard to say based on this output - since it isn't
195 time within a function, rather it is time that Perl spent processing the
196 main program. Since we have the last function called, we may guess where
197 the program was at; or we could enhance this script to trace Perl engine
198 internals as well (and/or syscalls).