cddl/contrib/dtracetoolkit/Examples/pl_calltime_example.txt


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

The following are examples of pl_calltime.d.

This script traces the elapsed time of Perl subroutines (functions) and
prints a report. Here it traces the example program, Code/Perl/func_abc.pl.

   # pl_calltime.d
   Tracing... Hit Ctrl-C to end.
   ^C
   
   Count,
      FILE                 TYPE       NAME                                COUNT
      func_abc.pl          sub        func_a                                  1
      func_abc.pl          sub        func_b                                  1
      func_abc.pl          sub        func_c                                  1
      -                    total      -                                       3
   
   Exclusive subroutine elapsed times (us),
      FILE                 TYPE       NAME                                TOTAL
      func_abc.pl          sub        func_a                            1006119
      func_abc.pl          sub        func_c                            1009978
      func_abc.pl          sub        func_b                            1010273
      -                    total      -                                 3026371
   
   Inclusive subroutine elapsed times (us),
      FILE                 TYPE       NAME                                TOTAL
      func_abc.pl          sub        func_c                            1009978
      func_abc.pl          sub        func_b                            2020252
      func_abc.pl          sub        func_a                            3026371

In total, 3 subroutines were called, one of each.

The exclusive subroutine elapsed times show that each subroutine spent around
1.0 seconds of time (~1000000 us) processing code - while not in other
subroutines.

The inclusive subroutine elapsed times show that func_a() took around 3.0
seconds to execute, followed by func_b() at 2.0 seconds, and func_c() at 1.0.
The inclusive time includes the time spent in other subroutines called, and
since func_a() called func_b() which called func_c(), these times make
perfect sense.

These elapsed times are the absolute time from when the subroutine began to
when it completed - which includes off-CPU time due to other system events
such as I/O, scheduling, interrupts, etc.

Elapsed times are useful for identifying where latencies are.
See Notes/ALLelapsed_notes.txt for more details. Also see
Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a
detailed explanation of exclusive vs inclusive subroutine time.

If you study the func_abc.pl program alongside the above output, the numbers
should make sense. 


The following traces a Perl network interface statistics tool, "nicstat"
version 0.99,

# pl_calltime.d
Tracing... Hit Ctrl-C to end.
^C

Count,
   FILE                 TYPE       NAME                                COUNT
   Config.pm            sub        DESTROY                                 1
   Config.pm            sub        TIEHASH                                 1
   Config.pm            sub        import                                  1
   DynaLoader.pm        sub        bootstrap                               1
   DynaLoader.pm        sub        dl_load_flags                           1
   Std.pm               sub        getopts                                 1
   nicstat              sub        fetch_net_data                          1
   nicstat              sub        find_nets                               1
   register.pm          sub        import                                  1
   warnings.pm          sub        BEGIN                                   1
   Config.pm            sub        BEGIN                                   2
   DynaLoader.pm        sub        BEGIN                                   2
   Exporter.pm          sub        import                                  2
   register.pm          sub        mkMask                                  2
   vars.pm              sub        import                                  2
   Kstat.pm             sub        BEGIN                                   3
   nicstat              sub        BEGIN                                   3
   vars.pm              sub        BEGIN                                   3
   Config.pm            sub        FETCH                                   4
   strict.pm            sub        unimport                                4
   strict.pm            sub        import                                  5
   AutoLoader.pm        sub        BEGIN                                   6
   strict.pm            sub        bits                                    6
   nicstat              sub        print_neat                             18
   -                    total      -                                      72

Exclusive subroutine elapsed times (us),
   FILE                 TYPE       NAME                                TOTAL
   DynaLoader.pm        sub        dl_load_flags                           2
   Config.pm            sub        TIEHASH                                 3
   Config.pm            sub        DESTROY                                 9
   register.pm          sub        mkMask                                 11
   Config.pm            sub        import                                 12
   Config.pm            sub        FETCH                                  17
   strict.pm            sub        import                                 38
   Config.pm            sub        BEGIN                                  38
   strict.pm            sub        bits                                   49
   vars.pm              sub        import                                 59
   strict.pm            sub        unimport                               65
   AutoLoader.pm        sub        BEGIN                                  70
   Std.pm               sub        getopts                                78
   register.pm          sub        import                                 86
   Exporter.pm          sub        import                                112
   warnings.pm          sub        BEGIN                                 680
   DynaLoader.pm        sub        BEGIN                                1131
   DynaLoader.pm        sub        bootstrap                            1221
   nicstat              sub        print_neat                           2450
   vars.pm              sub        BEGIN                                2608
   Kstat.pm             sub        BEGIN                                3171
   nicstat              sub        BEGIN                                3963
   nicstat              sub        fetch_net_data                      45424
   nicstat              sub        find_nets                           55737
   -                    total      -                                  117047

Inclusive subroutine elapsed times (us),
   FILE                 TYPE       NAME                                TOTAL
   DynaLoader.pm        sub        dl_load_flags                           2
   Config.pm            sub        TIEHASH                                 3
   Config.pm            sub        DESTROY                                 9
   register.pm          sub        mkMask                                 11
   Config.pm            sub        import                                 12
   Config.pm            sub        FETCH                                  17
   strict.pm            sub        import                                 46
   strict.pm            sub        bits                                   49
   vars.pm              sub        import                                 59
   Config.pm            sub        BEGIN                                  64
   strict.pm            sub        unimport                               87
   register.pm          sub        import                                 97
   Std.pm               sub        getopts                               112
   Exporter.pm          sub        import                                112
   AutoLoader.pm        sub        BEGIN                                 140
   warnings.pm          sub        BEGIN                                 680
   DynaLoader.pm        sub        bootstrap                            1224
   nicstat              sub        print_neat                           2450
   vars.pm              sub        BEGIN                                3412
   DynaLoader.pm        sub        BEGIN                                4656
   Kstat.pm             sub        BEGIN                                8020
   nicstat              sub        BEGIN                               13313
   nicstat              sub        fetch_net_data                      45424
   nicstat              sub        find_nets                           55737

The output showed that the most time was spent in the subroutine find_nets(),
with a total exclusive elapsed time of 55.7 ms. This also matches the
total inclusive time, suggesting that find_nets() didn't call other
subroutines.