A green regression, then a power fix

dbglab's regression is clean: someone has fixed all five of its known bugs (in a scratch copy here, one commit; the fixes are the subject of other lessons). Then a power-reduction pass lands one small commit in the peripheral's asynchronous FIFO. The next regression has six red lines, and the worst of them is a run that took 2.9 seconds instead of 0.05 and ended with TIMEOUT: still running after 400000 cycles. No WATCHDOG line at all.

Nothing says what is stuck, or even that anything is. Where do you start, and in what order?

What people usually do, and why it fails

A TIMEOUT with no watchdog reads like "slow", so people raise +MAX_CYCLES, or open a waveform of 400,000 cycles that is mostly a CPU reading registers. Both skip the question this part starts with: is anything making progress? Until that is answered, there is no wait-for table to build.

The method, in order

1. Report and classify. Group the failures by message, then count activity and progress per agent (hang, livelock or starvation).

2. Snapshot and table. Dump after progress stopped; apply the wait-for rules (who is waiting for whom).

3. Read the graph. A cycle, a chain that ends, or something stranger (finding the cycle).

4. Localise. Find the first cycle the trap was closed, and the signals that disagree.

5. Hypothesise and test with an experiment that changes only the suspect and could fail.

6. Fix, prove, prevent. The same command passes, a sweep is clean, and a check fires near the cause next time (watchdogs and hang detectors).

Do it

Report: three messages, one commit

$ git log --oneline -3
1e04860 periph: clock the FIFO's read-pointer synchroniser only on writes
2b3242e scratch: the five known fixes
49c5f04 tb: report cycles and sim time in the PASS line
$ tb/regress.sh icarus 1 2 3 | grep FAIL
periph_stream            seed 1      FAIL
periph_stream            seed 2      FAIL
periph_stream            seed 3      FAIL
dma_burst_backpressure   seed 1      FAIL
dma_burst_backpressure   seed 2      FAIL
dma_burst_backpressure   seed 3      FAIL
$ for t in periph_stream dma_burst_backpressure; do for s in 1 2 3; do tb/run.sh $t $s | grep FAIL; done; done
FAIL test=periph_stream seed=1 cycle=687: peripheral STATUS when drained: read 00003004 = 00000001, expected 00000000
FAIL test=periph_stream seed=2 cycle=15310: STREAM: peripheral FIFO still full after 5000 polls
FAIL test=periph_stream seed=3 cycle=15163: STREAM: peripheral FIFO still full after 5000 polls
FAIL test=dma_burst_backpressure seed=1 cycle=400000: TIMEOUT: still running after 400000 cycles
FAIL test=dma_burst_backpressure seed=2 cycle=400000: TIMEOUT: still running after 400000 cycles
FAIL test=dma_burst_backpressure seed=3 cycle=400000: TIMEOUT: still running after 400000 cycles

Three signatures, all from tests that use the peripheral FIFO, all after one commit. One is a wrong value: STATUS says full (bit 0) after the FIFO was drained. Keep it; it will test the hypothesis later. Verilator gives the same six failures. The rest of this lesson follows dma_burst_backpressure seed 1, the hang.

Classify: activity without progress

A probe counts, per 10,000-cycle window, the CPU's bus responses (activity), its writes that turn the sink on and off, the DMA's handshakes and the words leaving the stream (progress):

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

// not-run: needs dbglab's sources and bench; compile it next to them (command in the Evidence box)
// progress_probe: activity and progress per agent, per window of +WIN=<n> bus cycles (default
// 10000). Activity: CPU bus responses. Progress: DMA handshakes and words out of the stream.
// It only reads the design and the bench.
`timescale 1ns/1ps
module progress_probe;
  int unsigned win, cpu_rsp = 0, dma_hs = 0, words0 = 0, ctrl_wr = 0;
  initial if (!$value$plusargs("WIN=%d", win)) win = 10000;
  always @(posedge dbglab_tb.clk) begin
    #0.5;
    if (dbglab_tb.dut.m_rvalid[0]) cpu_rsp++;
    if (dbglab_tb.dut.m_valid[1] && dbglab_tb.dut.m_ready[1]) dma_hs++;
    if (dbglab_tb.dut.s_req[2] && dbglab_tb.dut.s_write && dbglab_tb.dut.s_addr[11:0] == 12'h008) ctrl_wr++;
    if (dbglab_tb.cycle % win == 0 && dbglab_tb.cycle != 0) begin
      $display("WINCHK cycles %6d-%6d: cpu responses %5d  sink on/off writes %4d | dma handshakes %3d  stream words %3d  dma=%s",
               dbglab_tb.cycle - win + 1, dbglab_tb.cycle, cpu_rsp, ctrl_wr, dma_hs,
               dbglab_tb.stream_words - words0, dbglab_tb.dut.u_dma.state.name());
      cpu_rsp = 0; dma_hs = 0; ctrl_wr = 0; words0 = dbglab_tb.stream_words;
    end
  end
endmodule

$ iverilog -g2012 -Wno-timescale -I tb -o build/probe.vvp $(grep -v '^#' rtl/files.f) tb/bus_rules.sv tb/dbglab_tb.sv progress_probe.sv
$ vvp -n build/probe.vvp +TEST=dma_burst_backpressure +SEED=1 +MAX_CYCLES=60000 | grep -E "^(dbglab|PASS|FAIL|[A-Z]+CHK)"
dbglab: test=dma_burst_backpressure seed=1
WINCHK cycles      1- 10000: cpu responses   780  sink on/off writes  372 | dma handshakes  36  stream words  16  dma=WAIT
WINCHK cycles  10001- 20000: cpu responses   756  sink on/off writes  378 | dma handshakes   0  stream words   0  dma=WAIT
...
WINCHK cycles  50001- 60000: cpu responses   780  sink on/off writes  390 | dma handshakes   0  stream words   0  dma=WAIT
FAIL test=dma_burst_backpressure seed=1 cycle=60000: TIMEOUT: still running after 60000 cycles

• The CPU is busy: about 760 responses and 380 sink writes per window, for ever. This is the test's driver loop: read STATUS, see the FIFO full, turn the sink on for a while, turn it off, repeat.

• The DMA and the stream have stopped: 16 words out, then zero handshakes and zero words, with the DMA in WAIT. Progress is zero; activity is not.

• Why no WATCHDOG: the bench counts any bus response as progress, so the polling CPU keeps it quiet. The same probe on dbglab's B2 deadlock shows zeros everywhere, which is why that one tripped the watchdog. This is a hang of the DMA behind a polling CPU, not a livelock: the CPU is not retrying the DMA's work, it is watching it.

The table: a contradiction

$ DUMP=1 tb/run.sh dma_burst_backpressure 1 icarus +MAX_CYCLES=12000
dbglab: test=dma_burst_backpressure seed=1
FAIL test=dma_burst_backpressure seed=1 cycle=12000: TIMEOUT: still running after 12000 cycles
$ python3 waitfor.py c7.vcd
at 120005 ns (bench cycle 12001, stream words 16)
agent   evidence                           waits for    what
CPU     valid=0                            -            nothing (idle)
FABRIC  grant=00 busy=0                    -            nothing (free or issuing)
DMA     state=WAIT paced=1 dreq=0          FIFO         dreq (a free FIFO entry)
FIFO    full=1                             SINK         the sink to take a word
SINK    sink_en=1 empty=1                  FIFO         a word in the FIFO
from DMA: DMA -> FIFO -> SINK -> FIFO: CYCLE

The rules report a cycle, but read its two edges: the FIFO waits for the sink to take a word and the sink waits for a word in the FIFO. Both cannot be true of one FIFO. The rules took full from the write side and empty from the read side, and the two sides disagree: the write side says full, the read side says empty. The sink is enabled and the bus is free. This is not a cycle of resources; it is one agent's stale picture of another. The search now is how does the write side learn what the read side did?

Localise: the read pointer never arrives

The write side computes wfull from its synchronised copy of the read pointer. A probe prints both sides' pointers every cycle, and checks for the contradiction itself:

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
30
31
32
33
34
35

// not-run: needs dbglab's sources and bench; compile it next to them (command in the Evidence box)
// fifo_probe: the two views of the peripheral FIFO, one line per bus cycle from +FROM to +TO.
// wptr and rptr are binary pointers (5 bits: 16 entries plus a wrap bit). "rptr seen by write"
// is the write side's synchronised copy of the read pointer, which is what wfull is computed
// from. VIEWCHK: the first cycle in which the write side says full while the read side has been
// empty for more than 16 bus cycles. It only reads the design.
`timescale 1ns/1ps
module fifo_probe;
  int unsigned from_c, to_c, both = 0;
  bit told = 0;
  function automatic logic [4:0] g2b(input logic [4:0] g);
    for (int i = 3; i >= 0; i--) g[i] = g[i] ^ g[i + 1];
    return g;
  endfunction
  initial begin
    if (!$value$plusargs("FROM=%d", from_c)) from_c = 1;
    if (!$value$plusargs("TO=%d", to_c)) to_c = 0;
    if (to_c >= from_c) $display("cycle  winc wfull wptr  rptr-seen-by-write | rptr rempty sink_en");
  end
  always @(posedge dbglab_tb.clk) begin
    #0.5;
    if (dbglab_tb.cycle >= from_c && dbglab_tb.cycle <= to_c)
      $display("%5d   %b    %b    %2d        %2d           |  %2d    %b      %b", dbglab_tb.cycle,
        dbglab_tb.dut.u_per.u_fifo.winc, dbglab_tb.dut.u_per.u_fifo.wfull, dbglab_tb.dut.u_per.u_fifo.wbin,
        g2b(dbglab_tb.dut.u_per.u_fifo.rptr_sync_w), dbglab_tb.dut.u_per.u_fifo.rbin,
        dbglab_tb.dut.u_per.u_fifo.rempty, dbglab_tb.dut.u_per.sink_en_p);
    both = (dbglab_tb.dut.u_per.u_fifo.wfull && dbglab_tb.dut.u_per.u_fifo.rempty) ? both + 1 : 0;
    if (both > 16 && !told) begin
      told = 1;
      $display("VIEWCHK cycle=%0d: write side full, read side empty for %0d cycles (wptr=%0d, rptr=%0d, seen by write=%0d)",
               dbglab_tb.cycle, both, dbglab_tb.dut.u_per.u_fifo.wbin, dbglab_tb.dut.u_per.u_fifo.rbin,
               g2b(dbglab_tb.dut.u_per.u_fifo.rptr_sync_w));
    end
  end
endmodule

$ vvp -n build/probe.vvp +TEST=dma_burst_backpressure +SEED=1 +MAX_CYCLES=12000 +FROM=1 +TO=400
cycle  winc wfull wptr  rptr-seen-by-write | rptr rempty sink_en
  209   1    0    14         0           |   0    0      0
  210   0    0    15         0           |   0    0      0
  215   1    0    15         0           |   0    0      0
  216   0    1    16         0           |   0    0      0
...
  236   0    1    16         0           |   1    0      1
  243   0    1    16         0           |   2    0      1
...
  354   0    1    16         0           |  15    0      1
  362   0    1    16         0           |  16    1      0
...
$ iverilog -g2012 -Wno-timescale -I tb -o build/probe.vvp $(grep -v '^#' rtl/files.f) tb/bus_rules.sv tb/dbglab_tb.sv fifo_probe.sv
$ vvp -n build/probe.vvp +TEST=dma_burst_backpressure +SEED=1 +MAX_CYCLES=12000 | grep -E "^(dbglab|PASS|FAIL|[A-Z]+CHK)"
dbglab: test=dma_burst_backpressure seed=1
VIEWCHK cycle=378: write side full, read side empty for 17 cycles (wptr=16, rptr=16, seen by write=0)
...

• Cycles 209 to 216: the DMA writes the 16th word with the sink off. The write side sees 16 written and 0 read: full, correctly.

• From cycle 236: the CPU has turned the sink on and the read pointer climbs, 1, 2, ... 16. The write side's copy stays at 0 the whole time, and winc is 0 on every line: nobody writes, because the FIFO is full.

• Cycle 362: the read side is empty; the write side still says full. Sixteen cycles later the view check fires. The first wrong cycle is 236, the first read the write side never learns about.

A synchroniser that does not move while its input does is not being clocked. The commit says exactly that:

$ git show 1e04860 -- rtl/async_fifo.sv
...
    The write side of the async FIFO needs the read pointer only to
    decide wfull when it writes. Its two-flop synchroniser toggled every
    bus cycle; it is now enabled by winc. Saves the clock power of ten
    flops while the peripheral is idle.
...
-  ptr_sync #(AW + 1) u_r2w (.clk(wclk), .rst_n(wrst_n), .d(rgray), .q(rptr_sync_w));
+  // The write side needs the read pointer only to decide wfull for a write, so its synchroniser
+  // is clocked only on writes: no toggling while the bus side is idle.
+  ptr_sync_en #(AW + 1) u_r2w (.clk(wclk), .rst_n(wrst_n), .en(winc), .d(rgray), .q(rptr_sync_w));
...

The reasoning in the message is half right: the write side needs the read pointer when it decides whether it may write. But while the FIFO is full it never writes, so winc never rises, so the news that space has appeared never arrives. The wait-for graph has a real cycle after all, one the rules did not model: the DMA waits for `dreq`, `dreq` waits for the synchroniser, the synchroniser waits for `winc`, `winc` waits for the DMA.

Hypothesise and test: an experiment that could fail

Hypothesis: the hang is only the stale copy. Prediction: if the synchroniser is made to take one sample of the read pointer during the hang, wfull drops, the DMA resumes, and it hangs again the next time the FIFO fills. If the FIFO were really full, nothing would change. The wrong value in periph_stream seed 1 fits too: STATUS reads wfull, which stays 1 after the drain.

The first version of the experiment forced the synchroniser's en port high for four cycles. It failed with STREAM: word #16 = 00000005, expected fe825ae4, because en is connected to winc, and forcing a port forces the net it is connected to: the experiment wrote four bus words into the FIFO, one of them the CPU's CTRL value 0x05. The probe below instead loads the two synchroniser flops with the read pointer, which is what one enabled clock edge would do:

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

// not-run: needs dbglab's sources and bench; compile it next to them (command in the Evidence box)
// kick_probe: the experiment. At bus cycle +KICK=<c> it loads both flops of the write side's
// read-pointer synchroniser with the read pointer, as one enabled clock edge would, and lets go
// after 4 cycles. If the hang is a stale copy of the read pointer, the DMA must start writing
// again; if the FIFO were really full, nothing would change.
`timescale 1ns/1ps
module kick_probe;
  int unsigned kick;
  initial begin
    if (!$value$plusargs("KICK=%d", kick)) kick = 0;
    if (kick != 0) begin
      wait (dbglab_tb.cycle == kick);
      force dbglab_tb.dut.u_per.u_fifo.u_r2w.q1 = dbglab_tb.dut.u_per.u_fifo.rgray;
      force dbglab_tb.dut.u_per.u_fifo.u_r2w.q  = dbglab_tb.dut.u_per.u_fifo.rgray;
      repeat (4) @(posedge dbglab_tb.clk);
      release dbglab_tb.dut.u_per.u_fifo.u_r2w.q1;
      release dbglab_tb.dut.u_per.u_fifo.u_r2w.q;
      $display("KICKCHK cycle=%0d: synchroniser loaded with the read pointer for 4 cycles; wfull=%b", dbglab_tb.cycle,
               dbglab_tb.dut.u_per.u_fifo.wfull);
    end
  end
endmodule

$ iverilog -g2012 -Wno-timescale -I tb -o build/kick.vvp $(grep -v '^#' rtl/files.f) tb/bus_rules.sv tb/dbglab_tb.sv kick_probe.sv progress_probe.sv
$ vvp -n build/kick.vvp +TEST=dma_burst_backpressure +SEED=1 +KICK=5000 +WIN=2500 +MAX_CYCLES=20000 | grep -E "^(dbglab|PASS|FAIL|[A-Z]+CHK)"
dbglab: test=dma_burst_backpressure seed=1
WINCHK cycles      1-  2500: cpu responses   216  sink on/off writes   90 | dma handshakes  36  stream words  16  dma=WAIT
WINCHK cycles   2501-  5000: cpu responses   192  sink on/off writes   96 | dma handshakes   0  stream words   0  dma=WAIT
KICKCHK cycle=5003: synchroniser loaded with the read pointer for 4 cycles; wfull=0
WINCHK cycles   5001-  7500: cpu responses   199  sink on/off writes   85 | dma handshakes   35  stream words  19  dma=WAIT
WINCHK cycles   7501- 10000: cpu responses   187  sink on/off writes   94 | dma handshakes   0  stream words   0  dma=WAIT
...
FAIL test=dma_burst_backpressure seed=1 cycle=20000: TIMEOUT: still running after 20000 cycles

Exactly as predicted: wfull drops at the kick, the DMA makes 35 handshakes and 19 more words leave the stream, then the FIFO fills again and the same hang returns. The hypothesis survived a test it could have failed.

Fix and prove

Two fixes, each in its own clone. A revert, which gives up the saving; or keep the gate but leave the synchroniser running while the FIFO is full, the one state in which the write side waits for news: .en(winc || wfull).

$ tb/regress.sh icarus 1 2 3 | tail -1          # either fix
0 failing run(s)
$ for s in $(seq 1 60); do tb/run.sh random $s | grep FAIL; done
$ tb/run.sh dma_burst_backpressure 1
dbglab: test=dma_burst_backpressure seed=1
PASS test=dma_burst_backpressure seed=1 cycles=772 time=7716 ns
$ tb/regress.sh verilator 1 2 3 | tail -1       # the winc || wfull fix
0 failing run(s)

Both pass the regression, 60 random seeds and the hang test in the same 772 cycles. The second still stops the synchroniser whenever the FIFO has space and nobody writes; a stale copy there is safe, because it can only make the FIFO look fuller than it is.

Prevent: checks that fire near the cause

$ iverilog -g2012 -Wno-timescale -I tb -o build/det.vvp $(grep -v '^#' rtl/files.f) tb/bus_rules.sv tb/dbglab_tb.sv hang_det.sv det_probe.sv
$ vvp -n build/det.vvp +TEST=dma_burst_backpressure +SEED=1 +MAX_CYCLES=12000 | grep -E "^(HANGDET|FAIL)"
HANGDET cycle=294: hung=10 first=DMA at ts=289; snap: grant=00 lock=10 dma_state=6 dreq=0 full=1 sink_en=1
FAIL test=dma_burst_backpressure seed=1 cycle=12000: TIMEOUT: still running after 12000 cycles

• The hang detector from the previous lesson names the DMA port at cycle 294: in WAIT with dreq=0, the FIFO full, the sink on and the grant free. (lock=10 is the DMA's own lock output, which the fixed fabric ignores.) It is silent on both fixes over all seven tests, seeds 1 to 3.

• The view check is the contradiction as an assertion: full on the write side while the read side has been empty for more than 16 cycles. It fired at cycle 378 here, at 444 and 296 in periph_stream seeds 2 and 3, and is silent on both fixes over the same 21 runs. It belongs next to every asynchronous FIFO, as a bound checker.

• The bench's watchdog counted the polling CPU as progress; counting progress per agent, as the classify step did, would make it fire too.

What the evidence says

Each step did one job. Classification turned a TIMEOUT into the DMA has stopped behind a busy CPU; the table found two views of one FIFO in contradiction; the pointer trace localised it to a synchroniser that does not move, and the commit said why. An experiment that could have failed confirmed it. Two fixes passed the same proof, and two checks now fire within 200 cycles of the trap closing, where the bench needed 400,000 cycles to say anything.

Traps

Related topics

• Part 7 · Hangs and Deadlocks

• Case study: the deadlock under back-pressure

• RTL: CDC handshakes

• CDC/RDC: debug and case studies

• Part 7: hangs and deadlocks