The report

The project has just widened its nightly random regression from three seeds to sixty, ahead of a release. The farm runs Verilator, because the build is paid once and each run is cheap. On Monday the ticket arrives with nothing but this:

$ for s in $(seq 1 60); do tb/run.sh random $s verilator | grep FAIL; done
FAIL test=random seed=10 cycle=4895: SCOREBOARD: RAM word 808 (address 00001ca0) read d5202ff9, expected b6c3311c (last written by DMA run #29)
FAIL test=random seed=13 cycle=3701: SCOREBOARD: RAM word 250 (address 000013e8) read f42b063a, expected c6278de6 (last written by DMA run #22)
FAIL test=random seed=16 cycle=12811: STREAM: word #203 = 5484683d, expected 3caa023d
FAIL test=random seed=20 cycle=11985: SCOREBOARD: RAM word 684 (address 00001ab0) read 00000000, expected 30253b37 (last written by DMA run #75)
...
FAIL test=random seed=58 cycle=15492: SCOREBOARD: RAM word 668 (address 00001a70) read 5f5d76a0, expected f74d9a8b (last written by DMA run #106)
FAIL test=random seed=59 cycle=3217: SCOREBOARD: RAM word 377 (address 000015e4) read 913f438a, expected 3fec7961 (last written by DMA run #22)

Twelve of sixty seeds fail. Seeds 1, 2 and 3, the old nightly, all pass. The messages name different words, different cycles and different DMA runs. One says a stream word is wrong instead of a RAM word. It looks like noise, and the first reply on the ticket is "flaky, probably the new seeds".

What random does (see meet dbglab): 1,500 operations of mixed CPU traffic while the DMA copies, fills or streams. Most DMA runs are 1 to 24 words long. One run in 400 is long, 257 to 320 words. The scoreboard checks a RAM word when the CPU reads it, and the whole RAM at the end.

Stop here if you want to try it yourself. You have dbglab, the sixty seeds and the lines above. Which seed would you pick first, and what is the first thing you would measure?

The hunt

Reproduce: the shortest seed, in both simulators

Seed 59 fails earliest, at cycle 3217. Run it twice, once in each simulator:

$ tb/run.sh random 59 verilator
dbglab: test=random seed=59
FAIL test=random seed=59 cycle=3217: SCOREBOARD: RAM word 377 (address 000015e4) read 913f438a, expected 3fec7961 (last written by DMA run #22)
$ tb/run.sh random 59
dbglab: test=random seed=59
FAIL test=random seed=59 cycle=3217: SCOREBOARD: RAM word 377 (address 000015e4) read 913f438a, expected 3fec7961 (last written by DMA run #22)

Same line, same cycle. So it is not flaky: a seed fixes the stimulus (determinism and seeds), and a seed that fails once fails every time. It is also not an X that Verilator's two-state model turned into a number: four-state Icarus reads the same value.

Now the first trap. A careful engineer reruns the whole sweep in Icarus to compare, and gets a different list:

$ for s in $(seq 1 60); do tb/run.sh random $s | grep FAIL; done > ../runs/icarus60.txt
$ wc -l < ../runs/icarus60.txt; grep -c xxxxxxxx ../runs/icarus60.txt
      19
9

Nineteen failures, nine of them reading xxxxxxxx. Those nine are a different signature: an unknown value, which Verilator's two-state flops start at zero and so never show. Seeds 16 and 51 fail in both lists but with different messages, because in Icarus the X shows up first. That is a second bug with its own ticket (it is the X that hid). Split it off now. Hunting two bugs as one is how a day disappears. This hunt follows the twelve Verilator failures, whose values are real numbers.

Observe: a word that nobody wrote

Read the message as evidence. The CPU read word 377 and got 913f438a. The model expected 3fec7961, the value DMA run #22 should have copied there. The read value is not X and not garbage. It looks like a real data word.

The natural guess is that a write was lost: the fabric dropped it, or the RAM did not store it. That guess predicts a write on the bus to 0x15e4 that left no trace. So watch every bus transfer to that address. dma_runs.sv is a probe compiled next to the bench that changes nothing. It prints one line per DMA run (what was programmed, how many words the engine wrote) and, with +ADDR, every transfer to one address:

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

// not-run: needs dbglab's sources and bench; compile it next to them (command in the Evidence box)
// dma_runs: one line per DMA run: the bench's run number, what was programmed, how many words
// the engine wrote, and when it started and finished. +LONG prints only runs of 256 words or
// more. +ADDR=<hex> also prints every bus transfer to that byte address.
`timescale 1ns/1ps
module dma_runs;
  int unsigned run, len, wrote, t0;
  logic [31:0] src, dst, watch;
  logic [7:0]  ctrl;
  bit          long_only, have_watch;
  initial begin
    long_only  = $test$plusargs("LONG");
    have_watch = $value$plusargs("ADDR=%h", watch);
  end
  always @(posedge dbglab_tb.clk) begin
    if (dbglab_tb.dut.dma_start) begin
      run = dbglab_tb.n_dma + 1;           // the bench counts a run once START is accepted
      len = dbglab_tb.dut.dma_len; src = dbglab_tb.dut.dma_src;
      dst = dbglab_tb.dut.dma_dst; ctrl = dbglab_tb.dut.dma_ctrl; wrote = 0; t0 = dbglab_tb.cycle;
    end
    if (dbglab_tb.dut.m_valid[1] && dbglab_tb.dut.m_ready[1] && dbglab_tb.dut.m_write[1]) wrote++;
    if (dbglab_tb.dut.dma_done && (!long_only || len >= 256))
      $display("DMA run #%0d  cycles %0d-%0d  ctrl=%02h len=%0d src=%h dst=%h  wrote %0d words",
               run, t0, dbglab_tb.cycle, ctrl, len, src, dst, wrote);
    if (have_watch)
      for (int m = 0; m < 2; m++)
        if (dbglab_tb.dut.m_valid[m] && dbglab_tb.dut.m_ready[m] && dbglab_tb.dut.m_addr[m] == watch)
          if (dbglab_tb.dut.m_write[m])
            $display("cycle %0d  %s write %h data=%h", dbglab_tb.cycle, m ? "DMA" : "CPU", watch, dbglab_tb.dut.m_wdata[m]);
          else
            $display("cycle %0d  %s read  %h", dbglab_tb.cycle, m ? "DMA" : "CPU", watch);
  end
endmodule

$ ../probes/run-probe.sh ../probes/dma_runs.sv random 59 +ADDR=000015e4
dbglab: test=random seed=59
DMA run #1  cycles 64-243  ctrl=03 len=22 src=000013b8 dst=00001be0  wrote 22 words
...
DMA run #21  cycles 2975-2985  ctrl=00 len=1 src=00001f6c dst=00001abc  wrote 1 words
DMA run #22  cycles 3020-3108  ctrl=00 len=267 src=00001b0c dst=00001204  wrote 11 words
DMA run #23  cycles 3152-3208  ctrl=00 len=7 src=00001f70 dst=000019a4  wrote 7 words
cycle 3215  CPU read  000015e4
FAIL test=random seed=59 cycle=3217: SCOREBOARD: RAM word 377 (address 000015e4) read 913f438a, expected 3fec7961 (last written by DMA run #22)

• One transfer to 0x15e4 in the whole run: the CPU's read at cycle 3215. Neither master ever wrote that address, so no write was lost. The value read is the word's preloaded contents from cycle 0. The guess about the fabric is dead after one run.

• Run #22 is the long one: 267 words from 0x1b0c to 0x1204. Word 377 is at offset 248 of its destination, so the run should have written it.

• It wrote 11 words and reported done at cycle 3108, 88 cycles after it started. The bench polled STATUS, saw done with no error, and moved on. Nothing complained until a CPU read landed on one of the missing words.

Localise: is it this run, or every long run?

One run that stopped early is an observation. A pattern is evidence. Run the same probe with +LONG on all sixty seeds and keep only the runs of 256 words or more (Icarus, so the X seeds stop early and drop out):

$ for s in $(seq 1 60); do ../probes/run-probe.sh ../probes/dma_runs.sv random $s +LONG | grep "^DMA" | sed "s/^/$s: /"; done
10: DMA run #29  cycles 4442-4859  ctrl=02 len=308 src=000015e8 dst=00001b1c  wrote 52 words
13: DMA run #22  cycles 3226-3501  ctrl=02 len=290 src=000017d0 dst=000010a4  wrote 34 words
20: DMA run #75  cycles 11647-11787  ctrl=03 len=273 src=000013a8 dst=000019ac  wrote 17 words
34: DMA run #74  cycles 11356-11435  ctrl=12 len=273 src=000014fc dst=00001b44  wrote 17 words
46: DMA run #36  cycles 5129-5546  ctrl=00 len=308 src=0000149c dst=000019b4  wrote 52 words
48: DMA run #70  cycles 10246-10489  ctrl=03 len=286 src=000013e8 dst=00001a6c  wrote 30 words
50: DMA run #93  cycles 13216-13661  ctrl=02 len=312 src=000016d4 dst=00001024  wrote 56 words
52: DMA run #23  cycles 3473-3632  ctrl=11 len=291 src=00001864 dst=000012b8  wrote 35 words
58: DMA run #106  cycles 14941-15255  ctrl=01 len=295 src=000013a8 dst=0000199c  wrote 39 words
59: DMA run #22  cycles 3020-3108  ctrl=00 len=267 src=00001b0c dst=00001204  wrote 11 words

Ten seeds have a long run. All ten fail, and none of the 41 passing seeds has one. Subtract the two numbers on each line:

Ten long runs, and every one is exactly 256 words short, whatever the mode: plain copy, fill (ctrl=12, seed 34) or with interrupts enabled. Short runs are never short. Wrong by exactly 2⁸ is the signature of a value that lost its top bits (logic bugs lists it). The bug is in whatever holds the run's length, and it only matters past 255. The twelve "random" seeds are simply the ones that happened to draw a long run.

Verilator's list has two more seeds, 16 and 51, which this Icarus sweep does not show: in Icarus the X bug stops them first. The same probe in a copy of HEAD with that bug fixed (the FILL reset restored in csr_block.sv) shows a long run in both, exactly 256 words short:

$ for s in 16 51; do ../probes/run-probe.sh ../probes/dma_runs.sv random $s +LONG | grep "^DMA" | sed "s/^/$s: /"; done
16: DMA run #80  cycles 12444-12733  ctrl=03 len=292 src=00001124 dst=00001670  wrote 36 words
51: DMA run #75  cycles 11227-11527  ctrl=02 len=293 src=00001afc dst=00001184  wrote 37 words

Now localise in history. The old nightly passed, so the project has a good commit. But first check that the good end really ran the scenario: a seed's stimulus can change when the test changes, and tests.svh changed three times since v0.1. Look at the long run at the release and at the commit before the suspect range:

$ git checkout -q v0.1 && ../probes/run-probe.sh ../probes/dma_runs.sv random 59 +LONG | grep -E "^(DMA|PASS|FAIL)"
DMA run #11  cycles 2342-5350  ctrl=01 len=267 src=00001b0c dst=00001204  wrote 267 words
PASS test=random seed=59
$ git checkout -q bc2bb34 && ../probes/run-probe.sh ../probes/dma_runs.sv random 59 +LONG | grep -E "^(DMA|PASS|FAIL)"
DMA run #22  cycles 3020-5154  ctrl=00 len=267 src=00001b0c dst=00001204  wrote 267 words
PASS test=random seed=59

Both ends are trustworthy. At v0.1 the same 267-word copy happens (as run #11, because later commits added more kinds of DMA run), and it writes all 267 words. A good end that passes because the scenario never happens tells bisect nothing. Look at the times too: the healthy run takes 2,134 cycles, the broken one 88. Now bisect, staying with Verilator:

$ git bisect start HEAD v0.1
Bisecting: 5 revisions left to test after this (roughly 3 steps)
[27acd3070be8abc6d2e39268f12788f0d15688ee] periph: deepen the async FIFO to 16 entries
$ time git bisect run tb/run.sh random 59 verilator > ../runs/bisect59.txt 2>&1
git bisect run tb/run.sh random 59 verilator > ../runs/bisect59.txt 2>&1  24.01s user 1.72s system 96% cpu 26.570 total
$ cat ../runs/bisect59.txt
running 'tb/run.sh' 'random' '59' 'verilator'
dbglab: test=random seed=59
PASS test=random seed=59
Bisecting: 2 revisions left to test after this (roughly 2 steps)
[03ebdc1fd778231df2f3dca283af1764db17f11e] dma: one width for the beat counters
running 'tb/run.sh' 'random' '59' 'verilator'
dbglab: test=random seed=59
FAIL test=random seed=59 cycle=3217: SCOREBOARD: RAM word 377 (address 000015e4) read 913f438a, expected 3fec7961 (last written by DMA run #22)
Bisecting: 0 revisions left to test after this (roughly 1 step)
[bc2bb3420e418e0217ea5985bd4a348397f1866f] dma: fill mode
running 'tb/run.sh' 'random' '59' 'verilator'
dbglab: test=random seed=59
PASS test=random seed=59
03ebdc1fd778231df2f3dca283af1764db17f11e is the first bad commit
...
    dma: one width for the beat counters
    
    Name the counter width once and cast the length into it; this also
    silences the Verilator WIDTH warning on the load.
...

Three runs and 27 seconds, almost all of it Verilator rebuilding the model at each commit. The same bisect in Icarus (git bisect run tb/run.sh random 59) finishes in under a second and names the same commit. Verilator pays off on long sweeps of one build, not on many builds of short runs. The method is the same as in bisection in history.

Hypothesise and test: a prediction for every run

The guilty commit is short. Its key lines:

1
2
3
4

// snippet: commit 13 (03ebdc1), rtl/dma_engine.sv lines 36-37 and 89
  localparam int CW = 8;           // beat counter width
  logic [CW-1:0] left_q;           // words still to write
          left_q  <= CW'(cfg_len);

Hypothesis: left_q counts the words still to write. It used to be 10 bits, like cfg_len; commit 13 made it 8 and cast the length into it. So a run loads LEN mod 256, writes that many words and finishes. Predictions: every run of 256 words or more writes LEN minus 256 words; every shorter run is unaffected. That predicts all ten lines of the table above exactly, and says why only one run in 400 can fail.

A tempting shortcut is to ask lint, since narrowing is lint's job. This dead end is worth seeing once:

$ verilator --lint-only -Wall $(grep -v '^#' rtl/files.f) --top-module dbglab_top 2>&1 | grep '^%Warning' | wc -l
22
$ verilator --lint-only -Wall $(grep -v '^#' rtl/files.f) --top-module dbglab_top 2>&1 | grep '^%Warning' | grep -c dma_engine
0

Twenty-two warnings, none in the DMA. The explicit cast tells lint that the truncation is intended, which is exactly what the commit message said it was for. Lint finds a missing cast, not a wrong one. The prediction has to be tested by running the design.

The last prediction is the strongest, because it could fail: with CW = 10, the Verilator sweep should be clean, and Icarus should still fail exactly the nine X seeds and nothing else. If any non-X failure survives, there is a third bug hiding behind this one.

The fix and the lesson

Fix: give the counter the width of what it counts

// snippet: the fix, rtl/dma_engine.sv line 36
  localparam int CW = 10;          // beat counter width

The cast stays harmless now, because it no longer narrows. Ten bits is the width of cfg_len, so the counter can hold any length software can program, up to 1023.

Prove: the repro, both sweeps, and nothing new

$ tb/run.sh random 59; tb/run.sh random 59 verilator
dbglab: test=random seed=59
PASS test=random seed=59 cycles=20514 time=205136 ns
dbglab: test=random seed=59
PASS test=random seed=59 cycles=20514 time=205136 ns
$ for s in $(seq 1 60); do tb/run.sh random $s verilator | grep FAIL; done | wc -l
       0
$ for s in $(seq 1 60); do tb/run.sh random $s | grep FAIL; done > ../runs/b3fix-icarus60.txt
$ diff <(grep xxxxxxxx ../runs/icarus60.txt) ../runs/b3fix-icarus60.txt && echo same
same

All three predictions hold. The repro passes in both simulators, the Verilator nightly is clean, and Icarus fails only the nine X lines it failed before, word for word. No third bug was hiding. Sixty seeds include only ten long runs, so this is evidence, not proof for every length. Proving the fix closes that gap with a directed 308-word copy and a formal check over every length.

Prevent: check the run when it ends, not when its words are read

The scoreboard reported seed 59 at cycle 3217, 109 cycles after the bad run ended. On the other failing seeds the gap runs from 18 to 627 cycles, and a missing word that is never read again would never fail at all. The rule the hardware broke is simple and local: a run that ends without an error has written exactly LEN words. Check that rule where it lives:

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

// not-run: needs dbglab's sources and bench; compile it next to them (command in the Evidence box)
// len_check: when a DMA run ends without an error, it must have written exactly LEN words.
`timescale 1ns/1ps
module len_check;
  int unsigned len, wrote;
  always @(posedge dbglab_tb.clk) begin
    if (dbglab_tb.dut.dma_start) begin len = dbglab_tb.dut.dma_len; wrote = 0; end
    if (dbglab_tb.dut.m_valid[1] && dbglab_tb.dut.m_ready[1] && dbglab_tb.dut.m_write[1]) wrote++;
    if (dbglab_tb.dut.dma_done && !dbglab_tb.dut.dma_err && wrote != len) begin
      $display("FAIL cycle=%0d: LEN_CHECK: DMA run #%0d ended after %0d of %0d words",
               dbglab_tb.cycle, dbglab_tb.n_dma, wrote, len);
      $fatal(1, "length check");
    end
  end
endmodule

$ ../probes/run-probe.sh ../probes/len_check.sv random 59          # at HEAD
dbglab: test=random seed=59
FAIL cycle=3108: LEN_CHECK: DMA run #22 ended after 11 of 267 words

It fires on the cycle the run ends and names the run, the count and the length. At HEAD it fires in all ten long-run seeds; with the fix it is silent on all sixty. In a real bench it belongs in the DMA's checker as an assertion (assertions as always-on probes). The random test needs a change too: one long run in 400 means three fixed seeds almost never draw one. Weighting lengths around 255, 256 and 257 makes the boundary a target instead of an accident.

Which step won this hunt? Localise, by counting. The fabric suspect died on one probe run. The table of requested against written made "twelve random seeds" into "every run over 255 words". After that, reading the diff took a minute.

Related topics

• Part 10 · Case Studies

• Logic bugs: off-by-one, width and sign

• Bisection in history

• The bug write-up (this bug, written up)

• Case study: the X that hid

• Case study: the reset value that changed