Twelve cycles and a red line

The regression of dbglab has one new failure, in the interrupt test:

$ tb/run.sh irq_w1c 1
dbglab: test=irq_w1c seed=1
FAIL test=irq_w1c seed=1 cycle=84: IRQ: irq=1 while CTRL=00 enables no interrupt

You dump the run, open the waveform at cycle 84, and add the signals that look relevant: the CPU's bus handshake, the DMA engine's busy and done, the control register, the interrupt. Twelve cycles, six lanes, all of them moving or stuck in ways that could mean something. Where do you look first?

What people usually do, and why it fails

Most people browse. They scan the lanes from top to bottom, stop at whatever looks unusual, and build a story around it. A waveform viewer makes this easy: one more signal is one click, and every signal looks equally important on the screen.

Browsing fails for two reasons. A real design always has something that looks odd: a request waiting, a counter wrapping, a flag that pulses. If you have no question, every odd thing is a candidate, and you follow the first one. And a waveform cannot tell you what is wrong, only what happened. Wrong means different from what was expected, and you cannot judge a lane until you have said what it should be. Browsing skips that step, so it feels like work and gives you nothing to rule out.

The method: one question, then only what it needs

This is the Observe step of the debug loop. Its output is the first wrong value you can point at. Five rules get you there:

1. Write the question first. One signal, one cycle, one expected value: why is `irq` 1 at cycle 84, when CTRL enables no interrupt? The failure message usually gives you all three.

2. Pick lanes from the logic, not the screen. Keep the questioned signal and the signals it is computed from. Look at the RTL line that drives it, not at the hierarchy browser.

3. Pick the cycles. Start at the cycle in the question and the cycle before it. Widen only when an input is wrong and you need to see when it went wrong.

4. Judge each lane: right or wrong, at that cycle. A lane you cannot judge has no place in this question.

5. Move the question. When you find a wrong input, it becomes the next question: why is this input wrong, and since when? When every input in the window is right, or wrong from the first slot, the cause is outside the window.

The picture: one real window of dbglab

This is dbglab's own RTL and bench, at HEAD, running irq_w1c with seed 1: the run that failed above. The window is the last twelve cycles before the failing check, cycles 73 to 84. ctrl is the CSR block's CTRL register.

Each slot is one bus clock, sampled just after the rising edge; slot 0 is cycle 73 and slot 11 is cycle 84.

• Slots 0 to 10: the CPU holds cpu_valid high with cpu_ready low; the DMA is busy.

• Slot 10 (cycle 83): dma_done pulses for one cycle.

• Slot 11 (cycle 84): the DMA is idle, the CPU gets ready, and irq rises.

• Every slot: ctrl holds 1 (01 in hex).

Do it: read the same window twice

Read 1: browsing

Read top to bottom, as most people do. The first thing that jumps out is the CPU: cpu_valid is high for twelve cycles and ready never comes until the last slot. That looks like a stalled bus, and a stall is a classic bug, so this is where a browsing reader starts digging. Is the arbiter stuck? Is the DMA hogging the bus? Then dma_done pulses, irq rises, and the CPU is finally served. A plausible story forms: the DMA held the bus too long and something went wrong with the interrupt at the end.

Notice what that read did not do. It never said what any lane should have been. It spent its attention on the CPU lanes, the most visible thing on the screen, and it ended with a story that cannot be tested.

Read 2: with the question

Now write the question down first: why is `irq` 1 at cycle 84, when software has not enabled any interrupt? Then find what irq is made of. One line of the CSR block drives it:

// snippet: rtl/csr_block.sv at HEAD, line 99
  assign irq      = (done_q & ctrl_q[CTRL_DONE_IE]) | (err_q & ctrl_q[CTRL_ERR_IE]);

So the lanes that matter are irq, the done flag (set by dma_done the cycle before) and ctrl. The CPU's valid and ready are not in that equation. They may be interesting, but they cannot answer this question, so you stop looking at them. Now judge each lane at cycle 84 and the cycle before:

Three lanes, one verdict each, and the answer is not where the failure is. irq did exactly what its logic says. Its input ctrl is wrong, and it is wrong in every slot. The window holds no cycle where ctrl changes, so the cause is earlier than cycle 73. Rule 5 applies: move the question.

The next question

The new question: when did CTRL become 01, and who wrote it? That needs a different view, not a wider window. Twelve cycles of six lanes will not show it; one line per change of CTRL will. A small probe compiled next to the design prints every change of ctrl_q and every CPU write to CTRL (address 0x2008):

1
2
3
4
5
6
7
8
9
10

// not-run: needs dbglab's sources and bench; compile it next to them (command in the Evidence box)
// ctrl_watch: prints every change of the CSR CTRL register and every CPU write to it.
`timescale 1ns/1ps
module ctrl_watch;
  always @(dbglab_tb.dut.u_csr.ctrl_q)
    $display("cycle %0d: ctrl_q = %h  (rst_n=%b)", dbglab_tb.cycle, dbglab_tb.dut.u_csr.ctrl_q, dbglab_tb.rst_n);
  always @(posedge dbglab_tb.clk)
    if (dbglab_tb.cpu_valid && dbglab_tb.cpu_ready && dbglab_tb.cpu_write && dbglab_tb.cpu_addr == 32'h2008)
      $display("cycle %0d: CPU writes CTRL = %h", dbglab_tb.cycle, dbglab_tb.cpu_wdata);
endmodule

$ ../probes/run-probe.sh ../probes/ctrl_watch.sv irq_w1c 1
dbglab: test=irq_w1c seed=1
cycle 1: ctrl_q = 01  (rst_n=0)
FAIL test=irq_w1c seed=1 cycle=84: IRQ: irq=1 while CTRL=00 enables no interrupt

Read it line by line. CTRL changed once, at cycle 1, while reset was still asserted. The CPU never wrote it. So CTRL came out of reset as 01, and the register map says 0. The first wrong value is CTRL's reset value; everything in the twelve-cycle window was a consequence of it. Which commit changed the reset value is a job for bisection in history, which finds it in four runs.

What the evidence says

The question cut six lanes to three and twelve cycles to two, and then it said something the browsing read never could: the answer is outside this window. That is a real result. It tells you not to widen the waveform around cycle 84, where nothing will change, but to go back to reset.

And the CPU stall that caught the browsing reader? It is real and it is by design: the DMA keeps the bus for a whole chunk of a copy, so a CPU poll waits. Whether that is acceptable is a fair question, and a later case study shows when it is not. It is not this question, and a browsing reader would have spent the morning on it.

Every waveform hunt follows the same shape: question, lanes from the logic, verdicts, then either a wrong input to follow or a new question about an earlier time. For the waveform patterns that recur in RTL (a missing default, a blocking-assignment race), see the RTL course's waveform debug lessons, and for walking a wrong value back cycle by cycle, Part 3: Localise.

Traps

Related topics

• Part 2 · Observe

• Dump strategy: what to dump, and when

• Part 3: Localise

• RTL: waveform bug patterns (latch and race)

• RTL: debug hierarchy before touching code