Cycle 7949, and where to start

dbglab's random test fails with seed 17:

$ 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)

The scoreboard is precise: which word, which value, which value it expected, and who it thinks wrote it. The natural move is to dump a few hundred cycles around 7949 and look. How far back do you think the damage was done?

What people usually do, and why it fails

Most people start at the reported cycle. They open a window around 7949, see the CPU read an unknown value from RAM, and start suspecting the read path: the RAM, the fabric's response mux, the CPU port. Everything in that window is working correctly. The RAM returned what it held; it had held it for thousands of cycles.

The mistake is to read a scoreboard message as when something went wrong. It is when the bench noticed. A scoreboard compares at the moments it chooses to look, and the gap between the damage and the next look has nothing to do with the bug. It depends on the stimulus.

Why this scoreboard is late, and how to make checks early

dbglab's bench keeps a model of every RAM word and compares a word only when the CPU happens to read it, plus once more in a final sweep at the end of the test. The random test reads a random word out of 1,024 in about a quarter of its operations. A word written by the DMA can sit for thousands of cycles before anyone reads it. That is a reasonable scoreboard, and it is late by design.

This is the Observe step again, and the fix is to observe where the work is done. Five rules:

1. Treat the scoreboard cycle as the symptom. Start from the transaction it blames, and first check that the transaction did what the model thinks.

2. Check each transaction when it completes. When a DMA run finishes, compare its destination with the model right then, not on the next random read.

3. Check in order where order is defined. A stream, a FIFO, a response queue: compare each item as it comes out, so the first mismatch is the first wrong item.

4. Monitor internal interfaces. A monitor at a block's output port checks it as it produces data, before other blocks mix it up.

5. Keep the late checks. The random read and the final sweep catch what the early checks did not think of. They are the backstop, not the first line.

The picture: 7,423 cycles of silence

Nearly the whole run lies between the damage and the report. The window around 7949 that a person would dump first holds only the read.

Do it: measure the gap, then close it

Where the damage was really done

The structured log of the same run answers the first rule's question: did run #4 really write word 816 (0x1cc0), and when?

$ ../probes/run-probe.sh ../probes/txn_log.sv random 17 +VERB=3 > b4.log
$ grep 'run=4 ' b4.log
cyc=483 lvl=INFO who=dma run=4 ev=START len=9 src=00001344 dst=00001ca8 ctrl=12
cyc=489 lvl=DBG who=dma run=4 ev=WR addr=00001ca8 data=xxxxxxxx resp=OK lat=1
...
cyc=515 lvl=DBG who=dma run=4 ev=WR addr=00001cc0 data=xxxxxxxx resp=OK lat=1
cyc=519 lvl=DBG who=dma run=4 ev=WR addr=00001cc4 data=xxxxxxxx resp=OK lat=1
cyc=525 lvl=DBG who=dma run=4 ev=WR addr=00001cc8 data=xxxxxxxx resp=OK lat=1
cyc=526 lvl=INFO who=dma run=4 ev=DONE err=0
$ grep 'addr=00001cc0' b4.log
cyc=515 lvl=DBG who=dma run=4 ev=WR addr=00001cc0 data=xxxxxxxx resp=OK lat=1
cyc=7948 lvl=DBG who=cpu op=1051 ev=RD addr=00001cc0 data=xxxxxxxx resp=OK lat=1

Read it line by line. Run #4 is a fill (ctrl=12) of nine words starting at 0x1ca8. Its first write is accepted at cycle 488 and answered at 489, and every one of its nine writes carries an unknown value. Word 816 is written at 515. Nothing touches it again until the CPU's read at 7948, which the bench reports at 7949. The scoreboard reported 7,434 cycles after word 816 was written, and 7,461 after the first bad write. Why FILL held an unknown value is traced in symptom, fault and cause and X in a waveform; here the question is only when could we have known?

A check at the end of every run

The bench already has everything a per-transaction check needs: the model of the RAM and the value the model expects a fill to write. A small module compiled next to dbglab compares each finished DMA run's destination with the model the moment the run ends:

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

// not-run: needs dbglab's sources and bench; compile it next to them (command in the Evidence box)
// run_check: a per-transaction check. When a DMA run into RAM finishes without an error, compare
// every destination word with what the bench's model says the run should have written: the
// source words for a copy, the model's FILL value for a fill. Compiled next to dbglab; reads only.
`timescale 1ns/1ps
module run_check;
  import dbglab_pkg::*;
  int unsigned run = 0, bad;
  logic [31:0] src, dst, exp;
  int          len, s, d, first;
  logic [7:0]  ctrl;
  always @(posedge dbglab_tb.clk) begin
    #0.5;                                              // just after the edge
    if (dbglab_tb.dut.u_dma.start && !dbglab_tb.dut.u_dma.busy) begin
      run++;
      src = dbglab_tb.dut.dma_src; dst = dbglab_tb.dut.dma_dst;
      len = dbglab_tb.dut.dma_len; ctrl = dbglab_tb.dut.dma_ctrl;
    end
    if (dbglab_tb.dut.u_dma.done && !dbglab_tb.dut.u_dma.err && !ctrl[CTRL_DST_FIXED]
        && dst >= RAM_BASE && dst < RAM_BASE + 32'h1000) begin
      s = (src - RAM_BASE) / 4; d = (dst - RAM_BASE) / 4; bad = 0; first = -1;
      for (int i = 0; i < len; i++) begin
        exp = ctrl[CTRL_FILL] ? dbglab_tb.m_fill : dbglab_tb.m_ram[s + i];
        if (dbglab_tb.dut.u_ram.mem[d + i] !== exp) begin
          bad++;
          if (first < 0) first = i;
        end
      end
      if (bad != 0) begin
        exp = ctrl[CTRL_FILL] ? dbglab_tb.m_fill : dbglab_tb.m_ram[s + first];
        $display("FAIL cycle=%0d: RUN_CHECK: DMA run #%0d (%s, LEN %0d, DST %h) left %0d of %0d words wrong; first: word %0d holds %h, expected %h",
                 dbglab_tb.cycle, run, ctrl[CTRL_FILL] ? "fill" : "copy", len, dst, bad, len,
                 d + first, dbglab_tb.dut.u_ram.mem[d + first], exp);
        $fatal(1, "run check failed");
      end
    end
  end
endmodule

Two choices keep it honest. The expected value comes from the bench's model (m_ram, m_fill), never from the design, so a design bug cannot make both sides agree. And it skips runs that ended in an error or wrote to the peripheral, which the bench checks elsewhere.

$ ../probes/run-probe.sh ../probes/run_check.sv random 17
dbglab: test=random seed=17
FAIL cycle=526: RUN_CHECK: DMA run #4 (fill, LEN 9, DST 00001ca8) left 9 of 9 words wrong; first: word 810 holds xxxxxxxx, expected 00000000
$ ../probes/run-probe.sh ../probes/run_check.sv random 10
dbglab: test=random seed=10
FAIL cycle=4859: RUN_CHECK: DMA run #29 (copy, LEN 308, DST 00001b1c) left 256 of 308 words wrong; first: word 763 holds 42ea2b0d, expected 411aabf8

Seed 17 now fails at cycle 526 instead of 7949, the cycle after run #4 finished, and the message names the run, its kind and its size: a nine-word fill wrote nine wrong words. That is already most of the way to "the fill value is wrong". Seed 10, the length bug, fails at the end of run #29 with "256 of 308 words wrong" and the first one at word 763, which is exactly 52 words into the destination.

Before and after, over every failing seed

One seed proves little; the gap depends on when the random test happens to read. Running all 60 seeds of random with and without the check:

Every failure moved earlier. The gap is small when the random test happens to read a damaged word soon after the run and huge when it does not, which is the point: with the check, the report no longer depends on luck. Seed 23 is worth a look. Its zeroed buffer was copied into the peripheral, and the bench's stream check, which compares words in order as they come out, caught it at 2385: much earlier than a random RAM read would have, because an in-order check looks at every word. The per-run check still beat it, because it looked at the RAM before the copy.

Is the check clean? On a copy of HEAD with both bugs fixed, it passes all 60 seeds, and the other six tests (seeds 1 to 3) fail only with the other bugs' own messages, never RUN_CHECK. It costs 2.15 s against 2.14 s on a 194,134-cycle run: it reads a few words per DMA run, and nothing else.

What the evidence says

The scoreboard was right every time: the data was wrong. It was late every time, by an amount set by the stimulus. A check that runs when each transaction completes turned "RAM word 816 is wrong at 7949" into "DMA run #4, a fill, wrote nine wrong words, at 526", which is a different starting point for the hunt: one run, one register to suspect (the fill value), and a window of 43 cycles. The first wrong cycle is the next step from there.

Traps

Related topics

• Part 2 · Observe

• Comparing a good and a bad run

• Part 3: Localise

• UVM: debugging the testbench