The report

The project runs its nightly random sweep in Verilator. A verification engineer reruns the same sixty seeds in Icarus before a release and files this:

$ grep xxxxxxxx ../runs/icarus60.txt
FAIL test=random seed=16 cycle=686: SCOREBOARD: RAM word 759 (address 00001bdc) read xxxxxxxx, expected 00000000 (last written by DMA run #3)
FAIL test=random seed=17 cycle=7949: SCOREBOARD: RAM word 816 (address 00001cc0) read xxxxxxxx, expected 00000000 (last written by DMA run #4)
FAIL test=random seed=19 cycle=415: SCOREBOARD: RAM word 984 (address 00001f60) read xxxxxxxx, expected 00000000 (last written by DMA run #3)
FAIL test=random seed=23 cycle=2385: STREAM: word #41 = xxxxxxxx, expected 00000000
FAIL test=random seed=29 cycle=1820: SCOREBOARD: RAM word 542 (address 00001878) read xxxxxxxx, expected 00000000 (last written by DMA run #8)
FAIL test=random seed=31 cycle=5693: SCOREBOARD: RAM word 652 (address 00001a30) read xxxxxxxx, expected 00000000 (last written by DMA run #3)
FAIL test=random seed=41 cycle=7656: SCOREBOARD: RAM word 846 (address 00001d38) read xxxxxxxx, expected 00000000 (last written by DMA run #41)
FAIL test=random seed=43 cycle=2793: SCOREBOARD: RAM word 444 (address 000016f0) read xxxxxxxx, expected 00000000 (last written by DMA run #7)
FAIL test=random seed=51 cycle=1155: SCOREBOARD: RAM word 929 (address 00001e84) read xxxxxxxx, expected 00000000 (last written by DMA run #7)

Nine seeds read an unknown value where the model expects zero. None of the nine shows this failure in the Verilator nightly. (Seeds 16 and 51 fail there too, but with a different message: that is another bug, the off-by-one that fails at wrap.) The first comment on the ticket: "Icarus X pessimism, Verilator is fine, low priority".

Stop here if you want to try it yourself. Is the comment right? If not, which seed would you take, and what in the message tells you where to start?

The hunt

Reproduce: a pass that proves nothing

Seed 17 is the one from the report with the longest wait. Run it in both simulators:

$ tb/run.sh random 17
dbglab: test=random seed=17
FAIL test=random seed=17 cycle=7949: SCOREBOARD: RAM word 816 (address 00001cc0) read xxxxxxxx, expected 00000000 (last written by DMA run #4)
$ tb/run.sh random 17 verilator
dbglab: test=random seed=17
PASS test=random seed=17 cycles=18442 time=184416 ns

Here is the trap the ticket fell into. Verilator is a two-state simulator: a flip-flop with no reset starts at 0, never X. If the missing value happens to be 0, and this one should be 0, the run passes. That pass does not say "no bug". It says "no bug if every unreset flop powers up at zero", which no silicon promises. The test is to give Verilator random start values instead (XRAND=1 builds with --x-initial unique and runs with +verilator+rand+reset+2):

$ XRAND=1 tb/run.sh random 17 verilator
dbglab: test=random seed=17
FAIL test=random seed=17 cycle=7949: SCOREBOARD: RAM word 816 (address 00001cc0) read 5d88e2dd, expected 00000000 (last written by DMA run #4)

Same word, same cycle, and now a random number where Icarus showed X. The bug is real in both simulators; Verilator's default start values hid it. "Blame the tool" is a hypothesis like any other, and it just failed its test (confirmation bias and blaming the tool covers how to check that claim properly). The repro is tb/run.sh random 17, deterministic, under a second.

Observe: the write, not the read

The failing read happens at cycle 7949. Opening a waveform there shows the CPU reading an X from RAM, which you already knew. The message says more: the word was last written by DMA run #4. So the question is what run #4 wrote, and when. dma_runs.sv, a probe compiled next to the bench that changes nothing, prints each DMA run and every bus transfer to one address:

$ ../probes/run-probe.sh ../probes/dma_runs.sv random 17 +ADDR=00001cc0
dbglab: test=random seed=17
DMA run #1  cycles 30-209  ctrl=0e len=22 src=00001874 dst=00003000  wrote 22 words
DMA run #2  cycles 291-310  ctrl=03 len=2 src=000019d8 dst=0000140c  wrote 2 words
DMA run #3  cycles 388-421  ctrl=03 len=4 src=00001784 dst=00001124  wrote 4 words
cycle 514  DMA write 00001cc0 data=xxxxxxxx
DMA run #4  cycles 483-526  ctrl=12 len=9 src=00001344 dst=00001ca8  wrote 9 words
...
DMA run #51  cycles 7752-7931  ctrl=02 len=22 src=00001a50 dst=000010dc  wrote 22 words
cycle 7947  CPU read  00001cc0
FAIL test=random seed=17 cycle=7949: SCOREBOARD: RAM word 816 (address 00001cc0) read xxxxxxxx, expected 00000000 (last written by DMA run #4)

• Run #4 has `ctrl=12`: bit 4 is fill and bit 1 is err_ie. A fill run reads nothing; it writes the FILL register's value to every destination word. Zeros expected means a zero fill.

• Cycle 514: the DMA writes xxxxxxxx to 0x1cc0, the seventh word of the nine-word fill starting at 0x1ca8.

• Cycles 527 to 7946: 47 more DMA runs and thousands of CPU operations, and not one touches 0x1cc0. The X just sits in RAM.

• Cycle 7947: the CPU reads it, and the scoreboard fails two cycles later, at 7949. The read comes 7,433 cycles after the bad write (514 to 7947).

Why did nothing complain at cycle 514? The bench has a valid/ready rule checker on both bus masters, and it does look for X:

$ grep -n "isunknown" tb/bus_rules.sv
27:      if ($isunknown(valid) || (valid && ($isunknown(addr) || $isunknown(write))))
47:  a_r1: assert property (@(posedge clk) disable iff (!rst_n) valid |-> !$isunknown({addr, write}));

It checks valid, addr and write, not the write data. An X can cross the bus as data and nobody looks until a reader compares it with the model. That gap is why the scoreboard is the first thing to notice (scoreboards report late measures this gap).

Localise: a register nobody wrote

Walk the data back one hop at a time (the first wrong cycle has the method). In fill mode the DMA's write data comes from wdata_q, loaded from fill_val_q, which samples the CSR block's FILL register at START. So: was FILL ever written before run #4 started at cycle 483? A second probe prints the first X write by either master and every CPU write to FILL (0x2024):

$ ../probes/run-probe.sh ../probes/x_writes.sv random 17 | head -4
dbglab: test=random seed=17
cycle 488  first X write: DMA, address 00001ca8, during DMA run #4
cycle 807  CPU writes FILL = 3578a189
cycle 1089  CPU writes FILL = 1449e86a

The first X on the bus is run #4's first word, at cycle 488. The first write to FILL comes at cycle 807, after the run. So at cycle 483 FILL held whatever it powered up with. Look at how the bench zeroes a buffer, then at the register:

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

// snippet: tb/tests.svh lines 194-198 (the zero-fill branch of r_start_dma) and rtl/csr_block.sv lines 55-65
  else if (k < 25) begin                                             // zero a buffer
    r_fill = 1'b1;
    if (m_fill != 32'h0) csr_wr(CSR_FILL, 32'h0);
    mode = 8'h1 << CTRL_FILL;
  end

  // Datapath registers: always programmed before START, so they need no reset.
  always_ff @(posedge clk)
    if (wr) begin
      case (off)
        CSR_SRC:  src_q  <= wdata;
        CSR_DST:  dst_q  <= wdata;
        CSR_LEN:  len_q  <= wdata[9:0];
        CSR_FILL: fill_q <= wdata;
        default: ;
      endcase
    end

Two reasonable decisions collide. The bench writes FILL only when its model says FILL is not already 0, trusting the register map's "FILL resets to 0". The RTL comment says the datapath registers are "always programmed before START". That is true for SRC, DST and LEN, which dma_program writes every time, and false for FILL. FILL has no reset, so in Icarus it is X until first written; in silicon it is whatever it powers up as.

Hypothesise and test: predict every seed

Hypothesis: FILL has no reset, and a zero fill that starts before any write to FILL writes FILL's power-up value. Predictions: (1) a check at START that a fill run's FILL is known fires on run #4 of seed 17, at cycle 483; (2) over many seeds, the seeds where that check fires are exactly the seeds that write an X to the bus; (3) since nothing makes the X get read soon, the wait between write and failure should vary wildly, and some X words should never be read at all.

1
2
3
4
5
6
7
8
9
10
11

// not-run: needs dbglab's sources and bench; compile it next to them (command in the Evidence box)
// fill_start_check: a fill run must not start with an unknown FILL value.
`timescale 1ns/1ps
module fill_start_check;
  always @(posedge dbglab_tb.clk)
    if (dbglab_tb.dut.dma_start && dbglab_tb.dut.dma_ctrl[4] && $isunknown(dbglab_tb.dut.dma_fill)) begin
      $display("FAIL cycle=%0d: FILL_CHECK: DMA run #%0d starts a fill with FILL=%h",
               dbglab_tb.cycle, dbglab_tb.n_dma + 1, dbglab_tb.dut.dma_fill);
      $fatal(1, "fill check");
    end
endmodule

$ ../probes/run-probe.sh ../probes/fill_start_check.sv random 17
dbglab: test=random seed=17
FAIL cycle=483: FILL_CHECK: DMA run #4 starts a fill with FILL=xxxxxxxx

Prediction 1 holds: cycle 483, the cycle run #4 starts, five cycles before the first bad write (488) and 7,466 cycles before the scoreboard reports at 7949. For predictions 2 and 3, sweep 300 seeds. Use a copy of HEAD with the off-by-one bug fixed (CW = 10), so its failures cannot mix in. Record the first X write and the failure line for each seed, then run the check on the same seeds:

$ for s in $(seq 1 300); do ../probes/run-probe.sh ../probes/x_writes.sv random $s | grep -E "first X|^FAIL" | tr '\n' ' ' | sed "s/^/$s /"; echo; done | grep "first X" > ../runs/xgap300.txt
$ for s in $(seq 1 300); do ../probes/run-probe.sh ../probes/fill_start_check.sv random $s | grep FILL_CHECK | sed "s/^/$s /"; done > ../runs/fillchk300.txt
$ wc -l < ../runs/fillchk300.txt; diff <(cut -d' ' -f1 ../runs/fillchk300.txt) <(cut -d' ' -f1 ../runs/xgap300.txt) && echo "same 41 seeds"
      41
same 41 seeds

Prediction 2 holds: 41 seeds write an X, and they are exactly the 41 where a fill starts with FILL unknown. There is no second source of X. A short script measures how long each X waited, from the seed's first X write to the failing check's report (for seed 17, 488 to 7949: 7,461 cycles; the failing word itself is the later write at 514):

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

# not-run: reads the sweep file written by the x_writes probe (commands above)
# gaps.py: from x_writes probe lines (one per seed), how long each X waited before a check saw it.
import re, sys
gaps, silent = [], []
for line in open(sys.argv[1]):
    seed, w = re.match(r"(\d+) cycle (\d+)  first X write", line).groups()
    f = re.search(r"FAIL test=random seed=\d+ cycle=(\d+)", line)
    if f: gaps.append((int(f.group(1)) - int(w), int(seed)))
    else: silent.append(int(seed))
gaps.sort()
print(f"seeds that write an X: {len(gaps) + len(silent)}; fail: {len(gaps)}; pass anyway: {len(silent)} {silent}")
for lo, hi in [(0, 100), (100, 1000), (1000, 5000), (5000, 10**6)]:
    print(f"  X seen {lo:>5}-{hi - 1 if hi < 10**6 else '':<5} cycles after it was written: {sum(lo <= g < hi for g, _ in gaps)}")
print(f"  shortest {gaps[0][0]} (seed {gaps[0][1]}), median {gaps[len(gaps) // 2][0]}, longest {gaps[-1][0]} (seed {gaps[-1][1]})")

$ python3 -I gaps.py runs/xgap300.txt
seeds that write an X: 41; fail: 37; pass anyway: 4 [86, 105, 128, 154]
  X seen     0-99    cycles after it was written: 0
  X seen   100-999   cycles after it was written: 14
  X seen  1000-4999  cycles after it was written: 15
  X seen  5000-      cycles after it was written: 8
  shortest 127 (seed 19), median 1730, longest 19708 (seed 293)

• No X is seen within 100 cycles. The shortest wait is 127 cycles. Every report lands far from its cause.

• Seed 293: the X is written at cycle 882 and found only by the RAM sweep at the end of the test, 19,708 cycles later. Without that sweep, this seed passes.

• Seeds 86, 105, 128 and 154 pass. They write an X into RAM, and later traffic overwrites it before anything reads it. A green run here is not evidence that the design never wrote an X.

Prediction 3 holds too. Now history: when did FILL lose its reset? Bisect would work (bisection in history bisects this exact bug), but here the suspect is one line, so ask git which commits added or removed it:

$ git log -S'fill_q <= FILL_RST' --oneline
b357bd8 csr: no reset on the DMA address and data registers
bc2bb34 dma: fill mode
$ git show b357bd8 -- rtl/csr_block.sv
...
    SRC, DST, LEN and FILL are always programmed before START, so their
    reset only costs area. Control and status keep their reset.
...
-      src_q <= SRC_RST; dst_q <= DST_RST; len_q <= LEN_RST;
-      fill_q <= FILL_RST;
...

Commit 12 added FILL with its reset; commit 14 removed it, with a reason that is true for three of the four registers. git log -S (the "pickaxe") lists the commits that change how many times a string appears. When you already know the line, it is faster than bisect and needs no test at all.

The fix and the lesson

Fix: give FILL its reset back

// snippet: the fix in rtl/csr_block.sv: FILL joins the reset block (two lines), and leaves the unreset one
      err_q <= 1'b0; err_addr_q <= '0; fill_q <= FILL_RST;
          CSR_FILL:    fill_q    <= wdata;

The alternative, making the bench always write FILL before a zero fill, would make the tests pass and leave the register map's promise broken for every driver that trusts it. The area saving was for registers that really are always written. FILL is not one of them, because the documented reset value is part of how software uses it.

Prove: three simulators' worth of evidence

$ tb/run.sh random 17 && tb/run.sh random 17 verilator && XRAND=1 tb/run.sh random 17 verilator
dbglab: test=random seed=17
PASS test=random seed=17 cycles=18442 time=184416 ns
dbglab: test=random seed=17
PASS test=random seed=17 cycles=18442 time=184416 ns
dbglab: test=random seed=17
PASS test=random seed=17 cycles=18442 time=184416 ns
$ (for s in $(seq 1 60); do tb/run.sh random $s | grep FAIL; done) > ../runs/b4fix-icarus60.txt
$ wc -l < ../runs/b4fix-icarus60.txt; diff ../runs/b4fix-icarus60.txt ../runs/vl60.txt && echo "same as the Verilator sweep at HEAD"
      12
same as the Verilator sweep at HEAD

Seed 17 passes in four-state Icarus, in two-state Verilator and with random start values. After the fix, Icarus fails exactly the twelve seeds the Verilator nightly failed at HEAD, line for line: the off-by-one bug, and nothing else. With both fixes applied, a copy fails none of 300 seeds in Icarus and none of 60 in Verilator with random start values, and the fill check stays silent on all 300.

Prevent: check where the X enters

• A check at the point of entry. fill_start_check fires at the START of the bad run and names the register. As an assertion in the DMA or CSR checker it turns a 7,000-cycle hunt into a one-line message. A general rule that would also work: no X on bus write data ($isunknown(wdata) when valid && write), the check bus_rules.sv leaves out. dbglab's bench is left unchanged here; the assertion that would have caught it shows how to write and prove such a check.

• Run the nightly where X can appear. Keep a four-state simulator in the loop, or run the two-state one with random start values on part of the seeds. A two-state-only regression cannot see this class of bug.

• Review every removed reset. The question: is this register written on every path before it is used, including paths that rely on its documented reset value? A lint rule that lists unreset flops makes the list to review; the localisation checklist produces one with Yosys.

Which step won this hunt? Observe, by reading the message to its end: "last written by DMA run #4" moved the search from cycle 7949 to cycle 483 in one probe run. The step that nearly lost it was Reproduce, where a passing run in the other simulator was taken as evidence.

Related topics

• Part 10 · Case Studies

• X and reset bugs

• X in a waveform

• Symptom, fault and cause (this bug's chain)

• Case study: the off-by-one that fails at wrap

• Case study: the reset value that changed