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.