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 :^)