The following are examples of running tcl_flow.d.
Here the script is tracing the execution of Code/Tcl/func_abc.tcl
# tcl_flow.d
C PID TIME(us) -- CALL
0 16068 3904942506169 > if
0 16068 3904942506261 > info
0 16068 3904942506286 < info
0 16068 3904942506350 > proc
0 16068 3904942506363 < proc
0 16068 3904942506369 < if
0 16068 3904942506383 > tclInit
0 16068 3904942506605 -> tclInit
0 16068 3904942506614 > global
0 16068 3904942506626 < global
0 16068 3904942506632 > global
0 16068 3904942506638 < global
0 16068 3904942506643 > rename
0 16068 3904942506666 < rename
0 16068 3904942506675 > info
0 16068 3904942506685 < info
0 16068 3904942506694 > info
0 16068 3904942506721 < info
0 16068 3904942506728 > unset
0 16068 3904942506741 < unset
0 16068 3904942506746 > concat
0 16068 3904942506760 < concat
0 16068 3904942506774 > file
0 16068 3904942506792 < file
0 16068 3904942506797 > file
0 16068 3904942506880 < file
0 16068 3904942506885 > file
0 16068 3904942506895 < file
0 16068 3904942506901 > file
0 16068 3904942507009 < file
0 16068 3904942507015 > file
0 16068 3904942507025 < file
0 16068 3904942507031 > file
0 16068 3904942507118 < file
0 16068 3904942507124 > file
0 16068 3904942507133 < file
0 16068 3904942507139 > file
0 16068 3904942507193 < file
0 16068 3904942507200 > uplevel
0 16068 3904942507209 > source
0 16068 3904942507649 > if
0 16068 3904942507664 > info
0 16068 3904942507673 < info
0 16068 3904942507681 < if
0 16068 3904942507691 > package
0 16068 3904942507700 < package
0 16068 3904942507712 > if
0 16068 3904942507722 > info
0 16068 3904942507728 < info
0 16068 3904942507749 > info
0 16068 3904942507773 < info
0 16068 3904942507780 < if
0 16068 3904942507797 > namespace
0 16068 3904942507898 > variable
0 16068 3904942507905 < variable
0 16068 3904942507911 > info
0 16068 3904942507923 < info
0 16068 3904942507928 > info
0 16068 3904942507934 < info
0 16068 3904942507939 > info
0 16068 3904942507947 < info
0 16068 3904942507952 > file
0 16068 3904942507971 < file
0 16068 3904942507977 > list
0 16068 3904942507991 < list
0 16068 3904942507996 > foreach
0 16068 3904942508020 > lsearch
0 16068 3904942508028 < lsearch
0 16068 3904942508034 > lappend
0 16068 3904942508041 < lappend
0 16068 3904942508051 > lsearch
0 16068 3904942508056 < lsearch
0 16068 3904942508061 > lappend
0 16068 3904942508068 < lappend
0 16068 3904942508073 < foreach
0 16068 3904942508078 > info
0 16068 3904942508086 < info
0 16068 3904942508090 > file
0 16068 3904942508108 < file
0 16068 3904942508113 > file
0 16068 3904942508129 < file
0 16068 3904942508134 > file
0 16068 3904942508142 < file
0 16068 3904942508148 > lsearch
0 16068 3904942508153 < lsearch
0 16068 3904942508158 > lappend
0 16068 3904942508166 < lappend
0 16068 3904942508170 > info
0 16068 3904942508176 < info
0 16068 3904942508181 > foreach
0 16068 3904942508190 > lsearch
0 16068 3904942508195 < lsearch
0 16068 3904942508200 > lappend
0 16068 3904942508206 < lappend
0 16068 3904942508211 < foreach
0 16068 3904942508217 < namespace
0 16068 3904942508243 > if
0 16068 3904942508261 > interp
0 16068 3904942508276 < interp
0 16068 3904942508283 < if
0 16068 3904942508296 > package
0 16068 3904942508302 < package
0 16068 3904942508312 > if
0 16068 3904942508322 > interp
0 16068 3904942508328 < interp
0 16068 3904942508369 < if
0 16068 3904942508387 > if
0 16068 3904942508398 > namespace
0 16068 3904942508406 < namespace
0 16068 3904942508412 < if
0 16068 3904942508424 > set
0 16068 3904942508430 < set
0 16068 3904942508437 > set
0 16068 3904942508443 < set
0 16068 3904942508451 > if
0 16068 3904942508463 > namespace
0 16068 3904942508469 < namespace
0 16068 3904942508479 > proc
0 16068 3904942508488 < proc
0 16068 3904942508493 < if
0 16068 3904942508573 > proc
0 16068 3904942508582 < proc
0 16068 3904942508599 > proc
0 16068 3904942508609 < proc
0 16068 3904942508638 > proc
0 16068 3904942508645 < proc
0 16068 3904942508664 > proc
0 16068 3904942508673 < proc
0 16068 3904942508686 > proc
0 16068 3904942508693 < proc
0 16068 3904942508737 > if
0 16068 3904942508760 > proc
0 16068 3904942508782 < proc
0 16068 3904942508788 < if
0 16068 3904942508826 > proc
0 16068 3904942508837 < proc
0 16068 3904942508843 < source
0 16068 3904942508848 < uplevel
0 16068 3904942508857 <- tclInit
0 16068 3904942508871 < tclInit
0 16068 3904942509050 > proc
0 16068 3904942509059 < proc
0 16068 3904942509067 > proc
0 16068 3904942509074 < proc
0 16068 3904942509081 > proc
0 16068 3904942509088 < proc
0 16068 3904942509094 > func_a
0 16068 3904942509110 -> func_a
0 16068 3904942509116 > puts
0 16068 3904942509256 < puts
0 16068 3904942509262 > after
0 16068 3904943510998 < after
0 16068 3904943511016 > func_b
0 16068 3904943511050 -> func_b
0 16068 3904943511058 > puts
0 16068 3904943511090 < puts
0 16068 3904943511094 > after
0 16068 3904944520994 < after
0 16068 3904944521013 > func_c
0 16068 3904944521043 -> func_c
0 16068 3904944521051 > puts
0 16068 3904944521092 < puts
0 16068 3904944521097 > after
0 16068 3904945530993 < after
0 16068 3904945531012 <- func_c
0 16068 3904945531020 < func_c
0 16068 3904945531025 <- func_b
0 16068 3904945531029 < func_b
0 16068 3904945531034 <- func_a
0 16068 3904945531039 < func_a
0 16068 3904945531064 > exit
^C
You can see the output is in five columns.
The first column is CPU-id, the second is PID, third is the time since boot in
microseconds since the previous action. The fourth and fifth columns
represent the action happening. The Tcl command or procedure name is prefixed
by an indicator reprenting what is happening. These may be -> (procedure
entry), <- (procedure return), > (command entry), or < (command return).
As each action is taken, the fourth and fifth columns are indented by 2 spaces.
This shows which procedure or command is calling which.
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.