1 The following are examples of pl_cputime.d. 2 3 This script traces the on-CPU time of Perl subroutines (functions) and 4 prints 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 30 In total, 3 subroutines were called, one each of func_a(), func_b() and 31 func_c(). 32 33 The exclusive subroutine on-CPU times show that func_a() spent around 264.2 ms 34 on-CPU, func_b() spent 538.5 ms, and func_c() spent 799.0 ms. This exclusive 35 times excludes time spent in other subroutines. 36 37 The inclusive subroutine on-CPU times show that func_c() spent around 799.0 ms 38 on-CPU, func_b() spent around 1.3 seconds, and func_a() spent around 1.6 39 seconds. This inclusive time includes the time spent in other subroutines 40 called, and since func_a() called func_b() which called func_c(), these 41 times make perfect sense. 42 43 These on-CPU times are the time the thread spent running on a CPU, from when 44 the subroutine began to when it completed. This does not include time 45 spent off-CPU time such as sleeping for I/O or waiting for scheduling. 46 47 On-CPU times are useful for showing who is causing the CPUs to be busy. 48 See Notes/ALLoncpu_notes.txt for more details. Also see 49 Notes/ALLexclusive_notes.txt and Notes/ALLinclusive_notes.txt for a 50 detailed explanation of exclusive vs inclusive subroutine time. 51 52 If you study the func_slow.pl program alongside the above output, the numbers 53 should make sense. 54 55 56 57 The following traces a Perl network interface statistics tool, "nicstat" 58 version 0.99, 59 60 # pl_cputime.pl 61 Tracing... Hit Ctrl-C to end. 62 ^C 63 64 Count, 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 92 Exclusive 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 120 Inclusive 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 147 The output showed that the most CPU time was spent in the subroutine 148 find_nets(), with a total exclusive on-CPU time of 52.1 ms. This also matches 149 the total inclusive time, suggesting that find_nets() didn't call other 150 subroutines. 151 152
Indexes created Wed Apr 22 00:22:44 UTC 2026