Ten hours, no message

The overnight regression should take forty minutes. In the morning one job has been running for ten hours, until the farm's wall-clock limit killed it. Its log has one line, the test name and seed. No FAIL, no cycle, no hint of what was stuck. Worse, the rest of the regression waited behind it, so half the results are missing too.

Something in that test stopped making progress early, maybe in its first microsecond of simulated time. Why did it take ten hours to find out, and why does the log say nothing?

What people usually do, and why it fails

Many benches rely on the farm's wall-clock kill, or on one global timeout set "high enough to be safe". A global timeout only knows how long the test has run, not whether anything is happening, so it must be longer than the longest healthy test, and every hang costs that much. When it fires, all it can say is "still running".

The opposite mistake is a tight global timeout that kills healthy long tests. Then someone raises it, and the next hang costs more. Both are the same error: using a clock to detect a lack of progress.

The method: two guards, sized from measurements

1. A global timeout caps the whole test: a ceiling in cycles, sized from the longest legal run of that test with a generous margin. It catches anything the watchdog misses, including a livelock.

2. A progress watchdog fails when nothing useful has happened for N cycles. N is sized from the longest legal quiet stretch, measured, times a margin.

3. Define progress as finished work: a handshake that completed, a response that arrived, a word delivered. Do not count activity, such as clock edges or a bench polling a register.

4. Give long waits their own limit, such as a maximum number of status polls, with a message that names the wait.

5. Make the FAIL line start the debug. Print the cycle and the state of every interface that could be waiting, as in the deadlock case study.

6. Count cycles, not seconds. Wall time changes with the machine and the simulator; a cycle count gives the same failure everywhere.

7. Never raise a limit to make a test pass until you know why it fired.

The picture: the same hang, three guards

All three bars are the same hang. Only the first one is useful: it arrives fastest and its message names the agent that was waiting.

Do it: dbglab's two guards

The guards in the bench

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16

// snippet: tb/dbglab_tb.sv, lines 60-61 and 284-296
  always @(posedge clk)
    if (cycle >= max_cycles) fail($sformatf("TIMEOUT: still running after %0d cycles", max_cycles));
  ...
  int unsigned last_progress = 0;
  int          wd_words = 0;
  always @(posedge clk)
    if (rst_n) begin
      if ((dut.m_valid & dut.m_ready) != 2'b00 || dut.m_rvalid != 2'b00 || stream_words != wd_words) begin
        last_progress = cycle;
        wd_words = stream_words;
      end
      else if (cycle - last_progress > WD_LIMIT)
        fail($sformatf("WATCHDOG: no bus or stream progress for %0d cycles; cpu_valid=%b cpu_ready=%b cpu_addr=%08h",
                       WD_LIMIT, cpu_valid, cpu_ready, cpu_addr));
    end

The global timeout is +MAX_CYCLES, 400,000 by default. Progress is a request accepted, a response, or a word out of the stream. WD_LIMIT is 2,000.

The watchdog on a real hang

$ /usr/bin/time -p tb/run.sh dma_burst_backpressure 1
dbglab: test=dma_burst_backpressure seed=1
FAIL test=dma_burst_backpressure seed=1 cycle=2165: WATCHDOG: no bus or stream progress for 2000 cycles; cpu_valid=1 cpu_ready=0 cpu_addr=00003008
real 0.05
...

The last progress was at cycle 165; the watchdog waited its 2,000 cycles and failed at 2165, in 0.05 seconds. The message already starts the hunt: the CPU is waiting (valid=1 ready=0) on a write to 0x3008.

The same hang with only a global timeout

In a scratch copy, set WD_LIMIT to 100,000,000 so the watchdog never fires:

$ /usr/bin/time -p tb/run.sh dma_burst_backpressure 1
dbglab: test=dma_burst_backpressure seed=1
FAIL test=dma_burst_backpressure seed=1 cycle=400000: TIMEOUT: still running after 400000 cycles
real 2.76
...
$ time tb/run.sh dma_burst_backpressure 1 icarus +MAX_CYCLES=20000000
dbglab: test=dma_burst_backpressure seed=1
FAIL test=dma_burst_backpressure seed=1 cycle=20000000: TIMEOUT: still running after 20000000 cycles
tb/run.sh dma_burst_backpressure 1 icarus +MAX_CYCLES=20000000  136.15s user 0.56s system 99% cpu 2:17.10 total

Same bug, 185 times later and with no detail; raise the cap "to be safe" and it takes over two minutes. On a design a thousand times bigger, the same arithmetic gives the ten-hour job from the scene.

Sizing the limits from measurements

How long can a healthy dbglab test go without progress? Measure it with a probe that uses the watchdog's own definition:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19

// not-run: needs dbglab's sources and bench; compile it next to them (command in the Evidence box)
// quiet_probe: measures the longest stretch with no bus or stream progress, using the
// watchdog's own definition of progress. It only reads the design and the bench.
`timescale 1ns/1ps
module quiet_probe;
  int unsigned last = 0, longest = 0, at = 0, words = 0;
  always @(posedge dbglab_tb.clk) begin
    #0.5;
    if (dbglab_tb.rst_n) begin
      if ((dbglab_tb.dut.m_valid & dbglab_tb.dut.m_ready) != 2'b00 || dbglab_tb.dut.m_rvalid != 2'b00
          || dbglab_tb.stream_words != words) begin
        if (dbglab_tb.cycle - last > longest) begin longest = dbglab_tb.cycle - last; at = dbglab_tb.cycle; end
        last = dbglab_tb.cycle;
        words = dbglab_tb.stream_words;
      end
    end
  end
  final $display("QUIET: longest stretch without progress = %0d cycles, ended at cycle %0d", longest, at);
endmodule

$ ../probes/run-probe.sh ../probes/quiet_probe.sv periph_stream 1 | grep -E "PASS|QUIET"
PASS test=periph_stream seed=1 cycles=687 time=6866 ns
QUIET: longest stretch without progress = 22 cycles, ended at cycle 449
$ ../probes/run-probe.sh ../probes/quiet_probe.sv random 2 | grep -E "PASS|QUIET"
PASS test=random seed=2 cycles=20526 time=205256 ns
QUIET: longest stretch without progress = 52 cycles, ended at cycle 3683
$ cd ../c14 && ../probes/run-probe.sh ../probes/quiet_probe.sv periph_power 1 | grep -E "PASS|QUIET"
PASS test=periph_power seed=1
QUIET: longest stretch without progress = 302 cycles, ended at cycle 393

The longest legal quiet stretch found is 302 cycles, while the sink is powered down in periph_power (run at commit 14, before that test's own bug). A limit of 2,000 is about 6.6 times that: room for a slower peripheral, small enough to report a hang in microseconds of simulated time. The global timeout gets the same treatment: healthy random runs end at about 18,000 to 21,000 cycles, so 400,000 is about 20 times the longest healthy test.

Too tight a cap fails healthy work, and the message looks just like a hang:

$ tb/run.sh random 1 icarus +MAX_CYCLES=10000
dbglab: test=random seed=1
FAIL test=random seed=1 cycle=10000: TIMEOUT: still running after 10000 cycles

Seed 1 passes at 19,972 cycles with the default cap. A TIMEOUT alone cannot tell a hang from a slow test; a watchdog can.

The polling trap

dbglab's watchdog counts any bus response as progress. What if the CPU is the one polling? In a scratch copy with B2 fixed, a test stops the sink, starts a paced 48-word copy into the peripheral and waits. The FIFO fills, the DMA waits for space forever, and the CPU reads STATUS again and again, every read a bus response:

$ /usr/bin/time -p tb/run.sh poll_hang 1
dbglab: test=poll_hang seed=1
FAIL test=poll_hang seed=1 cycle=60136: DMA run #1: STATUS.busy still set after 20000 polls
real 1.12
...
$ /usr/bin/time -p tb/run.sh poll_hang 1 icarus +NOLIMIT
dbglab: test=poll_hang seed=1
FAIL test=poll_hang seed=1 cycle=400000: TIMEOUT: still running after 400000 cycles
real 3.94
...

The global watchdog never fires in either run. What saves the first run is the bench's own limit on a wait (dma_wait gives up after 20,000 polls) with a message that names the DMA run. Remove that limit, as the second run does, and only the global timeout is left. Note that random's final while (r_active) r_poll_dma(); loop in dbglab has no such limit.

A small bench with both guards

The same two guards in a bench you can run anywhere. The engine sends len words and then pulses done, but it decides it is finished only when a word moves, so a zero-length job never ends. One job in 200 is empty.

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29

// copy_engine: after start, sends len words on a valid/ready port, then pulses done.
// The bug: done is decided only when a word is sent, so a zero-length job never ends.
module copy_engine (
  input  logic       clk, rst_n, start,
  input  logic [3:0] len,
  output logic       valid,
  input  logic       ready,
  output logic       done
);
  typedef enum logic [1:0] {IDLE, SEND, FIN} state_t;
  state_t     state;
  logic [3:0] sent, len_q;
  assign valid = (state == SEND) && (sent < len_q);
  always_ff @(posedge clk or negedge rst_n)
    if (!rst_n) begin
      state <= IDLE; sent <= '0; len_q <= '0; done <= 1'b0;
    end else begin
      done <= 1'b0;
      case (state)
        IDLE: if (start) begin state <= SEND; sent <= '0; len_q <= len; end
        SEND: if (valid && ready) begin
                sent <= sent + 4'd1;
                if (sent + 4'd1 == len_q) state <= FIN;   // only checked when a word moves
              end
        FIN:  begin done <= 1'b1; state <= IDLE; end
        default: state <= IDLE;
      endcase
    end
endmodule

$ iverilog -g2012 -o w.vvp wd_tb.sv
$ vvp -n w.vvp
PASS: seed=1 40 jobs, 265 words, 440 cycles
$ /usr/bin/time -p vvp -n w.vvp +SEED=4
FAIL seed=4 cycle=611: WATCHDOG: no word and no done for 200 cycles; job 32 len=0 state=SEND sent=0 valid=0
...
real 0.00
...
$ /usr/bin/time -p vvp -n w.vvp +SEED=4 +NOWD
FAIL seed=4 cycle=1000000: TIMEOUT: still running after 1000000 cycles
...
real 2.02
...

Read the watchdog line field by field. Job 32 has len=0, the engine sits in SEND with nothing sent and valid low, so no word can ever move: the bug is in that line. The TIMEOUT run reaches the same verdict about 1,600 times later and says only that it took too long. Verilator 5.048 prints the same lines and needs 0.20 s for the timeout run, a reminder that wall time depends on the simulator while cycles do not.

What the evidence says

On dbglab's deadlock and on the small bench, the watchdog turned a hang into a deterministic FAIL line at a known cycle, in a fraction of a second, with the state needed for the next step. That is what Reproduce needs from a hang: one command, a fixed failing cycle, and a message to start Observe from. The global timeout still earns its place, because the polling run shows a hang the watchdog cannot see.

Traps

Related topics

• Part 1 · Reproduce

• Case study: the deadlock under back-pressure

• Part 7: hangs and deadlocks

• The reproduction checklist