[Richard Suchenwirth] 2008-07-16 - The following little script demonstrates how performance data for a program (number how often a command is called, average time) can be collected via [trace execution]. You can specify a number of commands (procs or built-ins) for which at start and end, the microseconds timestamp is taken. The difference between the two is added to an array indexed by command name. I first tried just asking for profiling [[[info commands]], but that took so much time that I couldn't stand it. See discussion below. #---------------------------------------- begin package profiler package require Tcl 8.5 namespace eval profiler {variable T; variable S} proc profiler::enter args { variable S ::profiler::push S [::tcl::clock::microseconds] } proc profiler::leave {str args} { variable T; variable S set t0 [::profiler::pop S] ::profiler::push T([lindex $str 0]) [expr {[::tcl::clock::microseconds]-$t0}] } proc profiler::do {what cmdlist} { set cmd "" foreach i $cmdlist { if {!([string match *profiler::* $i])} { append cmd "trace $what execution $i enter ::profiler::enter\n" append cmd "trace $what execution $i leave ::profiler::leave\n" } } eval $cmd } interp alias {} profiler::push {} lappend proc profiler::pop _stack { upvar 1 $_stack stack K [lindex $stack end] [set stack [lrange $stack 0 end-1]] } proc profiler::K {a b} {set a} proc profiler::stats list { set sum [expr double([join $list +])] format "%10.0f %6d %10.2f" $sum [llength $list] [expr {$sum/[llength $list]}] } proc profiler::report {{channel stdout}} { variable T foreach i [lsort -dic [array names T]] { puts $channel [format "%-20s %s" $i [stats $T($i)]] } } #---------------------------------------- end package profiler if 0 {Here we build our "test bed", a main and a very simple function, which we then instrument:} proc main argv { foreach i {1 2 3 4} {puts ==[f $i]} } proc f x {expr {$x*$x}} #-- We activate profiling on all procs, and a few selected Tcl commands: profiler::do add [concat [info procs] {expr lindex foreach upvar puts clock}] main $argv profiler::do remove [info commands] ;# no error if more removed than added profiler::report if 0 {This is seen on [stdout] of my desktop machine: ==1 ==4 ==9 ==16 expr 137662 84 1638.83 f 29036 4 7259.00 foreach 14879 1 14879.00 lindex 105756 116 911.69 main 15969 1 15969.00 puts 34906 4 8726.50 upvar 134692 92 1464.04 I noticed that it is dangerous to trace some essential commands. Adding [set] to the above list slowed the process down very much, and brought these ugly figures: expr 51470212 654 78700.63 f 12083216 4 3020804.00 foreach 7130413 1 7130413.00 lindex 41924889 848 49439.73 main 8306913 1 8306913.00 puts 15131320 4 3782830.00 set 43121372 906 47595.33 upvar 51070069 722 70734.17 Not a pretty sight. If someone can explain, I'd gladly listen :^) [Lars H]: Does it make a difference if you change the definition of [K] to proc profiler::K {a b} {return $a} ? Get rid of the ''t0'' variable in profiler::leave? It seems every call to this procedure does 3 [set]s, 2 [lindex]es, and only one each of all other commands, which could make a difference if the profiler spends a lot of time profiling itself. I think traces on a command are disabled inside the trace procedure for that command, but this is on a per-command basis, so traces on all traced commands in profiler::leave will fire before trace-of-trace recursion stops. It could simply be that adding [set] to the mix is what is required to make the recursive tracing overhead dominate the I/O latency in [puts]. ---- !!!!!! %| [Category Performance] | [Category Example] |% !!!!!!