1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 | 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.
|