mirror of
https://github.com/Stichting-MINIX-Research-Foundation/netbsd.git
synced 2025-09-10 15:46:33 -04:00
200 lines
11 KiB
Plaintext
200 lines
11 KiB
Plaintext
The following are examples of pl_flowtime.d.
|
|
|
|
This is a simple script to trace the flow of Perl subroutines (functions).
|
|
Here it traces the example program, Code/Perl/func_abc.pl.
|
|
|
|
# pl_flowtime.d
|
|
C TIME(us) FILE DELTA(us) -- SUB
|
|
0 4201460363351 func_abc.pl 2 -> func_a
|
|
0 4201461370041 func_abc.pl 1006689 -> func_b
|
|
0 4201462380038 func_abc.pl 1009997 -> func_c
|
|
0 4201463390094 func_abc.pl 1010055 <- func_c
|
|
0 4201463390117 func_abc.pl 23 <- func_b
|
|
0 4201463390126 func_abc.pl 8 <- func_a
|
|
^C
|
|
|
|
As each subroutine is entered, the third column is indented by 2 spaces. This
|
|
shows which subroutine is calling who - the output above begins by showing that
|
|
func_a() began, and then called func_b().
|
|
|
|
The DELTA(us) column shows time from that line to the previous line, and
|
|
so can be a bit tricky to read. For example, the second line of data output
|
|
(skipping the header) reads as "the time from func_a() beginning to
|
|
func_b() beginning was 1006689 us, or 1.01 seconds".
|
|
|
|
If the output looks shuffled, check the CPU "C" and "TIME" columns, and
|
|
post sort based on TIME if necessary.
|
|
|
|
See Notes/ALLflow_notes.txt for important notes about reading flow outputs.
|
|
|
|
|
|
|
|
The following traces a Perl network interface statistics tool, "nicstat"
|
|
version 0.99,
|
|
|
|
# pl_flowtime.d
|
|
C TIME(us) FILE DELTA(us) -- SUB
|
|
0 4201691465151 nicstat 2 -> BEGIN
|
|
0 4201691465593 strict.pm 441 -> bits
|
|
0 4201691465625 strict.pm 32 <- bits
|
|
0 4201691465655 strict.pm 29 -> import
|
|
0 4201691465676 strict.pm 21 <- import
|
|
0 4201691465684 nicstat 7 <- BEGIN
|
|
0 4201691465710 nicstat 25 -> BEGIN
|
|
0 4201691468038 Exporter.pm 2328 -> import
|
|
0 4201691468121 Exporter.pm 82 <- import
|
|
0 4201691468133 nicstat 12 <- BEGIN
|
|
0 4201691468160 nicstat 26 -> BEGIN
|
|
0 4201691468367 Kstat.pm 207 -> BEGIN
|
|
0 4201691468378 strict.pm 10 -> import
|
|
0 4201691468388 strict.pm 10 <- import
|
|
0 4201691468396 Kstat.pm 8 <- BEGIN
|
|
0 4201691468419 Kstat.pm 23 -> BEGIN
|
|
0 4201691468612 DynaLoader.pm 192 -> BEGIN
|
|
0 4201691468685 vars.pm 73 -> BEGIN
|
|
0 4201691468694 vars.pm 8 <- BEGIN
|
|
0 4201691468727 vars.pm 33 -> BEGIN
|
|
0 4201691469199 warnings.pm 471 -> BEGIN
|
|
0 4201691469863 warnings.pm 663 <- BEGIN
|
|
0 4201691471965 register.pm 2102 -> import
|
|
0 4201691471986 register.pm 21 -> mkMask
|
|
0 4201691472000 register.pm 13 <- mkMask
|
|
0 4201691472052 register.pm 52 -> mkMask
|
|
0 4201691472063 register.pm 10 <- mkMask
|
|
0 4201691472074 register.pm 10 <- import
|
|
0 4201691472081 vars.pm 7 <- BEGIN
|
|
0 4201691472109 vars.pm 28 -> BEGIN
|
|
0 4201691472118 strict.pm 8 -> import
|
|
0 4201691472126 strict.pm 8 -> bits
|
|
0 4201691472139 strict.pm 12 <- bits
|
|
0 4201691472148 strict.pm 9 <- import
|
|
0 4201691472155 vars.pm 7 <- BEGIN
|
|
0 4201691472450 vars.pm 294 -> import
|
|
0 4201691472501 vars.pm 51 <- import
|
|
0 4201691472509 DynaLoader.pm 7 <- BEGIN
|
|
0 4201691472557 DynaLoader.pm 48 -> BEGIN
|
|
0 4201691472650 Config.pm 92 -> BEGIN
|
|
0 4201691472658 strict.pm 8 -> import
|
|
0 4201691472667 strict.pm 8 <- import
|
|
0 4201691472675 Config.pm 7 <- BEGIN
|
|
0 4201691472809 Config.pm 133 -> BEGIN
|
|
0 4201691472817 strict.pm 8 -> unimport
|
|
0 4201691472825 strict.pm 8 -> bits
|
|
0 4201691472852 strict.pm 26 <- bits
|
|
0 4201691472868 strict.pm 16 <- unimport
|
|
0 4201691472876 Config.pm 7 <- BEGIN
|
|
0 4201691473222 Config.pm 345 -> TIEHASH
|
|
0 4201691473231 Config.pm 9 <- TIEHASH
|
|
0 4201691473275 Config.pm 43 -> import
|
|
0 4201691473292 Config.pm 17 <- import
|
|
0 4201691473301 DynaLoader.pm 8 <- BEGIN
|
|
0 4201691474650 AutoLoader.pm 1349 -> BEGIN
|
|
0 4201691474661 strict.pm 10 -> import
|
|
0 4201691474670 strict.pm 9 <- import
|
|
0 4201691474679 AutoLoader.pm 8 <- BEGIN
|
|
0 4201691474701 AutoLoader.pm 21 -> BEGIN
|
|
0 4201691474709 AutoLoader.pm 8 <- BEGIN
|
|
0 4201691474797 AutoLoader.pm 88 -> BEGIN
|
|
0 4201691474810 AutoLoader.pm 12 <- BEGIN
|
|
0 4201691475186 AutoLoader.pm 376 -> BEGIN
|
|
0 4201691475195 strict.pm 9 -> unimport
|
|
0 4201691475203 strict.pm 7 -> bits
|
|
0 4201691475214 strict.pm 10 <- bits
|
|
0 4201691475223 strict.pm 8 <- unimport
|
|
0 4201691475230 AutoLoader.pm 7 <- BEGIN
|
|
0 4201691475435 AutoLoader.pm 204 -> BEGIN
|
|
0 4201691475444 strict.pm 8 -> unimport
|
|
0 4201691475451 strict.pm 7 -> bits
|
|
0 4201691475462 strict.pm 10 <- bits
|
|
0 4201691475470 strict.pm 8 <- unimport
|
|
0 4201691475478 AutoLoader.pm 7 <- BEGIN
|
|
0 4201691475697 AutoLoader.pm 219 -> BEGIN
|
|
0 4201691475706 strict.pm 8 -> unimport
|
|
0 4201691475714 strict.pm 7 -> bits
|
|
0 4201691475724 strict.pm 10 <- bits
|
|
0 4201691475732 strict.pm 8 <- unimport
|
|
0 4201691475739 AutoLoader.pm 7 <- BEGIN
|
|
0 4201691475842 Config.pm 102 -> FETCH
|
|
0 4201691475854 Config.pm 11 <- FETCH
|
|
0 4201691475870 Config.pm 15 -> FETCH
|
|
0 4201691475879 Config.pm 9 <- FETCH
|
|
0 4201691475890 Config.pm 10 -> FETCH
|
|
0 4201691475898 Config.pm 8 <- FETCH
|
|
0 4201691475909 Config.pm 10 -> FETCH
|
|
0 4201691475917 Config.pm 8 <- FETCH
|
|
0 4201691476012 Kstat.pm 94 <- BEGIN
|
|
0 4201691476041 Kstat.pm 29 -> BEGIN
|
|
0 4201691476051 vars.pm 9 -> import
|
|
0 4201691476084 vars.pm 32 <- import
|
|
0 4201691476091 Kstat.pm 7 <- BEGIN
|
|
0 4201691476147 DynaLoader.pm 56 -> bootstrap
|
|
0 4201691476373 DynaLoader.pm 225 -> dl_load_flags
|
|
0 4201691476383 DynaLoader.pm 9 <- dl_load_flags
|
|
0 4201691476813 DynaLoader.pm 430 <- bootstrap
|
|
0 4201691476837 nicstat 23 <- BEGIN
|
|
0 4201691483648 Std.pm 6811 -> getopts
|
|
0 4201691483697 Exporter.pm 49 -> import
|
|
0 4201691483737 Exporter.pm 39 <- import
|
|
0 4201691483756 Std.pm 19 <- getopts
|
|
0 4201691483780 nicstat 24 -> find_nets
|
|
0 4201691539198 nicstat 55418 <- find_nets
|
|
0 4201691539610 nicstat 411 -> fetch_net_data
|
|
0 4201691583290 nicstat 43679 <- fetch_net_data
|
|
0 4201691583781 nicstat 491 -> print_neat
|
|
0 4201691583930 nicstat 149 <- print_neat
|
|
0 4201691583996 nicstat 65 -> print_neat
|
|
0 4201691584165 nicstat 169 <- print_neat
|
|
0 4201691584174 nicstat 9 -> print_neat
|
|
0 4201691584298 nicstat 124 <- print_neat
|
|
0 4201691584308 nicstat 9 -> print_neat
|
|
0 4201691584432 nicstat 124 <- print_neat
|
|
0 4201691584473 nicstat 41 -> print_neat
|
|
0 4201691584597 nicstat 123 <- print_neat
|
|
0 4201691584607 nicstat 9 -> print_neat
|
|
0 4201691584730 nicstat 123 <- print_neat
|
|
0 4201691585091 nicstat 361 -> print_neat
|
|
0 4201691585217 nicstat 125 <- print_neat
|
|
0 4201691585226 nicstat 9 -> print_neat
|
|
0 4201691585379 nicstat 152 <- print_neat
|
|
0 4201691585389 nicstat 9 -> print_neat
|
|
0 4201691585512 nicstat 123 <- print_neat
|
|
0 4201691585521 nicstat 9 -> print_neat
|
|
0 4201691585644 nicstat 123 <- print_neat
|
|
0 4201691585653 nicstat 9 -> print_neat
|
|
0 4201691585825 nicstat 171 <- print_neat
|
|
0 4201691585834 nicstat 9 -> print_neat
|
|
0 4201691585988 nicstat 154 <- print_neat
|
|
0 4201691586274 nicstat 285 -> print_neat
|
|
0 4201691586434 nicstat 160 <- print_neat
|
|
0 4201691586443 nicstat 9 -> print_neat
|
|
0 4201691586567 nicstat 123 <- print_neat
|
|
0 4201691586576 nicstat 9 -> print_neat
|
|
0 4201691586731 nicstat 154 <- print_neat
|
|
0 4201691586740 nicstat 8 -> print_neat
|
|
0 4201691586892 nicstat 151 <- print_neat
|
|
0 4201691586901 nicstat 9 -> print_neat
|
|
0 4201691587025 nicstat 123 <- print_neat
|
|
0 4201691587034 nicstat 9 -> print_neat
|
|
0 4201691587157 nicstat 123 <- print_neat
|
|
0 4201691590909 Config.pm 3751 -> DESTROY
|
|
0 4201691590938 Config.pm 29 <- DESTROY
|
|
|
|
After initialising Perl libraries and modules, the "nicstat" program ran,
|
|
the output matching what was expected from the source.
|
|
|
|
The DELTA column shows that most time is spent in the find_nets() and
|
|
fetch_nets_data() subroutines, with 55.4 ms and 44.7 ms of elapsed
|
|
function time respectively. Those particular times were easy to interpret,
|
|
since there were no child subroutines called, and the delta spanned
|
|
the subroutine entry to its return.
|
|
|
|
Some times get trickier to comprehend. The 2nd last line with a DELTA time
|
|
of 3751 us, means "the time from the print_neat() subroutine completing
|
|
to the DESTROY() subroutine starting, took 3751 us.". What is happening
|
|
during this time? It is hard to say based on this output - since it isn't
|
|
time within a function, rather it is time that Perl spent processing the
|
|
main program. Since we have the last function called, we may guess where
|
|
the program was at; or we could enhance this script to trace Perl engine
|
|
internals as well (and/or syscalls).
|
|
|