mirror of
https://github.com/Stichting-MINIX-Research-Foundation/netbsd.git
synced 2025-09-10 23:56:52 -04:00
151 lines
8.7 KiB
Plaintext
151 lines
8.7 KiB
Plaintext
The following are examples of pl_calltime.d.
|
|
|
|
This script traces the elapsed time of Perl subroutines (functions) and
|
|
prints a report. Here it traces the example program, Code/Perl/func_abc.pl.
|
|
|
|
# pl_calltime.d
|
|
Tracing... Hit Ctrl-C to end.
|
|
^C
|
|
|
|
Count,
|
|
FILE TYPE NAME COUNT
|
|
func_abc.pl sub func_a 1
|
|
func_abc.pl sub func_b 1
|
|
func_abc.pl sub func_c 1
|
|
- total - 3
|
|
|
|
Exclusive subroutine elapsed times (us),
|
|
FILE TYPE NAME TOTAL
|
|
func_abc.pl sub func_a 1006119
|
|
func_abc.pl sub func_c 1009978
|
|
func_abc.pl sub func_b 1010273
|
|
- total - 3026371
|
|
|
|
Inclusive subroutine elapsed times (us),
|
|
FILE TYPE NAME TOTAL
|
|
func_abc.pl sub func_c 1009978
|
|
func_abc.pl sub func_b 2020252
|
|
func_abc.pl sub func_a 3026371
|
|
|
|
In total, 3 subroutines were called, one of each.
|
|
|
|
The exclusive subroutine elapsed times show that each subroutine spent around
|
|
1.0 seconds of time (~1000000 us) processing code - while not in other
|
|
subroutines.
|
|
|
|
The inclusive subroutine elapsed times show that func_a() took around 3.0
|
|
seconds to execute, followed by func_b() at 2.0 seconds, and func_c() at 1.0.
|
|
The 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 elapsed times are the absolute time from when the subroutine began to
|
|
when it completed - which includes off-CPU time due to other system events
|
|
such as I/O, scheduling, interrupts, etc.
|
|
|
|
Elapsed times are useful for identifying where latencies are.
|
|
See Notes/ALLelapsed_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_abc.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_calltime.d
|
|
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 elapsed times (us),
|
|
FILE TYPE NAME TOTAL
|
|
DynaLoader.pm sub dl_load_flags 2
|
|
Config.pm sub TIEHASH 3
|
|
Config.pm sub DESTROY 9
|
|
register.pm sub mkMask 11
|
|
Config.pm sub import 12
|
|
Config.pm sub FETCH 17
|
|
strict.pm sub import 38
|
|
Config.pm sub BEGIN 38
|
|
strict.pm sub bits 49
|
|
vars.pm sub import 59
|
|
strict.pm sub unimport 65
|
|
AutoLoader.pm sub BEGIN 70
|
|
Std.pm sub getopts 78
|
|
register.pm sub import 86
|
|
Exporter.pm sub import 112
|
|
warnings.pm sub BEGIN 680
|
|
DynaLoader.pm sub BEGIN 1131
|
|
DynaLoader.pm sub bootstrap 1221
|
|
nicstat sub print_neat 2450
|
|
vars.pm sub BEGIN 2608
|
|
Kstat.pm sub BEGIN 3171
|
|
nicstat sub BEGIN 3963
|
|
nicstat sub fetch_net_data 45424
|
|
nicstat sub find_nets 55737
|
|
- total - 117047
|
|
|
|
Inclusive subroutine elapsed times (us),
|
|
FILE TYPE NAME TOTAL
|
|
DynaLoader.pm sub dl_load_flags 2
|
|
Config.pm sub TIEHASH 3
|
|
Config.pm sub DESTROY 9
|
|
register.pm sub mkMask 11
|
|
Config.pm sub import 12
|
|
Config.pm sub FETCH 17
|
|
strict.pm sub import 46
|
|
strict.pm sub bits 49
|
|
vars.pm sub import 59
|
|
Config.pm sub BEGIN 64
|
|
strict.pm sub unimport 87
|
|
register.pm sub import 97
|
|
Std.pm sub getopts 112
|
|
Exporter.pm sub import 112
|
|
AutoLoader.pm sub BEGIN 140
|
|
warnings.pm sub BEGIN 680
|
|
DynaLoader.pm sub bootstrap 1224
|
|
nicstat sub print_neat 2450
|
|
vars.pm sub BEGIN 3412
|
|
DynaLoader.pm sub BEGIN 4656
|
|
Kstat.pm sub BEGIN 8020
|
|
nicstat sub BEGIN 13313
|
|
nicstat sub fetch_net_data 45424
|
|
nicstat sub find_nets 55737
|
|
|
|
The output showed that the most time was spent in the subroutine find_nets(),
|
|
with a total exclusive elapsed time of 55.7 ms. This also matches the
|
|
total inclusive time, suggesting that find_nets() didn't call other
|
|
subroutines.
|
|
|