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