152 lines
8.9 KiB
Plaintext
152 lines
8.9 KiB
Plaintext
|
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.
|
||
|
|
|