[George Peter Staplin] Dec 28, 2005 - I wanted the ability to profile my whole program without wrapping many commands with [time], so I created a version of proc that logs the time.  The cost of the logging and tracing[http://www.tcl.tk/man/tcl8.4/TclCmd/trace.htm] increases the time, but it seems to be a good way to find hot spots in a program.

----
 # By George Peter Staplin
 # Dec 2005 
 array set ::debug_state {}

 proc debug_callback {args} {
  global debug_state
 
  set proc [lindex [lindex $args 0] 0]
  set type [lindex $args end]

  if {"enter" eq $type} {
   set debug_state($proc) [clock clicks]
  } else {
   set end [clock clicks]
   set fd [open $::debug_log_file a]
   puts $fd "$proc took: [expr {$end - $::debug_state($proc)}]"
   close $fd
   unset debug_state($proc)
  }
 }

 proc debug_trace cmd {
  trace add execution $cmd enter debug_callback
  trace add execution $cmd leave debug_callback
 }

 set ::debug_log_file debug.log
 rename proc _proc

 
 _proc proc {name arglist body} {
  set ns [uplevel 1 namespace current]
  set p [set ns]::[set name]
  _proc $p $arglist $body
 
  debug_trace $p
 }
----

Possible future improvements might include keeping a log of the entire runtime, and then averaging the runtime by the number of calls.  I however didn't need that for my usage, because I was killing the program with ^C. :)

----
[Category Performance] | [Category Debugging] | [Category Dev. Tools] | [Category Development]