xref: /netbsd-src/external/cddl/dtracetoolkit/dist/Docs/Examples/pl_calldist_example.txt (revision c29d51755812ace2e87aeefdb06cb2b4dac7087a)
1The following are examples of pl_calldist.d.
2
3This script traces the elapsed time of Perl subroutines (functions) and
4prints a report containing distribution plots per subroutine. Here it
5traces the example program, Code/Perl/func_abc.pl.
6
7   # pl_calldist.d
8   Tracing... Hit Ctrl-C to end.
9   ^C
10
11   Exclusive subroutine elapsed times (us),
12      func_abc.pl, sub, func_a
13              value  ------------- Distribution ------------- count
14             262144 |                                         0
15             524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
16            1048576 |                                         0
17
18      func_abc.pl, sub, func_b
19              value  ------------- Distribution ------------- count
20             262144 |                                         0
21             524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
22            1048576 |                                         0
23
24      func_abc.pl, sub, func_c
25              value  ------------- Distribution ------------- count
26             262144 |                                         0
27             524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
28            1048576 |                                         0
29
30
31   Inclusive subroutine elapsed times (us),
32      func_abc.pl, sub, func_c
33              value  ------------- Distribution ------------- count
34             262144 |                                         0
35             524288 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
36            1048576 |                                         0
37
38      func_abc.pl, sub, func_b
39              value  ------------- Distribution ------------- count
40             524288 |                                         0
41            1048576 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
42            2097152 |                                         0
43
44      func_abc.pl, sub, func_a
45              value  ------------- Distribution ------------- count
46            1048576 |                                         0
47            2097152 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
48            4194304 |                                         0
49
50In total, 3 subroutines were called - func_a(), func_b(), and func_c().
51
52The exclusive subroutine elapsed times show that each subroutine spent
53between 524 and 1048 ms. This exclusive time excludes the time spent in
54other subroutines.
55
56The inclusive subroutine elapsed times show that func_c() took between 0.5 and
571.0 seconds, func_b() took between 1.0 and 2.1 seconds, and func_a() took
58between 2.1 and 4.2 seconds to execute. This inclusive time includes the
59time spent in other subroutines called, and since func_a() called func_b()
60which called func_c(), these times make sense.
61
62These elapsed times are the absolute time from when the subroutine began to
63when it completed - which includes off-CPU time due to other system events
64such as I/O, scheduling, interrupts, etc.
65
66Elapsed times are useful for identifying where latencies are.
67See Notes/ALLelapsed_notes.txt for more details. Also see
68Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
69detailed explanation of exclusive vs inclusive subroutine time.
70
71
72
73The following traces a Perl network interface statistics tool, "nicstat"
74version 0.99,
75
76# pl_calldist.d
77Tracing... Hit Ctrl-C to end.
78^C
79
80Exclusive subroutine elapsed times (us),
81   DynaLoader.pm, sub, dl_load_flags
82           value  ------------- Distribution ------------- count
83               1 |                                         0
84               2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
85               4 |                                         0
86
87   Config.pm, sub, TIEHASH
88           value  ------------- Distribution ------------- count
89               2 |                                         0
90               4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
91               8 |                                         0
92
93   Config.pm, sub, DESTROY
94           value  ------------- Distribution ------------- count
95               4 |                                         0
96               8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
97              16 |                                         0
98
99   Config.pm, sub, import
100           value  ------------- Distribution ------------- count
101               4 |                                         0
102               8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
103              16 |                                         0
104
105   register.pm, sub, mkMask
106           value  ------------- Distribution ------------- count
107               2 |                                         0
108               4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
109               8 |                                         0
110
111   Config.pm, sub, FETCH
112           value  ------------- Distribution ------------- count
113               1 |                                         0
114               2 |@@@@@@@@@@@@@@@@@@@@                     2
115               4 |@@@@@@@@@@@@@@@@@@@@                     2
116               8 |                                         0
117
118   Config.pm, sub, BEGIN
119           value  ------------- Distribution ------------- count
120               4 |                                         0
121               8 |@@@@@@@@@@@@@@@@@@@@                     1
122              16 |@@@@@@@@@@@@@@@@@@@@                     1
123              32 |                                         0
124
125   strict.pm, sub, import
126           value  ------------- Distribution ------------- count
127               1 |                                         0
128               2 |@@@@@@@@                                 1
129               4 |@@@@@@@@@@@@@@@@                         2
130               8 |@@@@@@@@                                 1
131              16 |@@@@@@@@                                 1
132              32 |                                         0
133
134   strict.pm, sub, bits
135           value  ------------- Distribution ------------- count
136               2 |                                         0
137               4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              4
138               8 |@@@@@@@                                  1
139              16 |@@@@@@@                                  1
140              32 |                                         0
141
142   strict.pm, sub, unimport
143           value  ------------- Distribution ------------- count
144               4 |                                         0
145               8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@           3
146              16 |@@@@@@@@@@                               1
147              32 |                                         0
148
149   AutoLoader.pm, sub, BEGIN
150           value  ------------- Distribution ------------- count
151               1 |                                         0
152               2 |@@@@@@@                                  1
153               4 |@@@@@@@                                  1
154               8 |@@@@@@@@@@@@@@@@@@@@                     3
155              16 |@@@@@@@                                  1
156              32 |                                         0
157
158   Std.pm, sub, getopts
159           value  ------------- Distribution ------------- count
160              32 |                                         0
161              64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
162             128 |                                         0
163
164   register.pm, sub, import
165           value  ------------- Distribution ------------- count
166              32 |                                         0
167              64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
168             128 |                                         0
169
170   vars.pm, sub, import
171           value  ------------- Distribution ------------- count
172              16 |                                         0
173              32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
174              64 |                                         0
175
176   Exporter.pm, sub, import
177           value  ------------- Distribution ------------- count
178              16 |                                         0
179              32 |@@@@@@@@@@@@@@@@@@@@                     1
180              64 |@@@@@@@@@@@@@@@@@@@@                     1
181             128 |                                         0
182
183   DynaLoader.pm, sub, bootstrap
184           value  ------------- Distribution ------------- count
185             256 |                                         0
186             512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
187            1024 |                                         0
188
189   warnings.pm, sub, BEGIN
190           value  ------------- Distribution ------------- count
191             256 |                                         0
192             512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
193            1024 |                                         0
194
195   DynaLoader.pm, sub, BEGIN
196           value  ------------- Distribution ------------- count
197             128 |                                         0
198             256 |@@@@@@@@@@@@@@@@@@@@                     1
199             512 |                                         0
200            1024 |@@@@@@@@@@@@@@@@@@@@                     1
201            2048 |                                         0
202
203   nicstat, sub, print_neat
204           value  ------------- Distribution ------------- count
205              32 |                                         0
206              64 |@@@@@@@@@@@@@@@@@@@@@@                   10
207             128 |@@@@@@@@@@@@@@@@@@                       8
208             256 |                                         0
209
210   vars.pm, sub, BEGIN
211           value  ------------- Distribution ------------- count
212               1 |                                         0
213               2 |@@@@@@@@@@@@@                            1
214               4 |                                         0
215               8 |@@@@@@@@@@@@@                            1
216              16 |                                         0
217              32 |                                         0
218              64 |                                         0
219             128 |                                         0
220             256 |                                         0
221             512 |                                         0
222            1024 |                                         0
223            2048 |@@@@@@@@@@@@@                            1
224            4096 |                                         0
225
226   Kstat.pm, sub, BEGIN
227           value  ------------- Distribution ------------- count
228               4 |                                         0
229               8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              2
230              16 |                                         0
231              32 |                                         0
232              64 |                                         0
233             128 |                                         0
234             256 |                                         0
235             512 |                                         0
236            1024 |                                         0
237            2048 |@@@@@@@@@@@@@                            1
238            4096 |                                         0
239
240   nicstat, sub, BEGIN
241           value  ------------- Distribution ------------- count
242             128 |                                         0
243             256 |@@@@@@@@@@@@@                            1
244             512 |@@@@@@@@@@@@@                            1
245            1024 |                                         0
246            2048 |@@@@@@@@@@@@@                            1
247            4096 |                                         0
248
249   nicstat, sub, fetch_net_data
250           value  ------------- Distribution ------------- count
251           16384 |                                         0
252           32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
253           65536 |                                         0
254
255   nicstat, sub, find_nets
256           value  ------------- Distribution ------------- count
257           16384 |                                         0
258           32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
259           65536 |                                         0
260
261
262Inclusive subroutine elapsed times (us),
263   DynaLoader.pm, sub, dl_load_flags
264           value  ------------- Distribution ------------- count
265               1 |                                         0
266               2 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
267               4 |                                         0
268
269   Config.pm, sub, TIEHASH
270           value  ------------- Distribution ------------- count
271               2 |                                         0
272               4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
273               8 |                                         0
274
275   Config.pm, sub, DESTROY
276           value  ------------- Distribution ------------- count
277               4 |                                         0
278               8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
279              16 |                                         0
280
281   Config.pm, sub, import
282           value  ------------- Distribution ------------- count
283               4 |                                         0
284               8 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
285              16 |                                         0
286
287   register.pm, sub, mkMask
288           value  ------------- Distribution ------------- count
289               2 |                                         0
290               4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
291               8 |                                         0
292
293   Config.pm, sub, FETCH
294           value  ------------- Distribution ------------- count
295               1 |                                         0
296               2 |@@@@@@@@@@@@@@@@@@@@                     2
297               4 |@@@@@@@@@@@@@@@@@@@@                     2
298               8 |                                         0
299
300   strict.pm, sub, bits
301           value  ------------- Distribution ------------- count
302               2 |                                         0
303               4 |@@@@@@@@@@@@@@@@@@@@@@@@@@@              4
304               8 |@@@@@@@                                  1
305              16 |@@@@@@@                                  1
306              32 |                                         0
307
308   strict.pm, sub, import
309           value  ------------- Distribution ------------- count
310               1 |                                         0
311               2 |@@@@@@@@                                 1
312               4 |@@@@@@@@@@@@@@@@                         2
313               8 |                                         0
314              16 |@@@@@@@@@@@@@@@@                         2
315              32 |                                         0
316
317   Config.pm, sub, BEGIN
318           value  ------------- Distribution ------------- count
319               8 |                                         0
320              16 |@@@@@@@@@@@@@@@@@@@@                     1
321              32 |@@@@@@@@@@@@@@@@@@@@                     1
322              64 |                                         0
323
324   Std.pm, sub, getopts
325           value  ------------- Distribution ------------- count
326              32 |                                         0
327              64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
328             128 |                                         0
329
330   register.pm, sub, import
331           value  ------------- Distribution ------------- count
332              32 |                                         0
333              64 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
334             128 |                                         0
335
336   strict.pm, sub, unimport
337           value  ------------- Distribution ------------- count
338               8 |                                         0
339              16 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 4
340              32 |                                         0
341
342   vars.pm, sub, import
343           value  ------------- Distribution ------------- count
344              16 |                                         0
345              32 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 2
346              64 |                                         0
347
348   AutoLoader.pm, sub, BEGIN
349           value  ------------- Distribution ------------- count
350               1 |                                         0
351               2 |@@@@@@@                                  1
352               4 |@@@@@@@                                  1
353               8 |                                         0
354              16 |@@@@@@@@@@@@@@@@@@@@                     3
355              32 |@@@@@@@                                  1
356              64 |                                         0
357
358   Exporter.pm, sub, import
359           value  ------------- Distribution ------------- count
360              16 |                                         0
361              32 |@@@@@@@@@@@@@@@@@@@@                     1
362              64 |@@@@@@@@@@@@@@@@@@@@                     1
363             128 |                                         0
364
365   DynaLoader.pm, sub, bootstrap
366           value  ------------- Distribution ------------- count
367             256 |                                         0
368             512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
369            1024 |                                         0
370
371   warnings.pm, sub, BEGIN
372           value  ------------- Distribution ------------- count
373             256 |                                         0
374             512 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
375            1024 |                                         0
376
377   nicstat, sub, print_neat
378           value  ------------- Distribution ------------- count
379              32 |                                         0
380              64 |@@@@@@@@@@@@@@@@@@@@@@                   10
381             128 |@@@@@@@@@@@@@@@@@@                       8
382             256 |                                         0
383
384   vars.pm, sub, BEGIN
385           value  ------------- Distribution ------------- count
386               1 |                                         0
387               2 |@@@@@@@@@@@@@                            1
388               4 |                                         0
389               8 |                                         0
390              16 |                                         0
391              32 |@@@@@@@@@@@@@                            1
392              64 |                                         0
393             128 |                                         0
394             256 |                                         0
395             512 |                                         0
396            1024 |                                         0
397            2048 |@@@@@@@@@@@@@                            1
398            4096 |                                         0
399
400   DynaLoader.pm, sub, BEGIN
401           value  ------------- Distribution ------------- count
402             512 |                                         0
403            1024 |@@@@@@@@@@@@@@@@@@@@                     1
404            2048 |@@@@@@@@@@@@@@@@@@@@                     1
405            4096 |                                         0
406
407   Kstat.pm, sub, BEGIN
408           value  ------------- Distribution ------------- count
409               8 |                                         0
410              16 |@@@@@@@@@@@@@                            1
411              32 |@@@@@@@@@@@@@                            1
412              64 |                                         0
413             128 |                                         0
414             256 |                                         0
415             512 |                                         0
416            1024 |                                         0
417            2048 |                                         0
418            4096 |                                         0
419            8192 |@@@@@@@@@@@@@                            1
420           16384 |                                         0
421
422   nicstat, sub, BEGIN
423           value  ------------- Distribution ------------- count
424             256 |                                         0
425             512 |@@@@@@@@@@@@@                            1
426            1024 |                                         0
427            2048 |@@@@@@@@@@@@@                            1
428            4096 |                                         0
429            8192 |@@@@@@@@@@@@@                            1
430           16384 |                                         0
431
432   nicstat, sub, fetch_net_data
433           value  ------------- Distribution ------------- count
434           16384 |                                         0
435           32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
436           65536 |                                         0
437
438   nicstat, sub, find_nets
439           value  ------------- Distribution ------------- count
440           16384 |                                         0
441           32768 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@ 1
442           65536 |                                         0
443
444As an example of interpreting the output: the inclusive elapsed time for
445the "print_neat" subroutine in "nicstat",
446
447   nicstat, sub, print_neat
448           value  ------------- Distribution ------------- count
449              32 |                                         0
450              64 |@@@@@@@@@@@@@@@@@@@@@@                   10
451             128 |@@@@@@@@@@@@@@@@@@                       8
452             256 |                                         0
453
454shows that "print_neat" was called 18 times, 10 of which took between 64
455and 127 microseconds, and 8 of which took between 128 and 255 microseconds.
456
457