Debugging, speed and a complete script

Scripts fail. A good engineer finds the fault quickly, and the habits for that are the same in every tool. This lesson covers the commands that show what a script is doing, the mistakes that appear again and again, how to measure speed, and finally a complete script that uses nearly everything from the first eleven lessons.

Reading time: about 10 minutes.

12.1 Print first

The cheapest debugger is puts. Print the value of a variable before the line that fails, and use braces or list so that spaces and empty values are visible.

puts "name=<$name> n=[llength $items]"

The angle brackets show whether a value is empty or has trailing spaces. When a list looks wrong, puts [llength $x] and puts [lindex $x 0] usually explain it.

12.2 Asking Tcl about itself

info answers questions about procedures and variables.

proc f {a {b 1} args} { return [list $a $b $args] }
puts [info args f]
puts [info default f b v]
puts $v
puts [info level]
puts [info exists wns]

This prints:

a b args
1
1
0
0

info args f lists the parameter names. info default f b v returns 1 when the parameter has a default and stores the default in v. info level is the depth of the call stack: 0 at the top level, and 1 inside a procedure called from there. info exists tests a variable, and info commands and info procs list commands by pattern.

12.3 Stack traces

When a procedure fails deep in a chain of calls, the error trace shows the whole path.

proc a {} { b }
proc b {} { c }
proc c {} { error "deep failure" }
catch a m o
puts [dict get $o -errorinfo]

This prints:

deep failure
    while executing
"error "deep failure" "
    (procedure "c" line 1)
    invoked from within
"c "
    (procedure "b" line 1)
    invoked from within
"b "
    (procedure "a" line 1)
    invoked from within
"a"

Read it from the top: the message, where it was raised, and then each caller. In a tool, errorInfo holds the same trace for the last error, so print it when a script stops with a one-line message that is not enough.

Error codes carry the family of the failure in a form a script can test:

catch {expr {1/0}} m o
puts [dict get $o -errorcode]
catch {open /nonexistent/x r} m o
puts [lindex [dict get $o -errorcode] 0]

This prints ARITH DIVZERO {divide by zero} and POSIX. A handler that checks the first word can respond differently to a missing file and to bad arithmetic.

12.4 Watching a variable with trace

trace add variable runs a command whenever a variable is read, written or removed. It finds the line that changes a value unexpectedly.

trace add variable wns write {apply {{n1 n2 op} { upvar #0 $n1 v; puts "$n1 is now $v" }}}
set wns -0.5
set wns 0.1

This prints:

wns is now -0.5
wns is now 0.1

Remove the trace with trace remove variable when you have found the cause, because every write pays for the callback.

12.5 Wrapping a command with rename

rename gives a command a new name, so you can put a wrapper in its place that logs the call and then calls the original.

proc g {x} { return [expr {$x * 2}] }
rename g g_orig
proc g {x} { puts "calling g $x"; return [g_orig $x] }
puts [g 4]

This prints calling g 4 and then 8. The technique logs a tool command without editing every place that calls it. Use it for a short debugging session and take it out afterwards.

12.6 Measuring speed

time runs a script a number of times and reports the average.

set r [time {set s 0; for {set i 0} {$i < 1000} {incr i} {incr s}} 10]
puts $r

The result has the form N microseconds per iteration. The number depends on the machine, so the example does not print one. Use time to compare two ways of doing the same job, for example a braced and an unbraced expr from Lesson 3. For a whole tool step, use the stage timer that the tool provides. The Innovus reference lists time_info with a stage name, -current and -report for runtime and memory per stage.

Three habits keep scripts fast. Brace every expr. Use lappend and append rather than rebuilding a long value each pass. Filter inside the tool, as Lesson 10 showed, rather than fetching everything and filtering in Tcl.

12.7 Common mistakes

These are the faults seen most often. Each has appeared in an earlier lesson.

set x 3
puts [if {$x == "3.0"} {set r same} else {set r diff}]
puts [string equal $x 3.0]
set l {a b c}
set out {}
for {set i 0} {$i <= [llength $l]} {incr i} { lappend out [lindex $l $i] }
puts [llength $out]
puts "<$out>"

This prints:

same
0
4
<a b c {}>

The first pair shows that == compares numbers, so 3 and "3.0" are equal, and string equal compares text, so they differ. Decide which you mean. The loop used <= against the length, ran one step too far, and lindex returned an empty element instead of failing.

The remaining mistakes in one list:

• A brace on its own line. Writing if {...} and putting { on the next line ends the command early.
• Unbraced expr. It is slower and can be unsafe.
• Integer division. 7/2 is 3, so write 7/2.0.
• A comment with a brace in it inside a braced body can unbalance the braces.
• A list built by gluing strings. Use list and lappend.
• Brackets in names. Brace them and escape them in glob patterns.
• Forgetting close. Pair every open with a close, ideally with try ... finally.
• A global used by surprise. Pass values as arguments.

12.8 A complete script

The script below reads a timing summary, prints a table sorted by slack, and reports the worst slack, the total negative slack and the count of violating paths. It exits with status 1 when any path is below a margin. The report format is synthetic and made up for this course. It is not a real tool format, so a real report needs a different regexp, written after you have looked at the file.

The input, sample_timing.rpt:

# synthetic timing summary (not a real tool format)
view: func_ss_setup   check: setup
path 1  start: ff_a/CK  end: ff_b/D  slack: -0.120
path 2  start: ff_c/CK  end: ff_d/D  slack: 0.300
path 3  start: ff_e/CK  end: ff_f/D  slack: -0.450
path 4  start: ff_g/CK  end: ff_h/D  slack: 0.012
path 5  start: ff_i/CK  end: ff_j/D  slack: 1.250

The script, parse_report.tcl:

# usage: tclsh parse_report.tcl report_file ?margin?
package require Tcl 8.5-

proc parse_paths {file} {
    set fh [open $file r]
    set paths {}
    try {
        while {[gets $fh line] >= 0} {
            if {[regexp {^path\s+\d+\s+start:\s+(\S+)\s+end:\s+(\S+)\s+slack:\s+(-?[0-9.]+)} \
                    $line -> s e sl]} {
                lappend paths [list $s $e $sl]
            }
        }
    } finally {
        close $fh
    }
    return $paths
}

proc summarise {paths margin} {
    set wns ""
    set tns 0.0
    set nviol 0
    foreach p $paths {
        set sl [lindex $p 2]
        if {$wns eq "" || $sl < $wns} { set wns $sl }
        if {$sl < $margin} {
            set tns [expr {$tns + $sl}]
            incr nviol
        }
    }
    return [dict create wns $wns tns $tns violating $nviol total [llength $paths]]
}

if {$argc < 1 || $argc > 2} {
    puts stderr "usage: parse_report.tcl report_file ?margin?"
    exit 2
}
set file [lindex $argv 0]
set margin [expr {$argc == 2 ? [lindex $argv 1] : 0.0}]
if {[catch {parse_paths $file} paths]} {
    puts stderr "cannot read $file: $paths"
    exit 2
}
foreach p [lsort -real -index 2 $paths] {
    lassign $p s e sl
    puts [format "%-8s %-8s %7.3f  %s" $s $e $sl [expr {$sl < $margin ? "VIOLATED" : "met"}]]
}
set r [summarise $paths $margin]
puts [format "WNS %.3f  TNS %.3f  violating %d of %d" \
    [dict get $r wns] [dict get $r tns] [dict get $r violating] [dict get $r total]]
exit [expr {[dict get $r violating] > 0 ? 1 : 0}]

Run as tclsh parse_report.tcl sample_timing.rpt, it prints:

ff_e/CK  ff_f/D    -0.450  VIOLATED
ff_a/CK  ff_b/D    -0.120  VIOLATED
ff_g/CK  ff_h/D     0.012  met
ff_c/CK  ff_d/D     0.300  met
ff_i/CK  ff_j/D     1.250  met
WNS -0.450  TNS -0.570  violating 2 of 5

The exit status is 1, because two paths are below zero. With a margin of -0.2 the path at -0.120 counts as met, and only one path violates. With a missing file the script prints cannot read nofile and exits 2, and with no argument it prints the usage line and exits 2.

Count the lessons in it. The regexp with capture groups is Lesson 5. The while with gets and the try ... finally that closes the file are Lessons 9 and 6. The list of records and lsort -real -index are Lesson 4. The dictionary return is Lessons 7 and 8. The argc check, the catch around the parse and the exit status are Lessons 9, 6 and 11. Nothing here is specific to one tool.

12.9 How it fits an Innovus run

In a real flow, the timing step is Innovus, and this script sits after it. The Legacy reference states that timeDesign writes its reports under ./timingReports by default, with .tarpt files for path groups, and that -outDir and -prefix change the location and the file names. A wrapper script runs the step, finds the report files with glob, and calls a parser on each.

Legacy UI. To be run at the Innovus prompt. Check the options with timeDesign -help.

timeDesign -postCTS -outDir timingReports
foreach rpt [lsort [glob -nocomplain timingReports/*.tarpt]] {
    puts "found [file tail $rpt]"
}

Open one real report first and write the regexp for the lines you see. The pattern in parse_report.tcl is a template. The reference also describes a .summary file with WNS, TNS and the violating-path counts per group, which may already hold the numbers you want. The shape of the flow does not change: run the step, find the file, parse it, decide and exit.

12.10 Why an interviewer asks about this

Typical questions: "how do you debug a Tcl script", "how do you find where a variable changes" and "write a script that reads a report and prints the worst slack". Good answers mention puts with brackets around values, errorInfo for the trace, trace add variable for a watch, and time for speed. For the last, they sketch a regexp inside a gets loop, collect the numbers, and print the minimum, as parse_report.tcl does. Ending with a non-zero exit when the check fails shows you think about the flow around the script.