Nineteen failures on a Monday morning

The nightly regression ran dbglab's random test with sixty seeds, and nineteen of them failed. The release is on Friday. Your lead asks one question: how long will it take?

You cannot answer that yet. You can promise a method: nine steps, the same for every bug in this course, each with an output you can show. Where do you start?

What people usually do, and why it fails

Here is how this bug often goes. The story is illustrative; the runs in it are real.

An engineer opens the first failure, seed 10: a RAM word read back wrong. RAM bugs are often write-enable races, so they add a cycle of delay to the RAM's write enable and rerun seed 10. It still fails. They try seed 11 to see whether the problem is general:

$ tb/run.sh random 11
dbglab: test=random seed=11
PASS test=random seed=11 cycles=18509 time=185086 ns

Seed 11 passes, so the failure looks intermittent. The delay is left in "just in case", the bug is marked cannot reproduce, and the release goes ahead. Three weeks later a customer's driver copies 300 words and gets 44.

Every step of that story was a guess: a change before anyone looked at the hardware, a pass on another seed read as evidence, and nothing left behind to catch the bug next time. The engineer was not careless. They had no method.

The debug loop: nine steps, each with an output

The top row is a search: each step shrinks the space where the bug can hide. The bottom row closes the bug. A step is done when it has produced its output, not when you feel ready to move on.

The loop is not a straight line. A failed test sends you back to Observe, a failed proof back to Fix. That is normal, as long as you know which step you are on.

One real bug, round the whole loop

The bug below is in dbglab, the course's running design: a bus with a CPU port, a DMA engine, RAM and a few peripherals. Every command runs in a copy of its history at HEAD.

Report: say what failed, not what you think broke

Start with the facts, grouped by signature. Two failures with different messages may be two different bugs, so sort them before you pick one.

$ for s in $(seq 1 60); do tb/run.sh random $s | grep FAIL; done > sweep.txt
$ wc -l < sweep.txt
      19
$ grep -c xxxxxxxx sweep.txt
9
$ grep -v xxxxxxxx sweep.txt
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=59 cycle=3217: SCOREBOARD: RAM word 377 (address 000015e4) read 913f438a, expected 3fec7961 (last written by DMA run #22)

Nine failures show an unknown value (xxxxxxxx). The other ten read a real but wrong value, and every one of those names a DMA run as the last writer of the word. That is two signatures, so treat them as two bugs until proven otherwise. Take the second group, and its first seed. The report: random, seed 10, HEAD 49c5f04: RAM word 808 should hold b6c3311c, written by DMA run #29; it reads d5202ff9.

Reproduce: one command that fails every time

$ tb/run.sh random 10
dbglab: test=random seed=10
FAIL test=random seed=10 cycle=4895: SCOREBOARD: RAM word 808 (address 00001ca0) read d5202ff9, expected b6c3311c (last written by DMA run #29)
$ tb/run.sh random 10 verilator
dbglab: test=random seed=10
FAIL test=random seed=10 cycle=4895: SCOREBOARD: RAM word 808 (address 00001ca0) read d5202ff9, expected b6c3311c (last written by DMA run #29)

Same line, same cycle, in two simulators. The seed fixes the stimulus, so this command is now the bug. It is also the command you will use to prove the fix.

Observe: look at what the hardware did

The scoreboard says where the damage was found, not where it was done. It found word 808 wrong at cycle 4895, but DMA run #29 was supposed to write it. So look at run #29. You do not need a waveform viewer for that: a small probe module, compiled next to the design, can print what the DMA was told and what it did. It reads signals by their hierarchical names and changes nothing. The script run-probe.sh used below just compiles it with dbglab's file list and runs the test (the exact command is in the Evidence box).

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

// not-run: needs dbglab's sources and bench; compile it next to them (command in the Evidence box)
// dma_probe: prints the start and the end of DMA run +RUN=<n>. It only reads the design.
`timescale 1ns/1ps
module dma_probe;
  int unsigned want, run = 0, writes = 0;
  logic started = 1'b0;
  initial if (!$value$plusargs("RUN=%d", want)) want = 0;   // 0: every run
  always @(posedge dbglab_tb.clk) begin
    #0.5;                                                     // just after the edge
    if (dbglab_tb.dut.u_dma.m_rvalid && dbglab_tb.dut.u_dma.state.name() == "WR_RSP") writes++;
    if (started && (want == 0 || run == want))
      $display("cycle %0d: DMA run #%0d start  LEN=%0d SRC=%h DST=%h  left_q=%0d",
               dbglab_tb.cycle, run, dbglab_tb.dut.u_dma.cfg_len, dbglab_tb.dut.u_dma.src_q,
               dbglab_tb.dut.u_dma.dst_q, dbglab_tb.dut.u_dma.left_q);
    started = 1'b0;
    if (dbglab_tb.dut.u_dma.start && !dbglab_tb.dut.u_dma.busy) begin
      run++; writes = 0; started = 1'b1;
    end
    if (dbglab_tb.dut.u_dma.done && (want == 0 || run == want))
      $display("cycle %0d: DMA run #%0d done   words written=%0d  dst_q=%h",
               dbglab_tb.cycle, run, writes, dbglab_tb.dut.u_dma.dst_q);
  end
endmodule

$ ../probes/run-probe.sh ../probes/dma_probe.sv random 10 +RUN=29
dbglab: test=random seed=10
cycle 4443: DMA run #29 start  LEN=308 SRC=000015e8 DST=00001b1c  left_q=52
cycle 4859: DMA run #29 done   words written=52  dst_q=00001bec
FAIL test=random seed=10 cycle=4895: SCOREBOARD: RAM word 808 (address 00001ca0) read d5202ff9, expected b6c3311c (last written by DMA run #29)

Read it line by line. The first line prints at cycle 4443, one cycle after run #29 starts (4442), when left_q holds its load. Software asked for 308 words. The DMA's counter of words still to write, left_q, loaded 52, and the run ended after 52 words at 0x1bec. Word 808, at 0x1ca0, was never written. The bench was right; the DMA stopped early.

Localise: find the first wrong value

Walk back from the symptom until the values are right again. The read at cycle 4895 is wrong because the copy was short, the copy was short because left_q was 52, and left_q was wrong the cycle it loaded (4443) from a length that was right. The first wrong value is left_q = 52 where 308 was expected, inside dma_engine. Everything after that is a consequence. Now the code to read is a few lines, not the whole design:

1
2
3
4

// snippet: rtl/dma_engine.sv at HEAD, 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);

Hypothesise: a cause that predicts something new

52 is 308 minus 256. The counter is 8 bits wide, the length register is 10 bits, and the cast drops the top two bits. Hypothesis: any run longer than 255 words writes only its length minus 256 (or minus 512, and so on). Notice what this predicts that you have not checked yet: every other wrong-value failure must also come from a run longer than 255 words, short by exactly 256.

Test: run the experiment that could prove you wrong

Seed 13 failed on DMA run #22. Before running anything, write down the prediction: run #22 is longer than 255 words, and left_q is its length minus 256.

$ ../probes/run-probe.sh ../probes/dma_probe.sv random 13 +RUN=22
dbglab: test=random seed=13
cycle 3227: DMA run #22 start  LEN=290 SRC=000017d0 DST=000010a4  left_q=34
cycle 3501: DMA run #22 done   words written=34  dst_q=0000112c
FAIL test=random seed=13 cycle=3701: SCOREBOARD: RAM word 250 (address 000013e8) read f42b063a, expected c6278de6 (last written by DMA run #22)

290 words asked, 34 loaded, 34 written: 290 minus 256. The prediction could have failed, and it did not. Running the same probe over all sixty seeds makes it stronger: exactly the ten seeds that fail with a wrong value contain a run longer than 255 words, and none of the 41 passing seeds does. Seed 11 passed only because the random test makes a long run once in 400; it never drew one.

Fix: change the cause

The cause is the counter's width, so the fix is the width. A 10-bit length needs a 10-bit counter:

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

Prove: the same command, then a wider net

$ tb/run.sh random 10
dbglab: test=random seed=10
PASS test=random seed=10 cycles=21581 time=215806 ns
$ tb/run.sh random 10 verilator
dbglab: test=random seed=10
PASS test=random seed=10 cycles=21581 time=215806 ns
$ for s in $(seq 1 60); do tb/run.sh random $s | grep FAIL; done > sweep.txt
$ wc -l < sweep.txt
       9
$ grep -c xxxxxxxx sweep.txt
9

The repro passes in both simulators. All ten wrong-value failures are gone; the nine left all show the other signature, the unknown value. That is a second bug for another day, and the reason you sorted the report first.

Prevent: leave a check behind

Why did nothing catch this earlier? The directed DMA test copies at most 64 words, and the random test makes a long run once in 400. A test aimed at the counter's edges costs a few lines:

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

// snippet: tb/tests.svh, a directed test for the beat counter's boundaries
// dma_long: copies at the beat counter's boundaries: 255, 256, 257 and 511 words (all that fit
// at word 512); the random test makes a run this long only once in 400.
task automatic t_dma_long();
  int len;
  csr_wr(CSR_CTRL, 32'h0);
  for (int k = 0; k < 4; k++) begin
    case (k)
      0: len = 255;
      1: len = 256;
      2: len = 257;
      default: len = 511;
    endcase
    run_copy(0, 512, len);
    for (int i = 0; i <= len; i++) ram_check(512 + i);   // the copy and one word after it
  end
endtask

$ tb/run.sh dma_long 1          # at HEAD, without the fix
dbglab: test=dma_long seed=1
FAIL test=dma_long seed=1 cycle=4920: SCOREBOARD: RAM word 516 (address 00001810) read 228510de, expected 934c82b1 (last written by DMA run #2)
$ tb/run.sh dma_long 1          # with the fix
dbglab: test=dma_long seed=1
PASS test=dma_long seed=1 cycles=14180 time=141796 ns

It fails on the 256-word copy at cycle 4920 with every seed tried (1, 2, 7 and 33). A second reason it escaped: the commit that narrowed the counter added the CW'() cast, and without the cast Verilator's lint would have warned (%Warning-WIDTHTRUNC: rtl/dma_engine.sv:89:19: Operator ASSIGNDLY expects 8 bits on the Assign RHS, but Assign RHS's VARREF 'cfg_len' generates 10 bits.). A cast tells the tool you meant to truncate. Before you write one, check that you did.

What the evidence says

Each step ruled something out. The report cut 19 failures to one group of ten; the repro turned a nightly result into a one-second command; observing run #29 moved the search from the scoreboard to the DMA; localising cut the DMA to three lines. The RTL did not change until a prediction had been tested.

Traps

Related topics

• Part 0 · What Debugging Is

• Bisection in history: find the commit that broke it

• Case study: the deadlock under back-pressure

• RTL: debug hierarchy before touching code

• RTL: FSM bug stories