Twenty-nine DMA runs, and one of them matters

dbglab's random test fails with seed 10, every time, in both simulators:

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

Before that line the bench made 363 operations: RAM reads and writes, register writes, words into the peripheral, idle gaps and 29 DMA runs. Somewhere in there is the cause. Which operations does the failure actually need?

What people usually do, and why it fails

The usual move is to open a waveform at cycle 0 and read forward, or to start deleting parts of the test by hand to see what still fails. Reading forward means looking at thousands of cycles that do not matter. Deleting by hand is slow and error-prone: you remove ten operations, the test passes, and you cannot tell whether you removed the cause or merely changed the timing so another check fires first. Most people give up after a few tries and debug the long test.

Shrinking is a search, and searches can be automated. You need three things: a test you can run with less stimulus, a machine-checkable definition of "the same failure", and a loop that tries smaller tests.

The method

1. Fix the repro. The run must be deterministic (determinism and seeds), or the shrinker chases noise.

2. Write the signature. A regular expression that matches this failure and no other: the check that fires and what it says, without the parts that change as the test shrinks (cycle numbers, run numbers, addresses).

3. Shrink the length first. Most random benches take a length. Bisect it to the shortest run that still fails with the signature. This is cheap and needs no bench change.

4. Then shrink the content. Record the operations as a list the bench can replay, and let delta debugging remove chunks of it, keeping any smaller list that still fails with the signature.

5. Keep every try legal. A shortened list must still obey the bench's rules, or the shrinker will find a broken test instead of your bug.

6. Read the result and keep it. The small list usually says what the bug is. It becomes the directed regression test.

Delta debugging ("ddmin") is a simple algorithm. Split the list into two halves and try each on its own. If neither fails, try removing one half; if that fails neither, split into more, smaller chunks and repeat. Every time a smaller list still fails, keep it and start again. It stops when no single operation can be removed.

The picture

Both runs start the same way: halving works while the failure needs only one small region of the list. They differ at 23 operations, where the definition of "same failure" takes over. The two sections below explain why.

Do it, step 1: shrink the length

dbglab's random test reads +OPS=<n>, the number of operations (default 1500). This script bisects it:

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

# not-run: runs dbglab's simulator through subprocess; run it from the dbglab folder (command in the Evidence box)
"""shrink_ops.py: the fewest +OPS for which a seed still fails with the same signature.
usage: python3 shrink_ops.py <seed> <max_ops> <signature regex>"""
import re, subprocess, sys

seed, hi, sig = sys.argv[1], int(sys.argv[2]), re.compile(sys.argv[3])

def fails(ops):
    out = subprocess.run(["vvp", "-n", "build/dbglab.vvp", "+TEST=random", f"+SEED={seed}", f"+OPS={ops}"],
                         capture_output=True, text=True).stdout
    line = next((l for l in out.splitlines() if l.startswith("FAIL")), "")
    hit = bool(sig.search(line))
    print(f"OPS={ops:5d}  {'same failure' if hit else ('other failure' if line else 'pass')}  {line[:90]}")
    return hit

assert fails(hi), "the starting length must fail"
lo = 0                       # invariant: lo passes (or is 0), hi fails with the signature
while hi - lo > 1:
    mid = (lo + hi) // 2
    if fails(mid): hi = mid
    else: lo = mid
print(f"smallest failing OPS: {hi}")

$ python3 ../shrink/shrink_ops.py 10 1500 'SCOREBOARD.*(read|holds) [0-9a-f]{8}, expected [0-9a-f]{8} \(last written by DMA run'
OPS= 1500  same failure  FAIL test=random seed=10 cycle=4895: SCOREBOARD: RAM word 808 (address 00001ca0) read d520
OPS=  750  same failure  FAIL test=random seed=10 cycle=4895: SCOREBOARD: RAM word 808 (address 00001ca0) read d520
OPS=  375  same failure  FAIL test=random seed=10 cycle=4895: SCOREBOARD: RAM word 808 (address 00001ca0) read d520
OPS=  187  pass
OPS=  281  pass
OPS=  328  same failure  FAIL test=random seed=10 cycle=4868: SCOREBOARD (final sweep): RAM word 763 (address 00001
OPS=  304  pass
OPS=  316  pass
OPS=  322  same failure  FAIL test=random seed=10 cycle=4868: SCOREBOARD (final sweep): RAM word 763 (address 00001
OPS=  319  pass
OPS=  320  same failure  FAIL test=random seed=10 cycle=4868: SCOREBOARD (final sweep): RAM word 763 (address 00001
smallest failing OPS: 320

Eleven runs take 1,500 operations to 320. Read the lines from 328 down: the test stops before word 808 is read, but the bench's final sweep compares every RAM word with its model and finds word 763 wrong, also last written by DMA run #29. The signature here accepts both checks (read|holds), because both report the same damage. Run with a signature that accepts only read, and the same search stops at 333, because 328 to 332 now count as "other failure". That is the first lesson of shrinking: the signature is a decision, and it changes the answer.

Length shrinking has a limit: it only cuts the tail. All 29 DMA runs, and hundreds of operations before the bad one, are still there.

Do it, step 2: make the stimulus a list

To remove operations from the middle, the bench must replay a list of operations instead of drawing them from the seed. dbglab's bench cannot read an external stimulus. So, in a scratch copy of its bench, the random test gained a +REC=<file> switch that writes each operation as it runs it, and a new replay test reads such a file. The RTL is unchanged. Each line is one operation:

$ tb/run.sh random 10 icarus +REC=seed10.ops
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)
$ head -6 seed10.ops
ie 1
wr 508 7daa3ca3
wr 804 927e7694
ctrl 1
wr 601 0c27e377
rd 755
$ vvp -n build/dbglab.vvp +TEST=replay +SEED=10 +STIM=seed10.ops | grep FAIL
FAIL test=replay seed=10 cycle=4895: SCOREBOARD: RAM word 808 (address 00001ca0) read d5202ff9, expected b6c3311c (last written by DMA run #29)

The replay matches the original to the cycle, which is the check you must make before trusting it. (The list is longer than the 333 steps the length search found because one step of the random test can poll the DMA and then do one more thing; each is a line.) The replay test also keeps the bench's rules, so any shortened list is still a legal test:

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

// snippet: the scratch bench's replay test, the rules that keep a shortened list legal
    end else if (op == "poll") begin
      if (r_active) r_poll_dma();                 // nothing to poll without a run
    end else if (op == "wr") begin
      n = $fscanf(fd, "%d %h", a, v);
      if (!r_owned(a)) ram_wr(a, v);              // never touch words the running DMA owns
    end else if (op == "rd") begin
      n = $fscanf(fd, "%d", a);
      if (!r_owned(a)) ram_check(a);
...
    end else if (op == "dma") begin
      n = $fscanf(fd, "%d %d %d %d %h", a, b, c, d, v);
      if (!r_active) begin                        // one DMA run at a time
...
        r_go(a, mode);
      end
...
  while (r_active) r_poll_dma();                  // finish and check the last run

Do it, step 3: delta debugging

The algorithm itself knows nothing about hardware. It takes a list and a function that says whether a candidate still fails. It runs on its own here with a self-test, and you can run it as it is:

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

"""ddmin.py: delta debugging. Shrink a list while a test keeps failing the same way.
fails(candidate) -> True when the candidate still shows the failure (same signature)."""

def split(items, n):
    """n nearly equal, contiguous chunks."""
    return [items[len(items) * i // n: len(items) * (i + 1) // n] for i in range(n)]

def ddmin(items, fails, log=print):
    n = 2
    while len(items) >= 2:
        chunks = split(items, n)
        for i, chunk in enumerate(chunks):                 # 1. does one chunk fail on its own?
            if fails(chunk):
                log(f"keep chunk {i + 1}/{n}: {len(items)} -> {len(chunk)}")
                items, n = chunk, 2
                break
        else:
            for i in range(n):                             # 2. can we drop one chunk?
                rest = [x for j, c in enumerate(chunks) if j != i for x in c]
                if fails(rest):
                    log(f"drop chunk {i + 1}/{n}: {len(items)} -> {len(rest)}")
                    items, n = rest, max(n - 1, 2)
                    break
            else:
                if n >= len(items):                        # 3. single items, none removable
                    break
                n = min(2 * n, len(items))                 #    nothing helped: finer chunks
                log(f"finer: {n} chunks of about {len(items) // n}")
    return items

if __name__ == "__main__":
    # Self-test: 300 operations; the "bug" needs operation 41 and, later, operation 207.
    calls = 0
    def toy_fails(ops):
        global calls
        calls += 1
        return 41 in ops and 207 in ops
    small = ddmin(list(range(300)), toy_fails, log=lambda m: None)
    print(f"minimal: {small} after {calls} tests")
    assert small == [41, 207], small
    print("PASS: ddmin keeps exactly the two operations the failure needs")

The driver connects it to the simulator: write the candidate list to a file, run the replay, check the FAIL line against the signature, and never run the same list twice.

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

# not-run: runs dbglab's simulator through subprocess; run it where the scratch bench's build/dbglab.vvp is
"""shrink_stim.py: shrink a recorded dbglab operation list with ddmin.
usage: python3 shrink_stim.py <seed> <ops file> <signature regex>   (run where build/dbglab.vvp is)"""
import re, subprocess, sys, time
from ddmin import ddmin

seed, src, sig = sys.argv[1], sys.argv[2], re.compile(sys.argv[3])
ops = open(src).read().splitlines()
runs, seen = 0, {}

def fails(candidate):
    global runs
    key = tuple(candidate)
    if key not in seen:                                   # never run the same list twice
        runs += 1
        with open("cand.ops", "w") as f:
            f.write("\n".join(candidate) + "\n")
        out = subprocess.run(["vvp", "-n", "build/dbglab.vvp", "+TEST=replay", f"+SEED={seed}",
                              "+STIM=cand.ops"], capture_output=True, text=True).stdout
        line = next((l for l in out.splitlines() if l.startswith("FAIL")), "")
        seen[key] = bool(sig.search(line))                # same failure, not just any failure
    return seen[key]

t0 = time.time()
assert fails(ops), "the full list must fail with the signature"
small = ddmin(ops, fails, log=lambda m: print(f"run {runs:4d}: {m}"))
open(src.replace(".ops", ".min.ops"), "w").write("\n".join(small) + "\n")
print(f"{len(ops)} operations -> {len(small)} in {runs} runs, {time.time() - t0:.1f} s:")
print("\n".join(small))

$ python3 ../shrink_stim.py 10 seed10.ops 'SCOREBOARD.*(read|holds) [0-9a-f]{8}, expected [0-9a-f]{8} \(last written by DMA run'
run    3: keep chunk 2/2: 364 -> 182
run    5: keep chunk 2/2: 182 -> 91
run    7: keep chunk 2/2: 91 -> 46
run    9: keep chunk 2/2: 46 -> 23
run   10: keep chunk 1/2: 23 -> 11
run   12: keep chunk 2/2: 11 -> 6
run   14: keep chunk 2/2: 6 -> 3
run   15: keep chunk 1/2: 3 -> 1
364 operations -> 1 in 15 runs, 0.4 s:
dma 70 308 378 711 00000000
$ vvp -n build/dbglab.vvp +TEST=replay +SEED=10 +STIM=seed10.min.ops | grep FAIL
FAIL test=replay seed=10 cycle=447: SCOREBOARD (final sweep): RAM word 763 (address 00001bec) holds 42ea2b0d, expected 35288af0 (last written by DMA run #1)

Read the result. Fifteen simulations, under half a second. One operation is left: a DMA run whose first field, 70, selects a plain RAM-to-RAM copy, of 308 words from word 378 to word 711. On its own it fails at cycle 447 instead of 4895, and the final sweep finds word 763 wrong: 711 + 52. The copy stopped after 52 words, and 308 − 52 = 256. You have not opened a waveform, and the hypothesis for the next step of the loop is already on the table: lengths above 255 lose 256 words.

What the evidence says, and the strict signature

The same shrinker with a signature that accepts only a CPU read (not the final sweep) gives a different answer:

$ python3 ../shrink_stim.py 10 seed10.ops 'SCOREBOARD: RAM word \d+ \(address [0-9a-f]+\) read [0-9a-f]{8}, expected [0-9a-f]{8} \(last written by DMA run'
run    3: keep chunk 2/2: 364 -> 182
...
run   71: drop chunk 13/14: 14 -> 13
364 operations -> 13 in 83 runs, 1.5 s:
dma 70 308 378 711 00000000
wr 244 cb606bc4
poll
wr 80 cc5d2c65
wr 340 b93b775f
per a0c2f255
per 5317e084
wr 73 14018373
poll
scratch c78b0290
poll
poll
rd 808

Thirteen operations, and only two carry the bug: the copy and the read of word 808. The other eleven are there because the read must wait until the copy is finished and closed; the replay skips a read of a word the running DMA owns. Remove any one of them and the read comes too early, is skipped, and the failure turns into the final sweep, which this signature rejects. Delta debugging promises a list from which no single operation can be removed. It does not promise the shortest test. Writing the directed test is your job: one 308-word copy, wait for done, read the copy back.

The tool also sorts failures. Seed 13 shrank to one copy of 290 words (dma 82 290 500 41), the same bug. Seed 17, with a signature for an unknown value, shrank to dma 24 9 209 810: a nine-word zero fill that nobody programmed a fill value for, which is a different bug, for Part 5.

Traps

Related topics

• Part 1 · Reproduce

• Next: reducing the design

• Recording everything to replay

• Part 3: localise, including bisection in stimulus

• The debug loop: the same bug, found with a probe