diff options
Diffstat (limited to 'cddl/contrib/dtracetoolkit/Examples/pl_flowtime_example.txt')
| -rw-r--r-- | cddl/contrib/dtracetoolkit/Examples/pl_flowtime_example.txt | 199 |
1 files changed, 199 insertions, 0 deletions
diff --git a/cddl/contrib/dtracetoolkit/Examples/pl_flowtime_example.txt b/cddl/contrib/dtracetoolkit/Examples/pl_flowtime_example.txt new file mode 100644 index 0000000..24c53838 --- /dev/null +++ b/cddl/contrib/dtracetoolkit/Examples/pl_flowtime_example.txt @@ -0,0 +1,199 @@ +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). + |
