A wrong word at cycle 3701

dbglab's random test fails with seed 13:

$ tb/run.sh random 13
dbglab: test=random seed=13
FAIL test=random seed=13 cycle=3701: SCOREBOARD: RAM word 250 (address 000013e8) read f42b063a, expected c6278de6 (last written by DMA run #22)

The bench read RAM word 250 and got a value it did not expect. The line even names a suspect, DMA run #22. But cycle 3701 is only where the bench happened to look. Where, and when, did the design first go wrong?

What people usually do, and why it fails

The usual move is to dump the run, open the waveform at cycle 3701 and look around: the CPU's read, the RAM's output, the bus. Everything there is quiet and plausible. The RAM returned what it holds, the bus carried it faithfully, and nothing near that cycle is broken. The engineer widens the window, adds more signals, and starts reading the DMA code from the top, hoping something stands out.

This fails because the failing cycle is the end of a chain, not its start. Each link in the chain was a correct reaction to a wrong input, so the cycles around the symptom all look right. What finds the start is a procedure: follow the wrong value back, one hop at a time, asking the same question at each hop. On the debug loop this is Localise.

The method: walk back one hop at a time

1. Write the symptom as four facts: which signal, which cycle, what it was, what it should have been. Here: the read of word 250 at cycle 3699 (reported at 3701) returned f42b063a; it should have returned c6278de6.

2. Find what made the value. A value is made by a line of logic from its inputs, or by an event that should have written it: a register load, a bus write, a pulse.

3. Judge each input at the cycle it was used. Right or wrong, against what the design was meant to do: the register map, the test's request, the spec. Not against what the code does.

4. If an input is wrong, it is the new symptom. Write its four facts and go back to step 2.

5. Stop when every input is right and the output is wrong. That is the first wrong cycle, and the logic between those inputs and that output is where the bug lives.

6. Keep a hop table. One row per hop: signal, cycle, actual, expected, verdict. It is your notes, the evidence for the next step, and the core of the bug report.

Every hop needs a way to ask "what was this signal at that cycle?" A waveform answers it, and so does a small probe that prints a few signals at the moments you care about. Reading a waveform with a question is one hop done well; this lesson chains the hops.

The picture: the walk on seed 13

Read the boxes right to left, in the order of the circled numbers. Each hop moves to the input that was wrong, and the walk stops at the box whose input (the box to its left) is right.

Do it: four hops with one probe

The probe below answers every question this walk asks. It reads signals by their hierarchical names and changes nothing; it is compiled next to dbglab with the design's own file list (the command is in the Evidence box). +WORD watches one RAM word, +RUN watches one DMA run.

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

// not-run: needs dbglab's sources and bench; compile it next to them (command in the Evidence box)
// walk_back: one probe per question of the walk back. It only reads the design.
//   +WORD=<n>  every request that reaches RAM word n: who made it, and what the RAM held
//   +RUN=<n>   DMA run n: the LEN the CPU wrote, what the DMA loaded, each write it made
`timescale 1ns/1ps
module walk_back;
  int unsigned word, want, run = 0;
  bit loaded = 1'b1;
  string who [2] = '{"cpu", "dma"};
  initial begin
    if (!$value$plusargs("WORD=%d", word)) word = 32'hFFFF_FFFF;
    if (!$value$plusargs("RUN=%d", want)) want = 0;
  end
  always @(posedge dbglab_tb.clk) begin
    #0.5;                                                      // just after the edge
    if (dbglab_tb.dut.s_req[0] && dbglab_tb.dut.s_addr[11:2] == word[9:0])
      $display("cycle %0d: word %0d %s by %s, RAM holds %h", dbglab_tb.cycle, word,
               dbglab_tb.dut.s_write ? "WRITE" : "read ", who[dbglab_tb.dut.u_fab.owner],
               dbglab_tb.dut.u_ram.mem[word]);
    if (dbglab_tb.dut.s_req[1] && dbglab_tb.dut.s_write && dbglab_tb.dut.s_addr[11:0] == 12'h018
        && run + 1 == want)
      $display("cycle %0d: CPU writes LEN = %0d", dbglab_tb.cycle, dbglab_tb.dut.s_wdata);
    if (!loaded) begin
      $display("cycle %0d: run %0d loads left_q = %0d from cfg_len = %0d", dbglab_tb.cycle, run,
               dbglab_tb.dut.u_dma.left_q, dbglab_tb.dut.u_dma.cfg_len);
      loaded = 1'b1;
    end
    if (dbglab_tb.dut.u_dma.start && !dbglab_tb.dut.u_dma.busy) begin
      run++;
      if (run == want) begin
        loaded = 1'b0;
        $display("cycle %0d: run %0d starts, cfg_len = %0d, left_q = %0d", dbglab_tb.cycle, run,
                 dbglab_tb.dut.u_dma.cfg_len, dbglab_tb.dut.u_dma.left_q);
      end
    end
    if (run == want && dbglab_tb.dut.m_valid[1] && dbglab_tb.dut.m_ready[1] && dbglab_tb.dut.m_write[1])
      $display("cycle %0d: run %0d writes %h, left_q = %0d", dbglab_tb.cycle, run,
               dbglab_tb.dut.m_addr[1], dbglab_tb.dut.u_dma.left_q);
    if (run == want && dbglab_tb.dut.u_dma.done)
      $display("cycle %0d: run %0d done", dbglab_tb.cycle, run);
  end
endmodule

$ ../probes/run-probe.sh ../probes/walk_back.sv random 13 +WORD=250 +RUN=22
dbglab: test=random seed=13
cycle 3222: CPU writes LEN = 290
cycle 3226: run 22 starts, cfg_len = 290, left_q = 0
cycle 3227: run 22 loads left_q = 34 from cfg_len = 290
cycle 3242: run 22 writes 000010a4, left_q = 34
cycle 3247: run 22 writes 000010a8, left_q = 33
...
cycle 3499: run 22 writes 00001128, left_q = 1
cycle 3501: run 22 done
cycle 3699: word 250 read  by cpu, RAM holds f42b063a
FAIL test=random seed=13 cycle=3701: SCOREBOARD: RAM word 250 (address 000013e8) read f42b063a, expected c6278de6 (last written by DMA run #22)

The output runs forward in time. The walk reads it from the bottom up.

Hop 1: the read

At cycle 3699 the CPU reads word 250 and the RAM holds f42b063a. The RAM returned exactly what it holds, so the read path is right given its input. The wrong thing is the content of word 250. What should have written it? The bench's model says DMA run #22.

Hop 2: the write that never came

The probe watches every request that reaches word 250, and between the start of the test and the read it printed none: no write by anyone. That is a missing event. Run #22 copied to destination 0x10a4, which is word 41 (with +WORD=41 the probe shows the DMA's write there at cycle 3242), so its 290 words cover words 41 to 330, and word 250 is the 210th of them. The run should have written it, and did not.

Hop 3: the run that stopped early

Run #22 made 34 writes, from 0x10a4 to 0x1128, and reported done at cycle 3501. Every write moved on by one word and counted left_q down by one, exactly as the DMA's code says. Given left_q = 34 at the start, the 34 writes and the early done are right. So the input to judge is the starting value of left_q.

Hop 4: the load

At cycle 3227, one cycle after the start, left_q loads 34 from cfg_len = 290. Now judge the input: is cfg_len right? The CPU wrote LEN = 290 at cycle 3222, and 290 is the length the test asked for (the model expects a 290-word copy). Input right, output wrong: cycle 3227 is the first wrong cycle, and the place is the line that loads left_q.

Here is the same moment in a real waveform of the run:

Each slot is one bus clock, sampled just after the rising edge; slot 0 is cycle 3221 and the values are hexadecimal (0x122 is 290, 0x22 is 34).

• Slot 2 (cycle 3223): cfg_len becomes 122, the CPU's LEN write of 290. Right.

• Slot 5 (cycle 3226): dma_start pulses while the DMA is idle.

• Slot 6 (cycle 3227): dma_busy rises and left_q loads 22, not 122. This is the first wrong slot; every slot before it is right.

The hop table, which is what goes into the notes and the bug report:

What the evidence says

Four hops took the search from a read at cycle 3699 to one assignment at cycle 3227, 472 cycles earlier and in a different block. Everything downstream of that cycle is a consequence and can be ignored. The next step of the loop is Hypothesise: why would a 10-bit length of 290 load as 34? 290 minus 34 is 256. You met this run in the debug loop, as the prediction that confirmed the counter hypothesis; there the walk was one sentence, here it is the method. The debug loop takes the bug on from here: hypothesis, fix and proof, on seed 10.

1
2
3
4

// snippet: rtl/dma_engine.sv at HEAD, lines 36-37 and 89, the logic at the first wrong cycle
  localparam int CW = 8;           // beat counter width
  logic [CW-1:0] left_q;           // words still to write
          left_q  <= CW'(cfg_len);

Traps

Try it: find the first wrong cycle

Each trace below is short and comes from a small model with one bug. The checker's message is at the top and the dashed line marks where it fired. Click a signal at a cycle to compare it with the model, and walk back until nothing earlier differs. Count your probes: a good walk follows the cone of influence, not every signal at every cycle.

Related topics

• Part 3 · Localise

• Next: bisection in time

• The debug loop: the same bug, hypothesis and fix

• Assertions as always-on probes: a check at this very line

• RTL: debug waveforms