Version 0 of Profiling with execution traces

Updated 2008-07-16 07:44:46 by suchenwi

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


enter categories here