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