Tcl · Module 27

Logging and Runtime Tracking

A flow that got slower is a step that got slower, and finding out which needs a number. The obvious way to get that number returns a different answer each time for identical work.

Intermediate20 min readtcledapart-iiinfrastructureloggingperformance

Part II · Module 27 · Chapter 27.6 · Logging and Runtime Tracking

"The flow got slower" is the most common and least actionable complaint in a chip project. It is also easy to replace with a number, and the obvious way of getting that number does not work.

1. The measurement everyone writes

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

set start [clock seconds]
# ... the step ...
puts "step finished in [expr {[clock seconds] - $start}]s"

That is the standard idiom, and it is this chapter's own brief. It is wrong, and not by a rounding error.

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

=== timing the same work with both clocks ===
    work ~ 120 ms -> clock seconds says 0s, clock milliseconds says 120ms
    work ~ 400 ms -> clock seconds says 0s, clock milliseconds says 400ms
    work ~ 900 ms -> clock seconds says 1s, clock milliseconds says 900ms
    work ~1600 ms -> clock seconds says 2s, clock milliseconds says 1600ms

Nine hundred milliseconds reads as 1 second. Sixteen hundred reads as 2 — a 25% overstatement. Four hundred reads as 0, which is to say the step did not happen.

2. Why: it counts boundaries, not time

A difference of two clock seconds readings is not an elapsed time. It is the number of second boundaries crossed between them.

clock seconds returns whole seconds since the epoch. If a step starts at …07.95 and ends at …08.35 — 400 ms of work — the two readings are …07 and …08, and the difference is 1. If it starts at …08.10 and ends at …08.50, identical work, the readings are both …08 and the difference is 0.

So the answer depends on where in the second the step happened to start, which is nothing to do with how long it took:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

=== and the boundary problem: same work, different answer ===
    0 0 0 1 0 0
    six identical 300 ms steps, measured with clock seconds

Six identical 300 ms steps. Five zeros and a one. Total real work 1.8 seconds, total reported 1 second — and the position of the 1 moves between runs, because it depends only on clock phase.

A measurement that returns a different answer for identical work is not a measurement. And note the failure direction: it under-reports most of the time and occasionally over-reports, so an average over many steps is also wrong, not merely noisy.

The registry's sample for this chapter uses clock seconds, which is how widespread the idiom is. It is folklore worth naming as folklore: clock seconds is correct for timestamps and wrong for durations. The fix is one word.

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

set t0 [clock milliseconds]
# ... the step ...
set ms [expr {[clock milliseconds] - $t0}]

clock milliseconds exists in Tcl 8.5, so this needs nothing newer than the interpreter already in front of you. For sub-millisecond work there is clock microseconds, and for benchmarking a command rather than a step there is time, which runs it a requested number of times and reports the average microseconds per iteration.

3. The stamp: elapsed, not wall clock

A second change, which the brief does not ask for and which makes a flow log far more useful:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

# A log line's stamp is ELAPSED time since the run started, not wall clock.
proc ::flow::stamp {} {
    if {$::flow::RUN_START == 0} { return "  +0.000s" }
    return [format "%+8.3fs" [expr {([clock milliseconds] - $::flow::RUN_START) / 1000.0}]]
}

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

  +0.000s INFO  step read_rtl: start
  +0.180s INFO  step read_rtl: ok in 180 ms
  +0.180s INFO  step elaborate: start
  +0.600s INFO  step elaborate: ok in 420 ms
  +0.600s INFO  step constrain: start
  +0.600s INFO  step constrain: FAILED in 0 ms
  +0.600s ERROR step constrain: missing SDC file
  +0.600s INFO  step compile: start
  +1.550s INFO  step compile: ok in 950 ms

+0.600s answers "how far into the run did this happen", which is the question you ask when reading a flow log. 14:22:07 does not, and it has two further costs: two runs of the same flow cannot be diffed, because every line differs; and a log read six months later needs arithmetic to locate anything.

The wall-clock start is recorded once, in the header, where provenance belongs (Chapter 27.1 §6). You lose nothing and the body of the log becomes comparable.

4. Timing a step without repeating yourself

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

proc ::flow::step {name body} {
    ::flow::log INFO "step $name: start"
    set t0 [clock milliseconds]
    set code [catch {uplevel 1 $body} result]
    set ms [expr {[clock milliseconds] - $t0}]
    set status [expr {$code == 0 ? "ok" : "FAILED"}]
    lappend ::flow::STEP_TIMES [list $name $ms $status]
    ::flow::log INFO [format "step %s: %s in %d ms" $name $status $ms]
    if {$code != 0} {
        ::flow::log ERROR "step $name: $result"
        if {$::STOP_ON_ERR} { return -code error $result }
    }
    return $result
}

Used as:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

::flow::step read_rtl  { busy 180 }
::flow::step elaborate { busy 420 }

Four things in that procedure are load-bearing.

uplevel 1 $body runs the step's code in the caller's scope, so a step can read and set the caller's variables as if the wrapper were not there (Chapter 11.5). Without it, ::flow::step would be a sealed box and every step would need its state passed in and out.

The duration is recorded on the failure path too. catch runs first, timing happens unconditionally, and the status is derived afterwards. A wrapper that times only successful steps loses exactly the data you want when a step starts failing after twenty minutes.

return -code error re-raises rather than calling error, which preserves the original message as the error rather than nesting it (Chapter 14.4).

STOP_ON_ERR gates the re-raise, so the same wrapper serves a flow that must stop and a flow that should carry on and report everything — the one-script-with-options argument from Chapter 27.5 and before it Chapter 21.7 §5.

5. Attributing the time

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

=== the runtime report ===
    STEP                  MS    SHARE  STATUS
    read_rtl             180    11.6%  ok
    elaborate            420    27.1%  ok
    constrain              0     0.0%  FAILED
    compile              950    61.3%  ok
    TOTAL               1550   100.0%

That table is the registry's phrase made real: "attributed to a step rather than to a feeling". compile is 61.3% of the run. If next week's flow is slower, the question is whether that 61.3% moved — and there is now a number from last week to compare it against.

Three details.

The share column, not just the duration. Absolute milliseconds get slower when the machine is busy, and the share is far more stable — so a step whose share grew is a real change, while every step getting slower together is a loaded machine. That is Chapter 22.7 §4's denominator argument applied to time.

The failed step is still in the table, at 0 ms. A step that vanishes from the report when it fails is a step nobody accounts for, and the total then silently describes a different flow from the one that ran — the same argument as Chapter 26.5 §5's every-scenario-produces-a-row.

The total is computed from the rows, not timed separately. Two independent measurements of one thing must agree or disagree visibly, and deriving it means it cannot drift — but note it therefore excludes everything between steps, which §6 is about.

6. What the numbers do not say

Being honest, since a table of percentages invites more confidence than it earns.

These are wall-clock durations, not CPU time. A step that spent eight minutes waiting for a licence and two minutes computing reports ten minutes, and the two are not the same problem. times gives CPU and elapsed separately if the distinction matters, and on a shared farm it usually does.

The total omits the gaps. Summing the steps measures time inside steps. A flow whose steps total 20 minutes and whose wall clock is 35 has 15 minutes somewhere else — reading files between steps, waiting, writing reports outside a step wrapper. Logging the run's own elapsed time alongside the step total makes that gap visible, and an unexplained gap is usually the interesting finding.

One run is a sample. The millisecond figures above are from a single real run and differ on the next. A regression in flow runtime needs several runs, or at minimum a share column rather than absolute times. The numbers published here are a record of one run, not a benchmark.

A mock flow reports all zeros. Chapter 27.1 §6's log shows every step at 0 ms, because the tool there does nothing. That is the right result and it is why this chapter times a flow with real work in it.

What to log, beyond durations.

The provenance header, once — design, stage, tool version, interpreter, host, roots (Chapter 27.1 §6).
Every file read and written, with its path. "Which netlist did this use" is the question that follows every surprising result.
The step name on both the start and the end line. A log truncated by a crash then still says which step was running — and that is the single most useful thing a log can tell you about a run that died.
A level on every line (INFO, WARN, ERROR), so a 40,000-line log can be filtered to the twelve lines that matter.
Not the progress spinner. A log is read by grep far more often than by a human watching it, and per-percent progress lines make that worse.

And flush after every line. ::flow::log calls flush because a log buffered at the moment a flow is killed is a log of a run you cannot diagnose — Chapter 12.6's argument, and the cost is negligible next to anything a flow step does.

7. Exercises

Exercise 1. Why is a difference of two clock seconds readings not a duration?

Exercise 2. 900 ms read as 1s and 400 ms read as 0s. Explain both.

Exercise 3. Six identical 300 ms steps gave 0 0 0 1 0 0. What does that prove?

Exercise 4. Why is an average over many steps also wrong, not just noisy?

Exercise 5. Why is clock seconds still the right call for a timestamp?

Exercise 6. Why is an elapsed stamp better than a wall-clock one, and what is kept instead?

Exercise 7. What does uplevel 1 $body buy, and what breaks without it?

Exercise 8. Why time the failure path?

Exercise 9. Why is the share column more useful than absolute milliseconds?

Exercise 10. Why is the failed step kept in the table?

Exercise 11. A flow's steps total 20 minutes and its wall clock is 35. What is the other 15, and how do you see it?

Exercise 12. Why log the step name on both the start and the end line?

Answers.

1. Because clock seconds returns whole seconds, so the difference counts second boundaries crossed between the two readings rather than time elapsed.

2. 900 ms from …07.95 to …08.85 crosses one boundary, so the readings differ by 1. 400 ms from …08.10 to …08.50 crosses none, so they are equal and the difference is 0.

3. That the answer depends on where in the second the step started, not on how long it took — so it is not a measurement.

4. Because it under-reports most of the time and occasionally over-reports, so the bias does not cancel.

5. Because a timestamp is a point in time to one-second resolution, which is what it returns. It is only differences that are wrong.

6. Because +0.600s answers "how far into the run did this happen", and it lets two runs be diffed line by line. The wall-clock start is recorded once in the header.

7. It runs the step's body in the caller's scope, so a step can read and set the caller's variables. Without it the wrapper is a sealed box and every step needs its state threaded in and out.

8. Because a step that starts failing after twenty minutes is exactly the case you want the duration for, and a wrapper that times only successes loses it.

9. Because absolute times rise when the machine is busy, while the share is stable — so a step whose share grew is a real change and everything slowing together is a loaded machine.

10. Because a step that vanishes when it fails is unaccounted for, and the total then describes a different flow from the one that ran.

11. Time outside any step wrapper — files read between steps, waiting, reports written elsewhere. Log the run's own elapsed time next to the step total and the gap is visible.

12. Because a log truncated by a crash still names the step that was running, which is the most useful single fact about a run that died.

Remember.

A difference of clock seconds counts boundaries crossed, not elapsed time. 900 ms reads as 1s; 400 ms reads as 0s.
Six identical 300 ms steps measured 0 0 0 1 0 0 — the answer depends on clock phase, so it is not a measurement.
The bias does not cancel, so averaging does not rescue it.
Use clock milliseconds for durations and clock seconds for timestamps. Both are in 8.5.
Stamp log lines with elapsed time, not wall clock — it answers the question you are asking and lets two runs be diffed. Keep the wall-clock start in the header.
uplevel 1 $body lets a timing wrapper run a step in the caller's scope.
Time the failure path, and keep the failed step in the table at 0 ms.
Report the share, not only the duration — shares are stable where absolute times are not.
Derive the total from the rows, and note that it excludes time between steps.
Wall clock is not CPU time, and one run is a sample.
Log the step name on both start and end, put a level on every line, and flush each one.

Where this fits

Part of the Tcl curriculum.