The following are examples of pl_cputime.d. This script traces the on-CPU time of Perl subroutines (functions) and prints a report. Here it traces the example program, Code/Perl/func_slow.pl. # pl_cputime.d Tracing... Hit Ctrl-C to end. ^C Count, FILE TYPE NAME COUNT func_slow.pl sub func_a 1 func_slow.pl sub func_b 1 func_slow.pl sub func_c 1 - total - 3 Exclusive subroutine on-CPU times (us), FILE TYPE NAME TOTAL func_slow.pl sub func_a 264193 func_slow.pl sub func_b 538498 func_slow.pl sub func_c 798961 - total - 1601653 Inclusive subroutine on-CPU times (us), FILE TYPE NAME TOTAL func_slow.pl sub func_c 798961 func_slow.pl sub func_b 1337459 func_slow.pl sub func_a 1601653 In total, 3 subroutines were called, one each of func_a(), func_b() and func_c(). The exclusive subroutine on-CPU times show that func_a() spent around 264.2 ms on-CPU, func_b() spent 538.5 ms, and func_c() spent 799.0 ms. This exclusive times excludes time spent in other subroutines. The inclusive subroutine on-CPU times show that func_c() spent around 799.0 ms on-CPU, func_b() spent around 1.3 seconds, and func_a() spent around 1.6 seconds. This 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 on-CPU times are the time the thread spent running on a CPU, from when the subroutine began to when it completed. This does not include time spent off-CPU time such as sleeping for I/O or waiting for scheduling. On-CPU times are useful for showing who is causing the CPUs to be busy. See Notes/ALLoncpu_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_slow.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_cputime.pl 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 on-CPU times (us), FILE TYPE NAME TOTAL DynaLoader.pm sub dl_load_flags 2 Config.pm sub TIEHASH 2 Config.pm sub DESTROY 6 Config.pm sub BEGIN 7 register.pm sub mkMask 8 Config.pm sub import 11 Config.pm sub FETCH 12 strict.pm sub unimport 17 strict.pm sub import 21 AutoLoader.pm sub BEGIN 22 Std.pm sub getopts 33 strict.pm sub bits 40 register.pm sub import 51 vars.pm sub import 65 Exporter.pm sub import 88 nicstat sub print_neat 426 warnings.pm sub BEGIN 598 DynaLoader.pm sub bootstrap 677 DynaLoader.pm sub BEGIN 1015 Kstat.pm sub BEGIN 2627 vars.pm sub BEGIN 2642 nicstat sub BEGIN 3033 nicstat sub fetch_net_data 42018 nicstat sub find_nets 52094 - total - 105526 Inclusive subroutine on-CPU times (us), FILE TYPE NAME TOTAL DynaLoader.pm sub dl_load_flags 2 Config.pm sub TIEHASH 2 Config.pm sub DESTROY 6 register.pm sub mkMask 8 Config.pm sub import 11 Config.pm sub FETCH 12 Config.pm sub BEGIN 19 strict.pm sub import 28 strict.pm sub unimport 35 strict.pm sub bits 40 AutoLoader.pm sub BEGIN 51 register.pm sub import 59 Std.pm sub getopts 63 vars.pm sub import 65 Exporter.pm sub import 88 nicstat sub print_neat 426 warnings.pm sub BEGIN 598 DynaLoader.pm sub bootstrap 680 vars.pm sub BEGIN 3313 DynaLoader.pm sub BEGIN 4401 Kstat.pm sub BEGIN 7124 nicstat sub BEGIN 10916 nicstat sub fetch_net_data 42018 nicstat sub find_nets 52094 The output showed that the most CPU time was spent in the subroutine find_nets(), with a total exclusive on-CPU time of 52.1 ms. This also matches the total inclusive time, suggesting that find_nets() didn't call other subroutines.