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
|
The following are examples of pl_flowinfo.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_flowinfo.d
C PID DELTA(us) FILE:LINE TYPE -- SUB
0 305127 2 func_abc.pl:15 sub -> func_a
0 305127 1008776 func_abc.pl:9 sub -> func_b
0 305127 1010019 func_abc.pl:4 sub -> func_c
0 305127 1009979 func_abc.pl:4 sub <- func_c
0 305127 26 func_abc.pl:9 sub <- func_b
0 305127 9 func_abc.pl:15 sub <- 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 abovebegins 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 1008776 us, or 1.01 seconds".
The LINE column shows the line in the file what was being executed. Refer
to the source program to see what this line refers to.
If the output looks shuffled, check the CPU "C" column - if it changes,
then the output is probably shuffled. See Notes/ALLsnoop_notes.txt for
details and suggested workarounds.
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_flowinfo.d
C PID DELTA(us) FILE:LINE TYPE -- SUB
0 305132 2 nicstat:83 sub -> BEGIN
0 305132 444 strict.pm:12 sub -> bits
0 305132 34 strict.pm:12 sub <- bits
0 305132 32 strict.pm:28 sub -> import
0 305132 22 strict.pm:28 sub <- import
0 305132 8 nicstat:83 sub <- BEGIN
0 305132 26 nicstat:84 sub -> BEGIN
0 305132 2339 Exporter.pm:30 sub -> import
0 305132 83 Exporter.pm:30 sub <- import
0 305132 14 nicstat:84 sub <- BEGIN
0 305132 27 nicstat:85 sub -> BEGIN
0 305132 205 Kstat.pm:34 sub -> BEGIN
0 305132 11 strict.pm:28 sub -> import
0 305132 11 strict.pm:28 sub <- import
0 305132 8 Kstat.pm:34 sub <- BEGIN
0 305132 23 Kstat.pm:35 sub -> BEGIN
0 305132 187 DynaLoader.pm:18 sub -> BEGIN
0 305132 73 vars.pm:3 sub -> BEGIN
0 305132 9 vars.pm:3 sub <- BEGIN
0 305132 34 vars.pm:7 sub -> BEGIN
0 305132 470 warnings.pm:134 sub -> BEGIN
0 305132 598 warnings.pm:134 sub <- BEGIN
0 305132 2151 register.pm:37 sub -> import
0 305132 23 register.pm:28 sub -> mkMask
0 305132 13 register.pm:28 sub <- mkMask
0 305132 53 register.pm:28 sub -> mkMask
0 305132 11 register.pm:28 sub <- mkMask
0 305132 11 register.pm:37 sub <- import
0 305132 8 vars.pm:7 sub <- BEGIN
0 305132 28 vars.pm:8 sub -> BEGIN
0 305132 9 strict.pm:28 sub -> import
0 305132 8 strict.pm:12 sub -> bits
0 305132 13 strict.pm:12 sub <- bits
0 305132 9 strict.pm:28 sub <- import
0 305132 8 vars.pm:8 sub <- BEGIN
0 305132 294 vars.pm:11 sub -> import
0 305132 52 vars.pm:11 sub <- import
0 305132 8 DynaLoader.pm:18 sub <- BEGIN
0 305132 48 DynaLoader.pm:25 sub -> BEGIN
0 305132 97 Config.pm:5 sub -> BEGIN
0 305132 9 strict.pm:28 sub -> import
0 305132 9 strict.pm:28 sub <- import
0 305132 8 Config.pm:5 sub <- BEGIN
0 305132 134 Config.pm:31 sub -> BEGIN
0 305132 9 strict.pm:33 sub -> unimport
0 305132 8 strict.pm:12 sub -> bits
0 305132 11 strict.pm:12 sub <- bits
0 305132 16 strict.pm:33 sub <- unimport
0 305132 8 Config.pm:31 sub <- BEGIN
0 305132 343 Config.pm:60 sub -> TIEHASH
0 305132 10 Config.pm:60 sub <- TIEHASH
0 305132 44 Config.pm:25 sub -> import
0 305132 18 Config.pm:25 sub <- import
0 305132 9 DynaLoader.pm:25 sub <- BEGIN
0 305132 1301 AutoLoader.pm:3 sub -> BEGIN
0 305132 11 strict.pm:28 sub -> import
0 305132 10 strict.pm:28 sub <- import
0 305132 9 AutoLoader.pm:3 sub <- BEGIN
0 305132 22 AutoLoader.pm:4 sub -> BEGIN
0 305132 9 AutoLoader.pm:4 sub <- BEGIN
0 305132 89 AutoLoader.pm:14 sub -> BEGIN
0 305132 13 AutoLoader.pm:14 sub <- BEGIN
0 305132 375 AutoLoader.pm:95 sub -> BEGIN
0 305132 9 strict.pm:33 sub -> unimport
0 305132 8 strict.pm:12 sub -> bits
0 305132 11 strict.pm:12 sub <- bits
0 305132 9 strict.pm:33 sub <- unimport
0 305132 8 AutoLoader.pm:95 sub <- BEGIN
0 305132 203 AutoLoader.pm:128 sub -> BEGIN
0 305132 9 strict.pm:33 sub -> unimport
0 305132 8 strict.pm:12 sub -> bits
0 305132 11 strict.pm:12 sub <- bits
0 305132 9 strict.pm:33 sub <- unimport
0 305132 8 AutoLoader.pm:128 sub <- BEGIN
0 305132 220 AutoLoader.pm:173 sub -> BEGIN
0 305132 9 strict.pm:33 sub -> unimport
0 305132 8 strict.pm:12 sub -> bits
0 305132 10 strict.pm:12 sub <- bits
0 305132 9 strict.pm:33 sub <- unimport
0 305132 8 AutoLoader.pm:173 sub <- BEGIN
0 305132 103 Config.pm:52 sub -> FETCH
0 305132 12 Config.pm:52 sub <- FETCH
0 305132 16 Config.pm:52 sub -> FETCH
0 305132 9 Config.pm:52 sub <- FETCH
0 305132 11 Config.pm:52 sub -> FETCH
0 305132 9 Config.pm:52 sub <- FETCH
0 305132 11 Config.pm:52 sub -> FETCH
0 305132 9 Config.pm:52 sub <- FETCH
0 305132 95 Kstat.pm:35 sub <- BEGIN
0 305132 29 Kstat.pm:36 sub -> BEGIN
0 305132 10 vars.pm:11 sub -> import
0 305132 33 vars.pm:11 sub <- import
0 305132 8 Kstat.pm:36 sub <- BEGIN
0 305132 56 DynaLoader.pm:133 sub -> bootstrap
0 305132 314 DynaLoader.pm:48 sub -> dl_load_flags
0 305132 11 DynaLoader.pm:48 sub <- dl_load_flags
0 305132 1113 DynaLoader.pm:133 sub <- bootstrap
0 305132 41 nicstat:85 sub <- BEGIN
0 305132 6102 Std.pm:219 sub -> getopts
0 305132 52 Exporter.pm:30 sub -> import
0 305132 40 Exporter.pm:30 sub <- import
0 305132 22 Std.pm:219 sub <- getopts
0 305132 24 nicstat:264 sub -> find_nets
0 305132 79662 nicstat:264 sub <- find_nets
0 305132 420 nicstat:304 sub -> fetch_net_data
0 305132 43871 nicstat:304 sub <- fetch_net_data
0 305132 479 nicstat:372 sub -> print_neat
0 305132 150 nicstat:372 sub <- print_neat
0 305132 10 nicstat:372 sub -> print_neat
0 305132 220 nicstat:372 sub <- print_neat
0 305132 10 nicstat:372 sub -> print_neat
0 305132 126 nicstat:372 sub <- print_neat
0 305132 10 nicstat:372 sub -> print_neat
0 305132 125 nicstat:372 sub <- print_neat
0 305132 10 nicstat:372 sub -> print_neat
0 305132 157 nicstat:372 sub <- print_neat
0 305132 10 nicstat:372 sub -> print_neat
0 305132 171 nicstat:372 sub <- print_neat
0 305132 343 nicstat:372 sub -> print_neat
0 305132 128 nicstat:372 sub <- print_neat
0 305132 10 nicstat:372 sub -> print_neat
0 305132 157 nicstat:372 sub <- print_neat
0 305132 9 nicstat:372 sub -> print_neat
0 305132 125 nicstat:372 sub <- print_neat
0 305132 9 nicstat:372 sub -> print_neat
0 305132 123 nicstat:372 sub <- print_neat
0 305132 9 nicstat:372 sub -> print_neat
0 305132 160 nicstat:372 sub <- print_neat
0 305132 10 nicstat:372 sub -> print_neat
0 305132 124 nicstat:372 sub <- print_neat
0 305132 342 nicstat:372 sub -> print_neat
0 305132 126 nicstat:372 sub <- print_neat
0 305132 10 nicstat:372 sub -> print_neat
0 305132 123 nicstat:372 sub <- print_neat
0 305132 10 nicstat:372 sub -> print_neat
0 305132 156 nicstat:372 sub <- print_neat
0 305132 10 nicstat:372 sub -> print_neat
0 305132 153 nicstat:372 sub <- print_neat
0 305132 10 nicstat:372 sub -> print_neat
0 305132 123 nicstat:372 sub <- print_neat
0 305132 9 nicstat:372 sub -> print_neat
0 305132 123 nicstat:372 sub <- print_neat
0 305132 3736 Config.pm:63 sub -> DESTROY
0 305132 32 Config.pm:63 sub <- DESTROY
After initialising Perl libraries and modules, the "nicstat" program ran,
the output matching what was expected from the source.
|
