Tracing with enterstep

Browsing the pages on tracing and debugging it rapidly becomes clear that people have very differrent ideas about what they want from a debug or trace package so here's yet another contribution.

One powerful feature of Tcl is the execution trace. Unfortunately enter traces are too high level and enterstep traces are too low level in that they always "step in" and they also trace uplevel commands.

One solution is to instrument a proc with puts but this is very difficult to do to the correct level so that it handles all control constructs properly.

The following code shows how to limit the output from tracing and incidentally outlines a method for performing intelligent single stepping without modding the source:

The Code

# Some code for implementing tracing of the steps in a proc
# WITHOUT tracing called or uplevelled code like the enterstep trace does.
# (It's not quite one trace per line because something like
# foo [a] [b] [c]
# will be 4 steps)

# Boilerplate ensemble stuff
namespace eval traceproc {
    namespace export {[a-z]*}
    namespace ensemble create
    variable tinfo
}

# This trace captures the level at which the call occurs
# and initializes data so that the first line of the proc within the source
# file can be recognized in the enterstep callback.
# NB recursion is not supported in this implementation
proc traceproc::Enter {procname args} {
    variable tinfo
    dict set tinfo($procname) firstline -1
    dict set tinfo($procname) level [expr {[info level]+1}]
}

# trace enterstep proc
proc traceproc::EnterStep {procname args} {
    variable tinfo
    #only trace top level steps in the proc
    if {[info level] == [dict get $tinfo($procname) level]} {
        if {[dict get $tinfo($procname) firstline] < 0} {
            # make line numbers relative to the start of the proc rather than the file
            set finfo [info frame -4]
            set firstline [dict get $finfo line]
            dict set tinfo($procname) firstline $firstline
        }
        DumpFrame $procname  -3
    }
}

proc traceproc::DumpFrame {procname frame} {
    variable tinfo
    set d [info frame [expr {$frame -1}]]
    # This test prevents tracing of stuff uplevelled from called procs
    if {"[dict get $d proc]" ne "$procname"} {
        return
    }
    set cmd [dict get $d cmd]
    # limit output to one line
    set nl [string first "\n" $cmd]
    if {$nl >= 0} {
        set cmd [string range $cmd 0 $nl-1]...
    }
    # calculate proc line number rather than file line number
    set procline [expr {[dict get $d line] - [dict get $tinfo($procname) firstline] + 1}]
    puts stdout "TRACE $procname line $procline $cmd"
    # by performing a vwait at this point you can easily implement single stepping etc
    #vwait ::step
}

# Add a print trace to the specified proc
proc traceproc::trace {procname} {
    # get the qualified name because it is used fro checking later
    set qprocname [uplevel 1 namespace which $procname]
    ::trace add execution $procname {enter} [list ::traceproc::Enter $qprocname]
    #::trace add execution $procname {leave} [list ::traceproc::Leave $qprocname]
    ::trace add execution $procname {enterstep} [list ::traceproc::EnterStep $qprocname]
}

Demonstrating

The Test Data

proc test1 {a b} {
    set c [test2 $a $b]
    if {$a > 1} {
        puts stdout "hello [test3 $a]"
    } else {
        puts stdout "else"
    }
    for {set i 0} {$i < 3} {incr i} {
        puts "  $i"
    }
    return $b
}

proc test2 {x y} {
    uplevel 1 set c 7
}

proc test3 x {
    return "value is $x"
}

traceproc trace test1
traceproc trace test2

test1 2 4

The Output

This produces the following output:

TRACE ::test1 line 1 test2 $a $b
TRACE ::test2 line 1 uplevel 1 set c 7
TRACE ::test1 line 1 set c [test2 $a $b]
TRACE ::test1 line 2 if {$a > 1} {...
TRACE ::test1 line 3 test3 $a
TRACE ::test1 line 3 puts stdout "hello [test3 $a]"
hello value is 2
TRACE ::test1 line 7 for {set i 0} {$i < 3} {incr i} {...
TRACE ::test1 line 7 set i 0
TRACE ::test1 line 8 puts "  $i"
  0
TRACE ::test1 line 7 incr i
TRACE ::test1 line 8 puts "  $i"
  1
TRACE ::test1 line 7 incr i
TRACE ::test1 line 8 puts "  $i"
  2
TRACE ::test1 line 7 incr i
TRACE ::test1 line 10 return $b

Enhancements

Obviously making this into a proper package would require passing a script rather than hardcoding a puts. Nesting is not supported. Tracing of non-script relative procs is not supported.

Towards a debugger

By adding the command

vwait ::step

to the trace action it is trivial to implement single stepping without stepping into called procs.

Many other wiki entries already show how to use uplevel to dump stack frames and allow editing of variables.

Category Debugging