1The following are examples of pl_cputime.d. 2 3This script traces the on-CPU time of Perl subroutines (functions) and 4prints a report. Here it traces the example program, Code/Perl/func_slow.pl. 5 6 # pl_cputime.d 7 Tracing... Hit Ctrl-C to end. 8 ^C 9 10 Count, 11 FILE TYPE NAME COUNT 12 func_slow.pl sub func_a 1 13 func_slow.pl sub func_b 1 14 func_slow.pl sub func_c 1 15 - total - 3 16 17 Exclusive subroutine on-CPU times (us), 18 FILE TYPE NAME TOTAL 19 func_slow.pl sub func_a 264193 20 func_slow.pl sub func_b 538498 21 func_slow.pl sub func_c 798961 22 - total - 1601653 23 24 Inclusive subroutine on-CPU times (us), 25 FILE TYPE NAME TOTAL 26 func_slow.pl sub func_c 798961 27 func_slow.pl sub func_b 1337459 28 func_slow.pl sub func_a 1601653 29 30In total, 3 subroutines were called, one each of func_a(), func_b() and 31func_c(). 32 33The exclusive subroutine on-CPU times show that func_a() spent around 264.2 ms 34on-CPU, func_b() spent 538.5 ms, and func_c() spent 799.0 ms. This exclusive 35times excludes time spent in other subroutines. 36 37The inclusive subroutine on-CPU times show that func_c() spent around 799.0 ms 38on-CPU, func_b() spent around 1.3 seconds, and func_a() spent around 1.6 39seconds. This inclusive time includes the time spent in other subroutines 40called, and since func_a() called func_b() which called func_c(), these 41times make perfect sense. 42 43These on-CPU times are the time the thread spent running on a CPU, from when 44the subroutine began to when it completed. This does not include time 45spent off-CPU time such as sleeping for I/O or waiting for scheduling. 46 47On-CPU times are useful for showing who is causing the CPUs to be busy. 48See Notes/ALLoncpu_notes.txt for more details. Also see 49Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a 50detailed explanation of exclusive vs inclusive subroutine time. 51 52If you study the func_slow.pl program alongside the above output, the numbers 53should make sense. 54 55 56 57The following traces a Perl network interface statistics tool, "nicstat" 58version 0.99, 59 60# pl_cputime.pl 61Tracing... Hit Ctrl-C to end. 62^C 63 64Count, 65 FILE TYPE NAME COUNT 66 Config.pm sub DESTROY 1 67 Config.pm sub TIEHASH 1 68 Config.pm sub import 1 69 DynaLoader.pm sub bootstrap 1 70 DynaLoader.pm sub dl_load_flags 1 71 Std.pm sub getopts 1 72 nicstat sub fetch_net_data 1 73 nicstat sub find_nets 1 74 register.pm sub import 1 75 warnings.pm sub BEGIN 1 76 Config.pm sub BEGIN 2 77 DynaLoader.pm sub BEGIN 2 78 Exporter.pm sub import 2 79 register.pm sub mkMask 2 80 vars.pm sub import 2 81 Kstat.pm sub BEGIN 3 82 nicstat sub BEGIN 3 83 vars.pm sub BEGIN 3 84 Config.pm sub FETCH 4 85 strict.pm sub unimport 4 86 strict.pm sub import 5 87 AutoLoader.pm sub BEGIN 6 88 strict.pm sub bits 6 89 nicstat sub print_neat 18 90 - total - 72 91 92Exclusive subroutine on-CPU times (us), 93 FILE TYPE NAME TOTAL 94 DynaLoader.pm sub dl_load_flags 2 95 Config.pm sub TIEHASH 2 96 Config.pm sub DESTROY 6 97 Config.pm sub BEGIN 7 98 register.pm sub mkMask 8 99 Config.pm sub import 11 100 Config.pm sub FETCH 12 101 strict.pm sub unimport 17 102 strict.pm sub import 21 103 AutoLoader.pm sub BEGIN 22 104 Std.pm sub getopts 33 105 strict.pm sub bits 40 106 register.pm sub import 51 107 vars.pm sub import 65 108 Exporter.pm sub import 88 109 nicstat sub print_neat 426 110 warnings.pm sub BEGIN 598 111 DynaLoader.pm sub bootstrap 677 112 DynaLoader.pm sub BEGIN 1015 113 Kstat.pm sub BEGIN 2627 114 vars.pm sub BEGIN 2642 115 nicstat sub BEGIN 3033 116 nicstat sub fetch_net_data 42018 117 nicstat sub find_nets 52094 118 - total - 105526 119 120Inclusive subroutine on-CPU times (us), 121 FILE TYPE NAME TOTAL 122 DynaLoader.pm sub dl_load_flags 2 123 Config.pm sub TIEHASH 2 124 Config.pm sub DESTROY 6 125 register.pm sub mkMask 8 126 Config.pm sub import 11 127 Config.pm sub FETCH 12 128 Config.pm sub BEGIN 19 129 strict.pm sub import 28 130 strict.pm sub unimport 35 131 strict.pm sub bits 40 132 AutoLoader.pm sub BEGIN 51 133 register.pm sub import 59 134 Std.pm sub getopts 63 135 vars.pm sub import 65 136 Exporter.pm sub import 88 137 nicstat sub print_neat 426 138 warnings.pm sub BEGIN 598 139 DynaLoader.pm sub bootstrap 680 140 vars.pm sub BEGIN 3313 141 DynaLoader.pm sub BEGIN 4401 142 Kstat.pm sub BEGIN 7124 143 nicstat sub BEGIN 10916 144 nicstat sub fetch_net_data 42018 145 nicstat sub find_nets 52094 146 147The output showed that the most CPU time was spent in the subroutine 148find_nets(), with a total exclusive on-CPU time of 52.1 ms. This also matches 149the total inclusive time, suggesting that find_nets() didn't call other 150subroutines. 151 152