1 The following are examples of pl_calldist.d.
3 This script traces the elapsed time of Perl subroutines (functions) and
4 prints a report containing distribution plots per subroutine. Here it
5 traces the example program, Code/Perl/func_abc.pl.
8 Tracing... Hit Ctrl-C to end.
11 Exclusive subroutine elapsed times (us),
12 func_abc.pl, sub, func_a
13 value ------------- Distribution ------------- count
15 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
18 func_abc.pl, sub, func_b
19 value ------------- Distribution ------------- count
21 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
24 func_abc.pl, sub, func_c
25 value ------------- Distribution ------------- count
27 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
31 Inclusive subroutine elapsed times (us),
32 func_abc.pl, sub, func_c
33 value ------------- Distribution ------------- count
35 524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
38 func_abc.pl, sub, func_b
39 value ------------- Distribution ------------- count
41 1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
44 func_abc.pl, sub, func_a
45 value ------------- Distribution ------------- count
47 2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
50 In total, 3 subroutines were called - func_a(), func_b(), and func_c().
52 The exclusive subroutine elapsed times show that each subroutine spent
53 between 524 and 1048 ms. This exclusive time excludes the time spent in
56 The inclusive subroutine elapsed times show that func_c() took between 0.5 and
57 1.0 seconds, func_b() took between 1.0 and 2.1 seconds, and func_a() took
58 between 2.1 and 4.2 seconds to execute. This inclusive time includes the
59 time spent in other subroutines called, and since func_a() called func_b()
60 which called func_c(), these times make sense.
62 These elapsed times are the absolute time from when the subroutine began to
63 when it completed - which includes off-CPU time due to other system events
64 such as I/O, scheduling, interrupts, etc.
66 Elapsed times are useful for identifying where latencies are.
67 See Notes/ALLelapsed_notes.txt for more details. Also see
68 Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
69 detailed explanation of exclusive vs inclusive subroutine time.
73 The following traces a Perl network interface statistics tool, "nicstat"
77 Tracing... Hit Ctrl-C to end.
80 Exclusive subroutine elapsed times (us),
81 DynaLoader.pm, sub, dl_load_flags
82 value ------------- Distribution ------------- count
84 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
87 Config.pm, sub, TIEHASH
88 value ------------- Distribution ------------- count
90 4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
93 Config.pm, sub, DESTROY
94 value ------------- Distribution ------------- count
96 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
99 Config.pm, sub, import
100 value ------------- Distribution ------------- count
102 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
105 register.pm, sub, mkMask
106 value ------------- Distribution ------------- count
108 4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
111 Config.pm, sub, FETCH
112 value ------------- Distribution ------------- count
114 2 |@@@@@@@@@@@@@@@@@@@@ 2
115 4 |@@@@@@@@@@@@@@@@@@@@ 2
118 Config.pm, sub, BEGIN
119 value ------------- Distribution ------------- count
121 8 |@@@@@@@@@@@@@@@@@@@@ 1
122 16 |@@@@@@@@@@@@@@@@@@@@ 1
125 strict.pm, sub, import
126 value ------------- Distribution ------------- count
129 4 |@@@@@@@@@@@@@@@@ 2
135 value ------------- Distribution ------------- count
137 4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4
142 strict.pm, sub, unimport
143 value ------------- Distribution ------------- count
145 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 3
149 AutoLoader.pm, sub, BEGIN
150 value ------------- Distribution ------------- count
154 8 |@@@@@@@@@@@@@@@@@@@@ 3
159 value ------------- Distribution ------------- count
161 64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
164 register.pm, sub, import
165 value ------------- Distribution ------------- count
167 64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
171 value ------------- Distribution ------------- count
173 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
176 Exporter.pm, sub, import
177 value ------------- Distribution ------------- count
179 32 |@@@@@@@@@@@@@@@@@@@@ 1
180 64 |@@@@@@@@@@@@@@@@@@@@ 1
183 DynaLoader.pm, sub, bootstrap
184 value ------------- Distribution ------------- count
186 512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
189 warnings.pm, sub, BEGIN
190 value ------------- Distribution ------------- count
192 512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
195 DynaLoader.pm, sub, BEGIN
196 value ------------- Distribution ------------- count
198 256 |@@@@@@@@@@@@@@@@@@@@ 1
200 1024 |@@@@@@@@@@@@@@@@@@@@ 1
203 nicstat, sub, print_neat
204 value ------------- Distribution ------------- count
206 64 |@@@@@@@@@@@@@@@@@@@@@@ 10
207 128 |@@@@@@@@@@@@@@@@@@ 8
211 value ------------- Distribution ------------- count
223 2048 |@@@@@@@@@@@@@ 1
227 value ------------- Distribution ------------- count
229 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
237 2048 |@@@@@@@@@@@@@ 1
241 value ------------- Distribution ------------- count
246 2048 |@@@@@@@@@@@@@ 1
249 nicstat, sub, fetch_net_data
250 value ------------- Distribution ------------- count
252 32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
255 nicstat, sub, find_nets
256 value ------------- Distribution ------------- count
258 32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
262 Inclusive subroutine elapsed times (us),
263 DynaLoader.pm, sub, dl_load_flags
264 value ------------- Distribution ------------- count
266 2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
269 Config.pm, sub, TIEHASH
270 value ------------- Distribution ------------- count
272 4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
275 Config.pm, sub, DESTROY
276 value ------------- Distribution ------------- count
278 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
281 Config.pm, sub, import
282 value ------------- Distribution ------------- count
284 8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
287 register.pm, sub, mkMask
288 value ------------- Distribution ------------- count
290 4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
293 Config.pm, sub, FETCH
294 value ------------- Distribution ------------- count
296 2 |@@@@@@@@@@@@@@@@@@@@ 2
297 4 |@@@@@@@@@@@@@@@@@@@@ 2
301 value ------------- Distribution ------------- count
303 4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4
308 strict.pm, sub, import
309 value ------------- Distribution ------------- count
312 4 |@@@@@@@@@@@@@@@@ 2
314 16 |@@@@@@@@@@@@@@@@ 2
317 Config.pm, sub, BEGIN
318 value ------------- Distribution ------------- count
320 16 |@@@@@@@@@@@@@@@@@@@@ 1
321 32 |@@@@@@@@@@@@@@@@@@@@ 1
325 value ------------- Distribution ------------- count
327 64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
330 register.pm, sub, import
331 value ------------- Distribution ------------- count
333 64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
336 strict.pm, sub, unimport
337 value ------------- Distribution ------------- count
339 16 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4
343 value ------------- Distribution ------------- count
345 32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
348 AutoLoader.pm, sub, BEGIN
349 value ------------- Distribution ------------- count
354 16 |@@@@@@@@@@@@@@@@@@@@ 3
358 Exporter.pm, sub, import
359 value ------------- Distribution ------------- count
361 32 |@@@@@@@@@@@@@@@@@@@@ 1
362 64 |@@@@@@@@@@@@@@@@@@@@ 1
365 DynaLoader.pm, sub, bootstrap
366 value ------------- Distribution ------------- count
368 512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
371 warnings.pm, sub, BEGIN
372 value ------------- Distribution ------------- count
374 512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
377 nicstat, sub, print_neat
378 value ------------- Distribution ------------- count
380 64 |@@@@@@@@@@@@@@@@@@@@@@ 10
381 128 |@@@@@@@@@@@@@@@@@@ 8
385 value ------------- Distribution ------------- count
397 2048 |@@@@@@@@@@@@@ 1
400 DynaLoader.pm, sub, BEGIN
401 value ------------- Distribution ------------- count
403 1024 |@@@@@@@@@@@@@@@@@@@@ 1
404 2048 |@@@@@@@@@@@@@@@@@@@@ 1
408 value ------------- Distribution ------------- count
419 8192 |@@@@@@@@@@@@@ 1
423 value ------------- Distribution ------------- count
427 2048 |@@@@@@@@@@@@@ 1
429 8192 |@@@@@@@@@@@@@ 1
432 nicstat, sub, fetch_net_data
433 value ------------- Distribution ------------- count
435 32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
438 nicstat, sub, find_nets
439 value ------------- Distribution ------------- count
441 32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
444 As an example of interpreting the output: the inclusive elapsed time for
445 the "print_neat" subroutine in "nicstat",
447 nicstat, sub, print_neat
448 value ------------- Distribution ------------- count
450 64 |@@@@@@@@@@@@@@@@@@@@@@ 10
451 128 |@@@@@@@@@@@@@@@@@@ 8
454 shows that "print_neat" was called 18 times, 10 of which took between 64
455 and 127 microseconds, and 8 of which took between 128 and 255 microseconds.