Hangs and Timeouts

Part II · Module 29 · Chapter 29.5 · Hangs and Timeouts

Chapter 29.4 classified twelve runs and two of them had no verdict at all. This chapter is about those two: the run that never finished, and the run that finished without saying so. They are not the same thing, and neither is a failure in the sense the other chapters have meant.

1. Three Shapes, Not Two

The expectation is a binary: a job either makes progress or it is stuck. Measured, there are three.

Shape one: infinite progress. A testbench waiting for a condition that will never hold, while the clock keeps running:

module tb_hang;
  logic clk = 0, rst_n = 0, ready = 0;
  integer cycles = 0;
  always #5 clk = ~clk;
  always @(posedge clk) begin
    cycles = cycles + 1;
    if (cycles % 2000 == 0) $display("TB  progress: %0d cycles @ %0t", cycles, $time);
  end
  initial begin
    repeat (2) @(posedge clk); rst_n = 1;
    $display("TB  waiting for ready");
    wait (ready === 1'b1);          // never asserted: the hang
    $display("TB  TEST PASSED");
    $finish;
  end
endmodule

$ run-timeout 5 -- vvp logs/hang.vvp > logs/hang.log 2>&1
$ echo "rc=$?"
rc=124
$ grep -c . logs/hang.log
4872
$ tail -1 logs/hang.log
TB  progress: 9742000 cycles @ 97419995

9.7 million simulated cycles in five seconds, and 4,872 lines of output. This run was not stuck at all — it was working extremely hard on something that could never complete. That matters because every instinct for diagnosing a stuck process (is it blocked on I/O, is it waiting on a lock) is the wrong instinct here.

Shape two: event starvation. A testbench whose clock is driven from an initial block that ends:

module tb_stall;
  logic clk = 0, ready = 0;
  initial begin
    $display("TB  starting");
    repeat (4) begin #5 clk = ~clk; end    // a few edges, then nothing
    $display("TB  waiting for ready (no further events will occur)");
    wait (ready === 1'b1);
  end
endmodule

$ run-timeout 5 -- vvp logs/stall.vvp > logs/stall.log 2>&1
$ echo "rc=$?"
rc=0
$ grep -c . logs/stall.log
2
$ cat logs/stall.log
TB  starting
TB  waiting for ready (no further events will occur)

Shape three is a normal run: a verdict, and rc=0. Which means shapes two and three are indistinguishable by exit status, and separated only by whether the log contains a verdict line.

2. The Discriminator Between Shapes One and Two

Shapes one and two both look like "it is not finishing". The difference is measurable in two seconds:

$ ( vvp logs/hang.vvp > logs/grow.log 2>&1 ) & sleep 1
$ a=$(wc -c < logs/grow.log); sleep 2; b=$(wc -c < logs/grow.log)
$ printf 'infinite-progress run: %s -> %s bytes over 2 s (delta %s)\n' "$a" "$b" "$((b-a))"
infinite-progress run: 40960 -> 122880 bytes over 2 s (delta 81920)

$ ( vvp logs/stall.vvp > logs/grow2.log 2>&1 ) & sleep 1
$ c=$(wc -c < logs/grow2.log); sleep 2; d=$(wc -c < logs/grow2.log)
$ printf 'starved run:           %s -> %s bytes over 2 s (delta %s)\n' "$c" "$d" "$((d-c))"
starved run:           66 -> 66 bytes over 2 s (delta 0)
$ pgrep -f 'stall.vvp' | wc -l
       0

81,920 bytes against 0 — and in the starved case the process is already gone. So the triage is:

The middle row is worth keeping even though this chapter does not produce it: a simulator blocked on a licence check, an NFS stall or a full disk is alive and silent, and that is a different investigation from either of the measured shapes.

3. The Timeout This Machine Does Not Have

$ command -v timeout gtimeout || echo "neither is installed"
neither is installed

GNU coreutils provides timeout; macOS does not ship it, and a great many engineering servers do not have it either. So it has to be built, and the interesting part is the exit-status contract:

#!/bin/bash
# run-timeout SECONDS -- CMD...   There is no timeout(1) on this machine.
# Exit status: the command's, or 124 if it had to be killed (GNU's convention).
set -u
secs=${1:?usage: run-timeout SECONDS -- CMD...}; shift
[ "${1:-}" = "--" ] && shift
[ $# -gt 0 ] || { echo "run-timeout: no command" >&2; exit 2; }

"$@" & cmd=$!
( sleep "$secs"; kill -0 "$cmd" 2>/dev/null && kill -TERM "$cmd" 2>/dev/null ) & watchdog=$!

wait "$cmd" 2>/dev/null; rc=$?
# if the watchdog is still alive, the command finished first; if it is gone, it fired
if kill -0 "$watchdog" 2>/dev/null; then
  kill -TERM "$watchdog" 2>/dev/null; wait "$watchdog" 2>/dev/null
  exit "$rc"
else
  exit 124
fi

Proven in all three directions, because a timeout that only ever reports one outcome is not a timeout:

$ run-timeout 10 -- vvp logs/ok.vvp > logs/fast.log 2>&1 ; echo "rc=$?"
rc=0
$ run-timeout 5 -- vvp logs/hang.vvp > logs/hang.log 2>&1 ; echo "rc=$?"
rc=124
$ run-timeout 10 -- vvp /no/such.vvp > logs/nofile.log 2>&1 ; echo "rc=$?"
rc=255

Success passes through as 0, the hang gives 124, and a genuine failure inside the limit passes through as 255 rather than being flattened into 124. That third case is the one most hand-rolled timeouts get wrong, and it matters because "the job timed out" and "the job failed in two seconds" lead to different investigations.

Three implementation details are load-bearing.

124 is GNU timeout's documented convention for "the command timed out". Using the same number means a flow that already distinguishes 124 keeps working, and anybody reading the status knows what it means without reading your script.

kill -0 sends no signal; it only tests whether the process exists and whether you may signal it. That is how the watchdog avoids killing a recycled PID, and how the parent distinguishes "the watchdog is still waiting" from "the watchdog fired and exited".

The watchdog is killed on the success path. Without that, a fast command leaves a sleep running for the full duration, and a regression that launches two thousand jobs leaves two thousand sleeping processes behind.

4. Finding the Last Thing a Run Actually Did

For shape one, the last progress line is the most useful piece of evidence in the log:

$ tail -1 logs/hang.log
TB  progress: 9742000 cycles @ 97419995

A cycle count and a simulated time. Both are needed: the time places a waveform window (Chapter 27.6), and the cycle count compared against a passing run's final count tells you whether the run got further than usual or stopped early.

For shape two there is no progress line, and the question becomes what the last thing it said was:

$ tail -2 logs/stall.log
TB  starting
TB  waiting for ready (no further events will occur)

Which is the single reason to make a testbench announce what it is about to wait for. A wait with no preceding $display leaves a log that ends on whatever happened before it, and the investigation starts from nothing.

That is a design obligation rather than an analysis technique, and it is cheap:

// before any unbounded wait, say what is being waited for
$display("TB  waiting for %0s at %0t", "ready", $time);
wait (ready === 1'b1);

Better still, do not write an unbounded wait at all:

// a wait with its own bound, which turns a hang into a reported failure
fork
  begin wait (ready === 1'b1); end
  begin #10000; $display("TB  ERROR timeout waiting for ready"); errors = errors + 1; end
join_any
disable fork;

A testbench that bounds its own waits converts shape one and shape two into ordinary failures with verdicts — which is the only fix that produces a usable regression report, because an external timeout can tell you that a run did not finish and never where.

5. A Detector

#!/bin/bash
# hangcheck RUNDIR... — classify runs that produced no verdict.
set -u
[ $# -gt 0 ] || { echo "usage: hangcheck RUNDIR..." >&2; exit 2; }
bad=0
printf '%-16s %-13s %-9s %s\n' RUN STATE LINES 'LAST LINE'
for d in "$@"; do
  log="$d/run.log"
  if [ ! -r "$log" ]; then
    printf '%-16s %-13s %-9s %s\n' "$(basename "$d")" NO-LOG - -; bad=1; continue
  fi
  n=$(grep -c . "$log")
  last=$(tail -1 "$log" | cut -c1-40)

  if grep -qE 'TEST (PASSED|FAILED)|Report Summary' "$log"; then
    state=FINISHED
  else
    # no verdict. Growing, alive, or over?
    a=$(wc -c < "$log"); sleep 2; b=$(wc -c < "$log")
    if [ "$b" -gt "$a" ];                        then state=PROGRESSING
    elif pgrep -f "$(basename "$d")" >/dev/null 2>&1; then state=BLOCKED
    else                                              state=NO-VERDICT
    fi
    bad=1
  fi
  printf '%-16s %-13s %-9s %s\n' "$(basename "$d")" "$state" "$n" "$last"
done
exit $bad

$ hangcheck regress/pass_s1 regress/killed regress/badcompile
RUN              STATE         LINES     LAST LINE
pass_s1          FINISHED      2         src/tb_ok.sv:24: $finish called at 75 (1
killed           NO-VERDICT    1257      TB  progress: 2512000 cycles @ 251199
badcompile       NO-VERDICT    1         (no executable; compile failed)
$ echo $?
1

Two details in that output are worth noticing. pass_s1's last line is the $finish notice rather than its verdict, because the simulator appends its own line after the testbench's — so the last line of a log is not the verdict line, and a report that shows "the last line" shows the tool's epilogue. The STATE column is derived from a search, not from the tail, which is why it is right.

And killed's cycle count is not reproducible: it depends on where the kill happened to land. Re-running the fixture gives a different number every time. That is correct and worth stating, because a reader comparing their own output to this one should expect that column to differ — and because it is the reason a progress figure is only meaningful relative to a passing run's final count, never as an absolute.

Three decisions.

It only measures growth for runs with no verdict. A finished run's log does not need a two-second sample, and sampling every run in a regression of two thousand would add an hour.

BLOCKED is a distinct state even though this chapter did not produce one. A silent, living process is the third row of §2's table and a different investigation; collapsing it into NO-VERDICT would hide it.

It prints the last line. For killed that is TB progress: 2446000 cycles @ 2445999 — which immediately says the run was shape one, had reached 2.4 million cycles, and was making progress when it died. That is the difference between a usable report and the word "timeout".

Practice

1. Write a testbench that waits on a condition never asserted, with a clock still running, and run it under a five-second limit. Record the status, the line count and the last line.
2. Compute the simulated cycles per wall-clock second from that run.
3. Write a testbench whose clock stops because the driving block ended, and run it with no limit at all. Record the status and the elapsed time.
4. Confirm it printed no verdict and explain why the simulator exited successfully.
5. Decide which of the two is more dangerous in a regression, and why.
6. Measure log growth over two seconds for both shapes.
7. Check whether timeout exists on your own machine, and on the compute server you actually use.
8. Write run-timeout and prove all three outcomes: success, timeout, and a failure inside the limit.
9. Remove the watchdog kill on the success path, launch fifty fast jobs, and count the leftover processes.
10. Wrap the command in ( … ) & without exec, time it out, and check whether the tool actually died.
11. Add a $display before every unbounded wait in a testbench and compare the log of a hang before and after.
12. Convert an unbounded wait into a bounded one with fork/join_any, and confirm the hang becomes a reported failure with a verdict.
13. Write hangcheck and run it over a regression containing a killed run.

Check Your Understanding

1. What are the three shapes, and which two are indistinguishable by exit status?
2. How many simulated cycles did the "hang" complete in five seconds, and why does that matter for diagnosis?
3. Why does a simulation with no remaining events exit zero?
4. Why is the starved run more dangerous than the hanging one?
5. What is the discriminator between shapes one and two?
6. What does the third row of the triage table describe, and why keep it?
7. Why use 124 for a timeout?
8. What does kill -0 do, and what two things does it enable here?
9. Why kill the watchdog on the success path?
10. Why does the timeout fail to stop a simulator wrapped in ( … ) &?
11. Why is a $display before an unbounded wait worth the line?
12. What does a bounded wait convert a hang into?
13. Why does hangcheck sample growth only for runs with no verdict?

6. Remember

• Three shapes, not two: infinite progress, event starvation, and a normal run.
• Event starvation exits 0 in under a second with no verdict. A status check calls it a pass and a timeout never fires.
• The hang was not stuck — 9.7 million cycles in five seconds. Diagnose it as overwork, not as a block.
• Log growth is the discriminator: 81,920 bytes in two seconds against 0.
• Keep a BLOCKED state for a silent living process — a licence, an NFS stall, a full disk.
• There is no timeout here. Build one, use 124, and pass a genuine failure's status through instead of flattening it.
• kill -0 tests existence without signalling, and kill the watchdog on the success path or you leak one sleep per job.
• The timeout only reaches the direct child, and only if $! is the tool rather than a subshell.
• Announce what a wait is waiting for, and prefer a bounded wait — which turns a hang into a reported failure with a verdict.
• Sample growth only for runs with no verdict.

7. What Is Next

The runs that did not finish are accounted for. Chapter 29.6 turns to the runs that finished and lied — the warning classes that indicate a real design problem, starting from the measurement that the simulator issued no warnings at all about an uninitialised value poisoning every expression it touched.