Tiny timing

Richard Suchenwirth 2006-04-11 - Here is an experiment on how to instrument procs so the time they consume is kept track of. It consists of a namespace timing, into which instrumented procs are renamed, and a wrapper is created that does the time book-keeping (see the template).

Lars H, 2006-04-15: Warning: renaming into a different namespace will break everything that relies on procs being in a particular namespace, such as variable.

Every time an instrumented proc is called, it calls its timing namesake, adds the time in microseconds to the timing::t array, and returns the namesake's results. (I did not put these procs into the timing namespace, to prevent conflicts with user procs of the same name...)

 namespace eval timing {array set t {}}

 proc timing args {
   set template {
      set t [time {set res [uplevel 1 ::timing::@here@ $args]}]
      lappend ::timing::t(@here@) [lindex $t 0]
      set res
   }
   foreach procname $args {
      rename $procname ::timing::$procname
      proc $procname args [string map [list @here@ $procname] $template]
   }
 }

#-- This produces a string with the results, in sorted order:

 proc timing'get {{name *}} {
   set res ""
   foreach i [lsort [array names ::timing::t $name]] {
      set times $::timing::t($i)
      append res "$i : [llength $times] times, [mean $times] usec\n"
   }
   set res
 }

#-- For heavy use, better use a looping mean - see Elegance vs. performance

 proc mean list {expr ([join $list +])/double([llength $list])}

#-- Now testing (I let them all wait a while so time for certain gets non-zero):

 proc foo       args {after 10; return 42}
 proc unbraced {x y} {after 10; expr $x+$y}
 proc braced   {x y} {after 10; expr {$x+$y}}

 timing foo unbraced braced

 foreach i {1 2 3 4 5 6 7 8 9 10} {foo; unbraced 17 4; braced 17 4}

 puts [timing'get]

#----- which shows on my machine:

 braced : 10 times, 15500.0 usec
 foo : 10 times, 15700.0 usec
 unbraced : 10 times, 15700.0 usec

The examples are of course over-simplified, and their measured times should not be taken too serious :^)

Category Debugging | Arts and crafts of Tcl-Tk programming