A repro in hand, and a meeting at three

Part 1's checklist left you a solid repro: tb/run.sh random 23 at HEAD fails every time with STREAM: word #41 = xxxxxxxx, expected 00000000 at cycle 2385. It fails in Icarus, passes in default Verilator, and passes at the commit before. At three o'clock someone will ask where the bug is. Which checks get you from the stream pins to one line of RTL, and how do you know when Localise is done?

What people usually do, and why it fails

Most people open the waveform at cycle 2385 and scroll back: the stream word came from the peripheral's FIFO, which a DMA run filled from RAM, which some earlier run wrote. Every hop is a new block, and without a plan the search follows whichever looks most suspicious. Meanwhile the two cheapest facts in hand, a passing commit one step back and a simulator that disagrees, sit unused.

The checklist

Work down the table. The order is a default: run the cheap reference rows (5, 6, 8) early if you have them, because each can cut the search to one change or one class of bug before you open a dump.

The output of the table is one sentence in the bug report: signal S in module M is first wrong at cycle C, since commit K, and the spec says it should be V. That sentence is what Part 4 starts from.

Do it: seed 23, row by row

Rows 1 to 3: the first wrong value, in time and in space

This failure is an unknown value, so "wrong" means X, and one script answers three rows at once. first_x.py, from the cone lesson, reads the failing run's dump and prints, for each signal, when it first went unknown. Pick one signal at each block boundary on the path back from the pin: the stream output, the DMA's read buffer, the RAM's read data, the bus write data, the DMA's fill value, and the CSR registers that feed the DMA.

$ tb/run.sh random 23
dbglab: test=random seed=23
FAIL test=random seed=23 cycle=2385: STREAM: word #41 = xxxxxxxx, expected 00000000
$ DUMP=1 tb/run.sh random 23 > /dev/null && mv dbglab.vcd ../b4-23.vcd
$ python3 ../tools/first_x.py ../b4-23.vcd --after 50000 --clock dbglab_tb.cycle dut.pstream_data u_dma.f_dout u_ram.rdata dut.m_wdata u_dma.fill_val_q u_csr.fill_q u_csr.src_q u_csr.dst_q u_csr.len_q
u_csr.dst_q              unknown from cycle     5 (was -), known again at cycle 21
u_csr.fill_q             unknown from cycle     5 (was -), unknown to the end
u_csr.len_q              unknown from cycle     5 (was -), known again at cycle 24
u_csr.src_q              unknown from cycle     5 (was -), known again at cycle 18
u_dma.fill_val_q         unknown from cycle    28 (was 0), unknown to the end
dut.m_wdata              unknown from cycle  2227 (was 97b1334d00000000), unknown to the end
u_ram.rdata              unknown from cycle  2361 (was cfa1f2e1), known again at cycle 2379
u_dma.f_dout             unknown from cycle  2365 (was 97b1334d), unknown to the end
dut.pstream_data         unknown from cycle  2381 (was 2b44c4cd), unknown to the end

Read it bottom to top, against the data path:

• Stream pin, cycle 2381; DMA buffer, 2365; RAM read data, 2361. A DMA run read an unknown word from RAM and carried it to the peripheral. RAM was not the source; it was holding something already written.

• Bus write data, 2227. An earlier DMA run put that unknown word on the bus, 134 cycles before it was read back. That is the first wrong value on the bus (row 1), and it puts the source upstream of the DMA's write side (row 3).

• The DMA's fill value, from cycle 28; CSR `fill_q`, from reset (cycle 5 is where the window opens). The run at 2227 was a fill run, which writes fill_val_q instead of copied data, and the DMA loads fill_val_q from the FILL register at every start. FILL was never written by software, so it is X from reset to the end.

• SRC, DST and LEN were also X from reset, but each was written before cycle 25 and known from then on. They are cleared: unknown, but never used while unknown.

Row 2, bisection in time, is answered by the same output: the state was already wrong at reset, and it first did damage at 2227. A halving search over the dump would land on the same two cycles; here one script read them off directly.

Row 4: stimulus

$ tb/run.sh random 23 icarus +OPS=185
dbglab: test=random seed=23
FAIL test=random seed=23 cycle=2385: STREAM: word #41 = xxxxxxxx, expected 00000000

Part 1 shrank the test to 185 operations with the same signature; the run above confirms it. What matters in the stimulus is a fill run that relies on FILL's reset value, then a copy of that buffer into the peripheral.

Rows 5 and 6: history and the other tools

$ git checkout -q 03ebdc1 && tb/run.sh random 23
dbglab: test=random seed=23
PASS test=random seed=23
$ git checkout -q b357bd8 && tb/run.sh random 23
dbglab: test=random seed=23
FAIL test=random seed=23 cycle=2385: STREAM: word #41 = xxxxxxxx, expected 00000000
$ git checkout -q main
$ tb/run.sh random 23 verilator
dbglab: test=random seed=23
PASS test=random seed=23 cycles=19235 time=192346 ns
$ XRAND=1 tb/run.sh random 23 verilator
dbglab: test=random seed=23
FAIL test=random seed=23 cycle=2385: STREAM: word #41 = f0db2f1b, expected 00000000

Commit 14, b357bd8, is the first that fails: csr: no reset on the DMA address and data registers. And the tools split on initial values: default Verilator starts unreset flip-flops at 0 (which happens to be the expected value) and passes; random start values fail at the same cycle with a real number. Both rows point at the same thing: a register that lost its reset.

Row 7: the cone

$ cat tools/noreset.ys
...
tee -o noreset.txt select -list t:$dff %co1 w:* %i w:u_ram.mem* %d
$ yosys -q -s tools/noreset.ys; cat noreset.txt
Warning: Replacing memory \mem with list of registers. See ys/sync_fifo.sv:67
Warning: Replacing memory \mem with list of registers. See ys/ram_slave.sv:14
dbglab_top/u_csr.len_q
dbglab_top/u_csr.fill_q
dbglab_top/u_csr.dst_q
dbglab_top/u_csr.src_q
dbglab_top/u_dma.u_buf.mem[3]
dbglab_top/u_dma.u_buf.mem[2]
dbglab_top/u_dma.u_buf.mem[1]
dbglab_top/u_dma.u_buf.mem[0]
$ tools/cone.sh ys dbglab_top u_dma.fill_val_q
...
== u_dma.fill_val_q
u_dma.state
u_dma.fill_val_q
u_csr.fill_q
u_csr.dma_start

Yosys calls a flip-flop with no reset a $dff and one with an asynchronous reset an $adff, so the first query lists every register without a reset, leaving out the RAM's words. Eight remain: the DMA's four-word buffer, which is always written before it is read, and four CSR registers. The second query is row 7 proper: the cone one stage behind the DMA's fill value holds four registers, and the only one that was ever unknown is u_csr.fill_q, which is also on the no-reset list.

Rows 8 and 9: a reference, and the checker

The commit before is a reference that differs in one commit; comparing a good and a bad run diffs that pair for seed 17 and finds the same register first. Then check the checker:

$ grep -n "FILL | RW" README.md
62:| 0x024 | FILL | RW | value written in fill mode. Reset 0 |
$ grep -n "m_fill    =" tb/dbglab_tb.sv
69:  logic [31:0] m_fill    = 32'h0;
145:      CSR_FILL:    m_fill    = data;

The register map says FILL resets to 0. The bench's model keeps its own 0 (line 69) and changes it only when software writes FILL (line 145); it never reads the RTL's value. The bench's expected 00000000 is the spec's value, so the design is wrong.

What the evidence says

Nine rows, each a command or two, and one sentence for the bug report: `u_csr.fill_q` in `csr_block` has no reset since commit 14 (`b357bd8`); it is X from reset, a zero fill drives it onto the bus from cycle 2227 (RAM holds it from 2230), and a later copy carries it to the stream pins at cycle 2381; the register map says FILL resets to 0. Every part of that sentence came from a run on this page. What it does not yet contain is a tested cause; "the missing reset is the whole story" is a hypothesis, and Part 4 tests it before anyone edits the RTL.

Traps

Related topics

• Part 3 · Localise

• The reproduction checklist: the step before

• Part 4: hypothesise and test, the step after

• Symptom, fault and cause: the same register, seen from the symptom