Red one night in three, and a release in a week

dbglab's nightly random test goes red about one night in three with a RAM word that reads xxxxxxxx. Making a flaky test fail already did the first piece of work: with the other bug (B3) fixed in a scratch copy, the rate is 100 failures in 1,000 seeds, every one an X where a zero was expected, last written by a DMA fill. A biased bench raised it to 88.5%. The ticket now says understood, not fixed.

You have a week. How do you get from a rate to a fix you can defend in review, with numbers?

What people usually do, and why it fails

Intermittent bugs usually stall here, in one of three ways. Verilator passes, so it is called a simulator problem. The bench is changed to always write FILL before a zero fill, and the regression goes green. The RTL is fixed, twenty seeds pass, and it is closed. The first trusts a simulator that cannot show the bug, the second stops the test asking the question, and the third is too small a sweep for a 10% bug (twenty clean runs happen by luck 12% of the time).

The method: the loop, with this part's tools

Do it: B4 from rate to proof

Reproduce: from a rate to an order

Part 1's mechanism says the failure needs a zero fill before any pattern fill, because only then does the DMA use FILL's reset value. That is an ordering claim, so make the order the knob. This directed test, added to a scratch copy of the bench, does two fills in a chosen order, programming each the way the random test does:

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

// not-run: added to tb/tests.svh in a scratch copy of dbglab (and dispatched from dbglab_tb.sv)
// fill_order (scratch copy only): two DMA fills in a chosen order, the way the random test
// programs them. +ORDER=0: the zero fill first; +ORDER=1: the pattern fill first.
task automatic t_fill_order();
  int ord, d;
  bit zero;
  logic [31:0] st;
  if (!$value$plusargs("ORDER=%d", ord)) ord = 0;
  csr_wr(CSR_CTRL, 32'h0);
  for (int k = 0; k < 2; k++) begin
    zero = (k == 0) == (ord == 0);
    if (zero) begin if (m_fill != 32'h0) csr_wr(CSR_FILL, 32'h0); end   // trusts FILL's reset value
    else csr_wr(CSR_FILL, rnd());
    csr_wr(CSR_CTRL, 32'h1 << CTRL_FILL);
    d = urange(0, 502) + 512 * k;                // nine words inside one half of the RAM
    dma_program(RAM_BASE, RAM_BASE + 4 * d, 9);
    dma_wait(st);
    dma_close(st, 1'b0, 32'h0);
    model_copy(0, d, 9, 1'b1);
    for (int i = 0; i < 9; i++) ram_check(d + i);
  end
endtask

$ for o in 0 1; do for s in $(seq 1 20); do tb/run.sh fill_order $s icarus +ORDER=$o | tail -1; done \
>   | cut -c1-4 | sort | uniq -c; done
  20 FAIL
  20 PASS
$ tb/run.sh fill_order 1 icarus +ORDER=0
dbglab: test=fill_order seed=1
FAIL test=fill_order seed=1 cycle=79: SCOREBOARD: RAM word 42 (address 000010a8) read xxxxxxxx, expected 00000000 (last written by DMA run #1)

Zero fill first: 20 failures in 20 seeds. Pattern fill first: 20 passes. A 10% intermittent is now a command that fails at cycle 79, in about 200 cycles of simulation. The same command in the other simulators is the next clue:

$ tb/run.sh fill_order 1 verilator +ORDER=0
dbglab: test=fill_order seed=1
PASS test=fill_order seed=1 cycles=199 time=1986 ns
$ XRAND=1 tb/run.sh fill_order 1 verilator +ORDER=0
dbglab: test=fill_order seed=1
FAIL test=fill_order seed=1 cycle=79: SCOREBOARD: RAM word 42 (address 000010a8) read 8f27a164, expected 00000000 (last written by DMA run #1)

Verilator passes, because its flops start at 0, which is the value the test expects. With random start values it fails at the same cycle with a random word instead of X. That is the signature of a start value, the fourth hidden input: whatever FILL holds, nothing wrote it.

Observe: a precursor, not the symptom

The symptom arrives late: in random seed 17 the bad words are written at cycle 488 and read at 7949. A precursor arrives at the cause: a fill run starts while FILL has not been written since reset. This probe compiles next to dbglab, changes nothing, keeps a flight recorder of the CPU's last six register writes, and fires once on that precursor:

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
36
37
38
39
40
41
42
43
44

// not-run: needs dbglab's sources and bench; compile it next to them (probes/run-fp.sh, in the Evidence box)
// fill_probe: compiled next to dbglab; reads the design by hierarchical names and changes nothing.
// A flight recorder keeps the CPU's last 6 register writes. The trigger is a precursor, not the
// symptom: a DMA fill run starts while FILL has not been written since reset. It prints once.
`timescale 1ns/1ps
module fill_probe;
  import dbglab_pkg::*;
  int unsigned  rec_cyc [6];
  logic [11:0]  rec_off [6];
  logic [31:0]  rec_dat [6];
  int unsigned  wp = 0, n_rec = 0, runs = 0;
  bit           fill_written = 0, fired = 0;
  function automatic string reg_name(input logic [11:0] off);
    case (off)
      CSR_SCRATCH: return "SCRATCH"; CSR_CTRL: return "CTRL";   CSR_STATUS: return "STATUS";
      CSR_SRC:     return "SRC";     CSR_DST:  return "DST";    CSR_LEN:    return "LEN";
      CSR_START:   return "START";   CSR_FILL: return "FILL";   default:    return "?";
    endcase
  endfunction
  always @(posedge dbglab_tb.clk) begin
    #0.5;                                     // just after the edge, as the bench acts
    if (!dbglab_tb.rst_n) fill_written = 0;
    if (dbglab_tb.dut.m_valid[0] && dbglab_tb.dut.m_ready[0] && dbglab_tb.dut.m_write[0]
        && dbglab_tb.dut.m_addr[0][31:12] == CSR_BASE[31:12]) begin
      rec_cyc[wp] = dbglab_tb.cycle; rec_off[wp] = dbglab_tb.dut.m_addr[0][11:0]; rec_dat[wp] = dbglab_tb.dut.m_wdata[0];
      wp = (wp + 1) % 6; n_rec++;
      if (dbglab_tb.dut.m_addr[0][11:0] == CSR_FILL) fill_written = 1;
    end
    if (dbglab_tb.dut.u_dma.start && !dbglab_tb.dut.u_dma.busy) begin
      runs++;
      if (!fired && dbglab_tb.dut.u_dma.cfg_ctrl[CTRL_FILL] && !fill_written) begin
        fired = 1;
        $display("PRECURSOR cycle=%0d: DMA run #%0d is a fill, and FILL was never written since reset (it holds %h)",
                 dbglab_tb.cycle, runs, dbglab_tb.dut.u_dma.cfg_fill);
        $display("  the last CPU register writes before it:");
        for (int k = (n_rec < 6 ? 6 - n_rec : 0); k < 6; k++) begin
          int unsigned i;
          i = (wp + k) % 6;
          $display("    cycle %0d: %s <= %h", rec_cyc[i], reg_name(rec_off[i]), rec_dat[i]);
        end
      end
    end
  end
endmodule

$ probes/run-fp.sh b3fix random 17
dbglab: test=random seed=17
PRECURSOR cycle=483: DMA run #4 is a fill, and FILL was never written since reset (it holds xxxxxxxx)
  the last CPU register writes before it:
    cycle 455: SCRATCH <= 976989f9
    cycle 470: CTRL <= 00000012
    cycle 473: SRC <= 00001344
    cycle 476: DST <= 00001ca8
    cycle 479: LEN <= 00000009
    cycle 482: START <= 00000001
FAIL test=random seed=17 cycle=7949: SCOREBOARD: RAM word 816 (address 00001cc0) read xxxxxxxx, expected 00000000 (last written by DMA run #4)
$ probes/run-fp.sh b3fix random 17 verilator
dbglab: test=random seed=17
PRECURSOR cycle=483: DMA run #4 is a fill, and FILL was never written since reset (it holds 00000000)
...
PASS test=random seed=17 cycles=18442 time=184416 ns

Read the recorder: the CPU set CTRL to 0x12 (a fill), then SRC, DST, LEN and START, and never FILL. The precursor fires 7,466 cycles before the symptom in Icarus. In Verilator it fires at the same cycle in a run that passes: the bug is there, and only the start value hides its effect. A check on the symptom can never see that; a check on the precursor does.

Is the precursor the whole story? Run it over the same 1,000 seeds as Part 1:

$ ./sweepA.sh                 # probes/run-fp.sh on random seeds 1 to 1000, one summary line each
$ awk '{print $2, $3}' sweepA.txt | sort | uniq -c
 884 precursor=0 fail=0
  16 precursor=1 fail=0
 100 precursor=1 fail=1

All 100 failing seeds fired the precursor first, and no seed failed without it: the precursor is necessary for this failure. It also fired in 16 seeds that passed. Those are not false alarms; the bug happened in them too, and the test never noticed:

$ vvp -n build/ow.vvp +TEST=random +SEED=86 +LO=1003 +HI=1011 | grep -E "OW|PASS"
OW cycle 978: master 1 writes xxxxxxxx to word 1003
...
OW cycle 1014: master 1 writes xxxxxxxx to word 1011
OW cycle 1428: master 1 writes f4eadf6f to word 1003
...
OW cycle 3566: master 1 writes ee389092 to word 1003
...
OW cycle 3630: master 1 writes dd223f41 to word 1011
...
PASS test=random seed=86 cycles=18828 time=188276 ns

Seed 86 is one of them: its fill wrote X into words 1003 to 1011, and a later DMA copy overwrote all nine (cycles 3566 to 3630) before anything read them. The bug happened; the test was lucky. A precursor check reports it anyway.

Localise and hypothesise

The precursor names the value the DMA loaded: cfg_fill, which is csr_block's fill_q. Its history is short:

$ git log --oneline -- rtl/csr_block.sv | head -2
b357bd8 csr: no reset on the DMA address and data registers
bc2bb34 dma: fill mode

1
2
3
4
5
6
7
8
9

// snippet: rtl/csr_block.sv at HEAD, lines 55-62
  // 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;

The comment states the assumption, and it is true for SRC, DST and LEN, which every DMA run writes before START. It is false for FILL: the register map documents a reset value of 0, and the "zero a buffer" path relies on it. Hypothesis: FILL lost its reset in commit 14. It predicts four things not yet seen: with FILL reset, the zero-fill-first test passes in Icarus and with random start values; the pattern-first order still passes; every one of the 100 failing seeds passes; and the precursor still fires, now harmlessly, since software still never writes FILL.

Fix: give FILL its reset back

$ git diff rtl/csr_block.sv
diff --git a/rtl/csr_block.sv b/rtl/csr_block.sv
index fa08187..007dc77 100644
--- a/rtl/csr_block.sv
+++ b/rtl/csr_block.sv
@@ -39,6 +39,7 @@ module csr_block import dbglab_pkg::*; (
     if (!rst_n) begin
       scratch_q <= SCRATCH_RST; ctrl_q <= CTRL_RST; done_q <= 1'b0;
       err_q <= 1'b0; err_addr_q <= '0;
+      fill_q <= FILL_RST;
     end else begin
       done_q <= dma_done | (done_q & ~clr_done);             // set wins
       err_q  <= dma_err  | (err_q  & ~clr_err);
@@ -47,6 +48,7 @@ module csr_block import dbglab_pkg::*; (
         case (off)
           CSR_SCRATCH: scratch_q <= wdata;
           CSR_CTRL:    ctrl_q    <= wdata[7:0];
+          CSR_FILL:    fill_q    <= wdata;
           default: ;
         endcase
       end
@@ -59,7 +61,6 @@ module csr_block import dbglab_pkg::*; (
         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

Prove: the repro, old seeds, fresh seeds, random starts

$ cd b34fix                  # the scratch copy with the fix
$ for o in 0 1; do for s in $(seq 1 20); do tb/run.sh fill_order $s icarus +ORDER=$o | tail -1; done \
>   | cut -c1-4 | sort | uniq -c; done
  20 PASS
  20 PASS
$ XRAND=1 tb/run.sh fill_order 1 verilator +ORDER=0
dbglab: test=fill_order seed=1
PASS test=fill_order seed=1 cycles=199 time=1986 ns
$ cd ..
$ probes/run-fp.sh b34fix random 17 | grep -E "^(PRECURSOR|PASS|FAIL)"
PRECURSOR cycle=483: DMA run #4 is a fill, and FILL was never written since reset (it holds 00000000)
PASS test=random seed=17 cycles=18442 time=184416 ns
$ ./sweepB.sh; cut -c1-4 sweepB.txt | sort | uniq -c      # random, seeds 1 to 1000
1000 PASS
$ ./sweepD.sh; cut -c1-4 sweepD.txt | sort | uniq -c      # random, fresh seeds 1001 to 2000
1000 PASS
$ ./sweepC.sh                # XRAND=1 in Verilator, seeds 1 to 200, before and after
$ for f in sweepC-b3fix.txt sweepC-b34fix.txt; do cut -c1-4 $f | sort | uniq -c; done
  21 FAIL
 179 PASS
 200 PASS

All four predictions held. Read the proof in the order of its strength.

• The ordered repro. Zero fill first went from 20 failures in 20 to 20 passes, in Icarus and with random start values. Before the fix its rate was at least 83% (the exact 95% low end for 20 in 20), so two clean runs already rule it out at 95%; twenty leave no doubt.

• The old failing seeds. Seeds 1 to 1,000 include the 100 that failed before. All 1,000 pass, so every known failure is gone. Fisher's test on 100 in 1,000 against 0 in 1,000 gives p = 1.2 × 10⁻³¹.

• Fresh seeds. 1,001 to 2,000 had never run. Zero failures in 1,000 bound the remaining rate on new stimulus below 0.30% at 95%, against 8.2% to 12.0% before.

• Random start values. In Verilator with XRAND=1, 21 of 200 seeds failed before and none after: the fix holds whatever the flops power up with.

• The precursor still fires in seed 17 and the run passes, as predicted: software still never writes FILL, and FILL now resets to the documented 0.

Prevent: leave the repro and the stress behind

• The ordered test joins the regression. fill_order with both orders runs in a fraction of a second and fails every seed if FILL ever loses its reset again.

• A random-start lane. One nightly lane in Verilator with XRAND=1 would have caught B4 at the 10% rate as a wrong value instead of passing it silently. The X and reset bugs lesson adds a reset-value check that catches it at cycle 5.

• A review question. For every register without a reset: does software write it before every use, including the paths that rely on a documented reset value? The commit message's "always programmed before START" was true for three of the four registers.

What the evidence says

Every step left an output: a rate, a command that fails every time, a probe line at the cause, a one-commit history, a prediction that held in three simulations, a two-line fix and a proof with numbers in it. What made this an intermittent hunt rather than an ordinary one was the order that made it deterministic, the precursor that saw the bug where the symptom could not, and the fresh seeds that turned "it passed" into a bound. Part 9 takes Prove and Prevent further.

Traps

Related topics

• Part 8 · Intermittent Failures

• X in a waveform: the same register from the X side

• X and reset bugs: the class

• Part 9: fix, prove, prevent