cddl/contrib/dtracetoolkit/Examples/tcl_flow_example.txt

   1 The following are examples of running tcl_flow.d.
   2
   3 Here the script is tracing the execution of Code/Tcl/func_abc.tcl
   4
   5 # tcl_flow.d
   6   C    PID TIME(us)         -- CALL
   7   0  16068 3904942506169     > if
   8   0  16068 3904942506261       > info
   9   0  16068 3904942506286       < info
  10   0  16068 3904942506350       > proc
  11   0  16068 3904942506363       < proc
  12   0  16068 3904942506369     < if
  13   0  16068 3904942506383     > tclInit
  14   0  16068 3904942506605      -> tclInit
  15   0  16068 3904942506614         > global
  16   0  16068 3904942506626         < global
  17   0  16068 3904942506632         > global
  18   0  16068 3904942506638         < global
  19   0  16068 3904942506643         > rename
  20   0  16068 3904942506666         < rename
  21   0  16068 3904942506675         > info
  22   0  16068 3904942506685         < info
  23   0  16068 3904942506694         > info
  24   0  16068 3904942506721         < info
  25   0  16068 3904942506728         > unset
  26   0  16068 3904942506741         < unset
  27   0  16068 3904942506746         > concat
  28   0  16068 3904942506760         < concat
  29   0  16068 3904942506774         > file
  30   0  16068 3904942506792         < file
  31   0  16068 3904942506797         > file
  32   0  16068 3904942506880         < file
  33   0  16068 3904942506885         > file
  34   0  16068 3904942506895         < file
  35   0  16068 3904942506901         > file
  36   0  16068 3904942507009         < file
  37   0  16068 3904942507015         > file
  38   0  16068 3904942507025         < file
  39   0  16068 3904942507031         > file
  40   0  16068 3904942507118         < file
  41   0  16068 3904942507124         > file
  42   0  16068 3904942507133         < file
  43   0  16068 3904942507139         > file
  44   0  16068 3904942507193         < file
  45   0  16068 3904942507200         > uplevel
  46   0  16068 3904942507209           > source
  47   0  16068 3904942507649             > if
  48   0  16068 3904942507664               > info
  49   0  16068 3904942507673               < info
  50   0  16068 3904942507681             < if
  51   0  16068 3904942507691             > package
  52   0  16068 3904942507700             < package
  53   0  16068 3904942507712             > if
  54   0  16068 3904942507722               > info
  55   0  16068 3904942507728               < info
  56   0  16068 3904942507749               > info
  57   0  16068 3904942507773               < info
  58   0  16068 3904942507780             < if
  59   0  16068 3904942507797             > namespace
  60   0  16068 3904942507898               > variable
  61   0  16068 3904942507905               < variable
  62   0  16068 3904942507911               > info
  63   0  16068 3904942507923               < info
  64   0  16068 3904942507928               > info
  65   0  16068 3904942507934               < info
  66   0  16068 3904942507939               > info
  67   0  16068 3904942507947               < info
  68   0  16068 3904942507952               > file
  69   0  16068 3904942507971               < file
  70   0  16068 3904942507977               > list
  71   0  16068 3904942507991               < list
  72   0  16068 3904942507996               > foreach
  73   0  16068 3904942508020                 > lsearch
  74   0  16068 3904942508028                 < lsearch
  75   0  16068 3904942508034                 > lappend
  76   0  16068 3904942508041                 < lappend
  77   0  16068 3904942508051                 > lsearch
  78   0  16068 3904942508056                 < lsearch
  79   0  16068 3904942508061                 > lappend
  80   0  16068 3904942508068                 < lappend
  81   0  16068 3904942508073               < foreach
  82   0  16068 3904942508078               > info
  83   0  16068 3904942508086               < info
  84   0  16068 3904942508090               > file
  85   0  16068 3904942508108               < file
  86   0  16068 3904942508113               > file
  87   0  16068 3904942508129               < file
  88   0  16068 3904942508134               > file
  89   0  16068 3904942508142               < file
  90   0  16068 3904942508148               > lsearch
  91   0  16068 3904942508153               < lsearch
  92   0  16068 3904942508158               > lappend
  93   0  16068 3904942508166               < lappend
  94   0  16068 3904942508170               > info
  95   0  16068 3904942508176               < info
  96   0  16068 3904942508181               > foreach
  97   0  16068 3904942508190                 > lsearch
  98   0  16068 3904942508195                 < lsearch
  99   0  16068 3904942508200                 > lappend
 100   0  16068 3904942508206                 < lappend
 101   0  16068 3904942508211               < foreach
 102   0  16068 3904942508217             < namespace
 103   0  16068 3904942508243             > if
 104   0  16068 3904942508261               > interp
 105   0  16068 3904942508276               < interp
 106   0  16068 3904942508283             < if
 107   0  16068 3904942508296             > package
 108   0  16068 3904942508302             < package
 109   0  16068 3904942508312             > if
 110   0  16068 3904942508322               > interp
 111   0  16068 3904942508328               < interp
 112   0  16068 3904942508369             < if
 113   0  16068 3904942508387             > if
 114   0  16068 3904942508398               > namespace
 115   0  16068 3904942508406               < namespace
 116   0  16068 3904942508412             < if
 117   0  16068 3904942508424             > set
 118   0  16068 3904942508430             < set
 119   0  16068 3904942508437             > set
 120   0  16068 3904942508443             < set
 121   0  16068 3904942508451             > if
 122   0  16068 3904942508463               > namespace
 123   0  16068 3904942508469               < namespace
 124   0  16068 3904942508479               > proc
 125   0  16068 3904942508488               < proc
 126   0  16068 3904942508493             < if
 127   0  16068 3904942508573             > proc
 128   0  16068 3904942508582             < proc
 129   0  16068 3904942508599             > proc
 130   0  16068 3904942508609             < proc
 131   0  16068 3904942508638             > proc
 132   0  16068 3904942508645             < proc
 133   0  16068 3904942508664             > proc
 134   0  16068 3904942508673             < proc
 135   0  16068 3904942508686             > proc
 136   0  16068 3904942508693             < proc
 137   0  16068 3904942508737             > if
 138   0  16068 3904942508760               > proc
 139   0  16068 3904942508782               < proc
 140   0  16068 3904942508788             < if
 141   0  16068 3904942508826             > proc
 142   0  16068 3904942508837             < proc
 143   0  16068 3904942508843           < source
 144   0  16068 3904942508848         < uplevel
 145   0  16068 3904942508857      <- tclInit
 146   0  16068 3904942508871     < tclInit
 147   0  16068 3904942509050     > proc
 148   0  16068 3904942509059     < proc
 149   0  16068 3904942509067     > proc
 150   0  16068 3904942509074     < proc
 151   0  16068 3904942509081     > proc
 152   0  16068 3904942509088     < proc
 153   0  16068 3904942509094     > func_a
 154   0  16068 3904942509110      -> func_a
 155   0  16068 3904942509116         > puts
 156   0  16068 3904942509256         < puts
 157   0  16068 3904942509262         > after
 158   0  16068 3904943510998         < after
 159   0  16068 3904943511016         > func_b
 160   0  16068 3904943511050          -> func_b
 161   0  16068 3904943511058             > puts
 162   0  16068 3904943511090             < puts
 163   0  16068 3904943511094             > after
 164   0  16068 3904944520994             < after
 165   0  16068 3904944521013             > func_c
 166   0  16068 3904944521043              -> func_c
 167   0  16068 3904944521051                 > puts
 168   0  16068 3904944521092                 < puts
 169   0  16068 3904944521097                 > after
 170   0  16068 3904945530993                 < after
 171   0  16068 3904945531012              <- func_c
 172   0  16068 3904945531020             < func_c
 173   0  16068 3904945531025          <- func_b
 174   0  16068 3904945531029         < func_b
 175   0  16068 3904945531034      <- func_a
 176   0  16068 3904945531039     < func_a
 177   0  16068 3904945531064     > exit
 178 ^C
 179
 180 You can see the output is in five columns.
 181
 182 The first column is CPU-id, the second is PID, third is the time since boot in
 183 microseconds since the previous action.  The fourth and fifth columns
 184 represent the action happening.   The Tcl command or procedure name is prefixed
 185 by an indicator reprenting what is happening.  These may be -> (procedure
 186 entry), <- (procedure return), > (command entry), or < (command return).
 187
 188 As each action is taken, the fourth and fifth columns are indented by 2 spaces.
 189 This shows which procedure or command is calling which.
 190
 191 If the output looks shuffled, check the CPU "C" and "TIME" columns, and
 192 post sort based on TIME if necessary.
 193
 194 See Notes/ALLflow_notes.txt for important notes about reading flow outputs.
 195