diff options
Diffstat (limited to 'Examples/pl_calltime_example.txt')
| -rw-r--r-- | Examples/pl_calltime_example.txt | 150 |
1 files changed, 150 insertions, 0 deletions
diff --git a/Examples/pl_calltime_example.txt b/Examples/pl_calltime_example.txt new file mode 100644 index 000000000000..3cc5480fdc2d --- /dev/null +++ b/Examples/pl_calltime_example.txt @@ -0,0 +1,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. + |