Commit 14 of dbglab was a tidy-up: four configuration registers lost their reset because "software always writes them first". The next nightly sweep has a new failure, random seed 17, and the commit before passes the same seed. The failing log says a RAM word read back as xxxxxxxx at cycle 7949.
You have something better than one failing run: a passing run of exactly the same stimulus. How do you make the good run tell you where the bad one went wrong?
The common move is to open the failing waveform at cycle 7949 and scroll back, looking for the first X. In this run that is a long walk: the X sits in RAM for 7,461 cycles, and the waveform is full of X values that are harmless (unreset registers that software writes before anyone reads them). Every one of them looks like a suspect.
The second common move is to compare the two logs:
$ (cd good && tb/run.sh random 17)
dbglab: test=random seed=17
PASS test=random seed=17
$ (cd bad && 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)A verdict diffed against a verdict has one line, and it says what you already knew. To compare runs you need logs that record what the hardware did, step by step, so that the first line that differs is a fact about the design.
Pair the runs so only one thing differs. The same test and seed on the commit before and after a change, or the same commit in two simulators. Then every difference is caused by that one change.
Never pair two seeds. A seed changes the stimulus, so the runs part company at the first random choice. Both runs can be correct and still differ everywhere.
Record behaviour, not verdicts. A transaction log (who, read or write, address, data, per cycle) or a full VCD. Both are cheap to produce and easy to compare mechanically.
Let a tool find the first difference. diff for logs, a short script for waveforms. Your eyes are for reading the answer, not for searching.
Sort differences by start and end. Some differences heal (a register that is X in one run and 0 in the other until software writes it). The thread to pull is the one still open when the value is used, here when the DMA loads it into its write data.
On the debug loop this is Observe: you are not guessing a cause yet, you are letting the passing run point at the first wrong cycle. The localise part uses the same idea against golden models and other simulators.
Read it top to bottom. Three registers differ for a few cycles and then agree again: they had no reset, and software wrote them before use, exactly as the commit message promised. fill_q differs for 808 cycles, long enough to reach the DMA's write data at cycle 486. The read data at 7948 is the echo the scoreboard heard.
A probe compiled next to the design prints one line per accepted request and per response. It reads signals by hierarchical name and changes nothing, so the same file works on both commits:
// not-run: needs dbglab's sources and bench; compile it next to them (command in the Evidence box)
// bus_log: one line per bus event, for diffing two runs. It only reads the design.
// cycle master WR addr data (a write accepted)
// cycle master RD addr (a read accepted)
// cycle master RSP data resp (the response)
`timescale 1ns/1ps
module bus_log;
string who [2] = '{"cpu", "dma"};
always @(negedge dbglab_tb.clk) begin // mid-cycle: inputs are stable
for (int m = 0; m < 2; m++) begin
if (dbglab_tb.dut.m_valid[m] && dbglab_tb.dut.m_ready[m])
if (dbglab_tb.dut.m_write[m])
$display("%6d %s WR %h %h", dbglab_tb.cycle, who[m], dbglab_tb.dut.m_addr[m], dbglab_tb.dut.m_wdata[m]);
else
$display("%6d %s RD %h", dbglab_tb.cycle, who[m], dbglab_tb.dut.m_addr[m]);
if (dbglab_tb.dut.m_rvalid[m])
$display("%6d %s RSP %h %b", dbglab_tb.cycle, who[m], dbglab_tb.dut.m_rdata, dbglab_tb.dut.m_resp);
end
end
endmodule$ (cd good && sh ../probes/run-probe.sh ../probes/bus_log.sv random 17 > ../logs/good-bus.log)
$ (cd bad && sh ../probes/run-probe.sh ../probes/bus_log.sv random 17 > ../logs/bad-bus.log)
$ wc -l logs/good-bus.log logs/bad-bus.log
10029 logs/good-bus.log
4276 logs/bad-bus.log
14305 total
$ diff logs/good-bus.log logs/bad-bus.log | head -8
252c252
< 488 dma WR 00001ca8 00000000
---
> 488 dma WR 00001ca8 xxxxxxxx
254c254
< 492 dma WR 00001cac 00000000
---
> 492 dma WR 00001cac xxxxxxxx
$ diff logs/good-bus.log logs/bad-bus.log | grep -E '^[0-9]'
252c252
254c254
...
270c270
4275,10029c4275,4276Read it line by line. The first 251 lines are identical: same requests, same data, same cycles. At line 252, cycle 488, the DMA writes address 0x1ca8; the good run writes zero, the bad run writes X. Nine such hunks follow, one per word of the run, up to cycle 524. Then the logs agree again for almost 4,000 lines, until the bad run reads one of those words back and stops. The bus log has already moved you from cycle 7949 to cycle 488 and from the CPU to the DMA.
The bus log only sees the bus. To see why the DMA wrote X, compare everything: dump a VCD in each tree and let a script walk both files. It matches signals by full name, finds when each one first differs and when it last healed, groups names that are the same net seen through several ports, and prints them in time order. With no arguments it runs a small self-test, which is what the course checker runs.
"""vcd_first_diff.py: where do two runs first disagree?
usage: python3 vcd_first_diff.py good.vcd bad.vcd [--cycle NAME] [--skip REGEX] [--top N]
python3 vcd_first_diff.py (no files: run the built-in self-test)
Reads two VCD files of the same design, matches signals by full hierarchical name, and
prints the signals that differ in the order they first differ, with both values and the
time the last difference ended ("end" if it never did). Standard library only.
"""
import re
import sys
def parse_vcd(lines):
"""Return ({name: width}, {name: [(time, value), ...]}, end_time)."""
scope, names_of, width, changes = [], {}, {}, {}
t, in_header = 0, True
for raw in lines:
tok = raw.split()
if not tok:
continue
if in_header:
if tok[0] == "$scope":
scope.append(tok[2])
elif tok[0] == "$upscope":
scope.pop()
elif tok[0] == "$var":
code, ref = tok[3], tok[4]
name = ".".join(scope + [ref])
names_of.setdefault(code, []).append(name)
width[name] = int(tok[2])
changes[name] = []
elif tok[0] == "$enddefinitions":
in_header = False
continue
head = tok[0]
if head[0] == "#":
t = int(head[1:])
elif head[0] in "bBrR":
for name in names_of.get(tok[1], []):
changes[name].append((t, norm(head[1:].lower(), width[name])))
elif head[0] in "01xzXZ":
for name in names_of.get(head[1:], []):
changes[name].append((t, head[0].lower()))
return width, changes, t
def norm(bits, w):
"""Left-extend a VCD vector the way the format does (x and z extend, 0 and 1 pad with 0)."""
pad = bits[0] if bits[0] in "xz" else "0"
return bits.rjust(w, pad)
def value_at(chg, t):
"""Value of a change list at time t (after all changes at t)."""
v = None
for ct, cv in chg:
if ct > t:
break
v = cv
return v
def compare(a, b, end):
"""(first time, good value, bad value, time the last difference ended or None) or None."""
times = sorted({ct for ct, _ in a} | {ct for ct, _ in b})
ia = ib = 0
va = vb = None
first = healed = None
for t in times:
if t > end:
break
while ia < len(a) and a[ia][0] == t:
va = a[ia][1]
ia += 1
while ib < len(b) and b[ib][0] == t:
vb = b[ib][1]
ib += 1
if va != vb:
if first is None:
first = (t, va, vb)
healed = None
elif first is not None and healed is None:
healed = t
return first + (healed,) if first else None
def first_diffs(good, bad, skip=None):
"""Differing signals in order of first difference. Names that differ identically
(one net seen through several ports) are grouped; a register (_q) names the group."""
wa, ca, ea = good
wb, cb, eb = bad
end = min(ea, eb)
groups = {}
for name in sorted(set(ca) & set(cb)):
if skip and re.search(skip, name):
continue
d = compare(ca[name], cb[name], end)
if d:
groups.setdefault(d, []).append(name)
out = []
for d, names in groups.items():
names.sort(key=lambda n: (not n.endswith("_q"), len(n), n))
out.append((d[0], names[0], d[1], d[2], d[3], len(names) - 1))
out.sort()
return out, end
def fmt(v):
"""A bit string as hex, one x (or z) per nibble that is not fully known."""
if v is None or len(v) == 1:
return v or "-"
v = v.rjust(-(-len(v) // 4) * 4, "0")
nib = [v[i:i + 4] for i in range(0, len(v), 4)]
return "".join(format(int(n, 2), "x") if set(n) <= {"0", "1"} else ("z" if "z" in n else "x") for n in nib)
def report(good, bad, cycle=None, skip=None, top=12):
diffs, end = first_diffs(good, bad, skip)
if not diffs:
print(f"no difference up to time {end}")
return diffs
def when(t):
if cycle and cycle in good[1]:
v = value_at(good[1][cycle], t)
return f"{t} (cycle {int(v, 2) if v and not re.search('[xz]', v) else '?'})"
return str(t)
print(f"compared up to time {end}: {len(diffs)} differences, first at {when(diffs[0][0])}")
for t, name, va, vb, heal, same in diffs[:top]:
h = "end" if heal is None else when(heal)
more = f" (+{same} same)" if same else ""
print(f"{when(t)} {name}{more} good={fmt(va)} bad={fmt(vb)} until {h}")
if len(diffs) > top:
print(f" ... {len(diffs) - top} more")
return diffs
SELF_GOOD = """$timescale 1ps $end
$scope module tb $end
$var reg 1 ! clk $end
$var reg 4 " q [3:0] $end
$var reg 4 # r [3:0] $end
$upscope $end
$enddefinitions $end
#0
0!
b0 "
b0 #
#10
1!
b1 "
#20
0!
#30
1!
b10 "
b1 #
"""
SELF_BAD = SELF_GOOD.replace('b10 "', 'bx "')
def self_test():
g = parse_vcd(SELF_GOOD.splitlines())
b = parse_vcd(SELF_BAD.splitlines())
diffs = report(g, b)
ok = len(diffs) == 1 and diffs[0][:2] == (30, "tb.q") and diffs[0][3] == "xxxx" and diffs[0][4] is None
print("PASS: self-test found tb.q at time 30" if ok else "FAIL: self-test")
def main(argv):
if len(argv) < 2:
self_test()
return
cycle = skip = None
top = 12
args = list(argv)
for opt in ("--cycle", "--skip", "--top"):
if opt in args:
i = args.index(opt)
val = args[i + 1]
del args[i:i + 2]
if opt == "--cycle":
cycle = val
elif opt == "--skip":
skip = val
else:
top = int(val)
with open(args[0]) as fa, open(args[1]) as fb:
good, bad = parse_vcd(fa), parse_vcd(fb)
report(good, bad, cycle, skip, top)
if __name__ == "__main__":
main(sys.argv[1:])$ (cd good && DUMP=1 tb/run.sh random 17); (cd bad && DUMP=1 tb/run.sh random 17)
...
$ python3 -I scripts/vcd_first_diff.py good/dbglab.vcd bad/dbglab.vcd --cycle dbglab_tb.cycle
compared up to time 79486000: 14 differences, first at 5000 (cycle 1)
5000 (cycle 1) dbglab_tb.dut.u_csr.dst_q (+3 same) good=00000000 bad=xxxxxxxx until 235000 (cycle 24)
5000 (cycle 1) dbglab_tb.dut.u_csr.fill_q (+3 same) good=00000000 bad=xxxxxxxx until 8075000 (cycle 808)
5000 (cycle 1) dbglab_tb.dut.u_csr.len_q (+3 same) good=000 bad=xxx until 265000 (cycle 27)
5000 (cycle 1) dbglab_tb.dut.u_csr.src_q (+3 same) good=00000000 bad=xxxxxxxx until 205000 (cycle 21)
305000 (cycle 31) dbglab_tb.dut.u_dma.fill_val_q good=00000000 bad=xxxxxxxx until 8235000 (cycle 824)
4855000 (cycle 486) dbglab_tb.dut.m_wdata (+1 same) good=0000000000000000 bad=xxxxxxxx00000000 until 5995000 (cycle 600)
4855000 (cycle 486) dbglab_tb.dut.u_dma.wdata_q (+2 same) good=00000000 bad=xxxxxxxx until 5995000 (cycle 600)
4865000 (cycle 487) dbglab_tb.u_rules_dma.wdata_q good=00000000 bad=xxxxxxxx until 6005000 (cycle 601)
4875000 (cycle 488) dbglab_tb.dut.s_wdata (+5 same) good=00000000 bad=xxxxxxxx until 5995000 (cycle 600)
79475000 (cycle 7948) dbglab_tb.cpu_rdata (+5 same) good=00000000 bad=xxxxxxxx until 79485000 (cycle 7949)
79475000 (cycle 7948) dbglab_tb.dut.s_rdata (+1 same) good=0000000000000000a089fbdd00000000 bad=0000000000000000a089fbddxxxxxxxx until end
79475000 (cycle 7948) dbglab_tb.dut.u_ram.rdata good=00000000 bad=xxxxxxxx until end
... 2 moreFourteen differences in the 7,949 cycles both runs cover, and they read like a story when sorted by time:
Cycle 1: four CSR registers are X in the bad run and zero in the good one. That is the commit, seen directly: they lost their reset.
Cycles 21 to 27: src_q, dst_q and len_q heal. Software wrote them before the first DMA run, so their X never mattered. Drop them.
Cycle 808: fill_q heals only here, when the first pattern fill writes FILL. Before that it was X for 807 cycles, and something used it.
Cycle 31 and 486: the DMA copies the X into fill_val_q at its first start, and at 486 a zero fill (run #4) loads it into its write data. At 488 it reaches the bus and the RAM.
Cycle 7948: the read data differs. This is where the scoreboard looked, and it is the last link of the chain, not the first.
The first difference (cycle 1) names four suspects, and the healing times clear three of them. The survivor, fill_q, connects without a gap to the first wrong write at cycle 488. You now know the faulty register, the run that used it and the cycle it went wrong, without having opened a waveform viewer. The next step is Localise and Hypothesise: why does a zero fill read FILL before anyone wrote it? The X lesson follows this X from the other end.
Compare with diffing two seeds of the same good commit:
$ python3 -I scripts/vcd_first_diff.py logs/good17.vcd logs/good18.vcd --cycle dbglab_tb.cycle --top 5
compared up to time 184416000: 130 differences, first at 0 (cycle 0)
0 (cycle 0) dbglab_tb.rng good=00f9915f bad=9f310b18 until end
0 (cycle 0) dbglab_tb.seed good=00000011 bad=00000012 until end
66000 (cycle 7) dbglab_tb.cpu_wdata (+8 same) good=00000002 bad=00000000 until end
66000 (cycle 7) dbglab_tb.dut.m_wdata (+1 same) good=0000000000000002 bad=0000000000000000 until end
75000 (cycle 8) dbglab_tb.u_rules_cpu.wdata_q good=00000002 bad=00000000 until end
... 125 moreBoth runs pass, yet 130 signals differ, from cycle 0 (the seed) and from cycle 7 on the bus, and none ever heals. Different stimulus, different everything. That is why the pairing rule comes first.
Mostly, but it is weaker. Commits 14, 15 and 16 all differ between those runs, so a difference could come from any of them. Here commit 15 only touches the peripheral's power isolation, which random never uses, and the bus-log diff is the same. You only know that after checking. Pair the runs as tightly as you can: one commit apart, or bisect first.
fill_val_q from cycle 31, but run #1 at cycle 31 was a copy, not a fill. Why does it differ, and why did the copy still pass?The DMA captures cfg_fill on every start, whatever the mode, so the X is copied into fill_val_q at the first start. A copy never reads fill_val_q; only a fill loads it into the write data. A difference in a register is harmless until something uses it, which is why you follow differences to the first one that reaches an output, here the bus write at cycle 488.
dbglab rebuilt with dbglab/build-history.sh, 2026-10-17, Icarus Verilog 13.0. Good run: commit 13 (03ebdc1), bad run: commit 14 (b357bd8), both tb/run.sh random 17. Commit 13 prints PASS; commit 14 prints the SCOREBOARD FAIL at cycle 7949.
Bus log: bus_log.sv compiled next to dbglab (iverilog -g2012 -Wno-timescale -I tb -o build/probe.vvp <rtl/files.f> tb/bus_rules.sv tb/dbglab_tb.sv bus_log.sv, vvp -n build/probe.vvp +TEST=random +SEED=17): 10029 lines good, 4276 bad; diff shows 9 one-line hunks at cycles 488 to 524, then the bad run stops at cycle 7948.
VCD: DUMP=1 tb/run.sh random 17 in each tree (7.5 MB each), then python3 -I vcd_first_diff.py good/dbglab.vcd bad/dbglab.vcd --cycle dbglab_tb.cycle (Python 3, 0.9 s). The script's self-test (no arguments) prints PASS. Seeds 17 and 18 on commit 13: 130 differences from cycle 0 (the seed), 7 on the bus, none heal.
Limits: one bug, one seed pair, Icarus only. Icarus does not dump memory arrays, so the RAM contents never appear in the VCD; the bus log and the read data show them instead. A clean diff only means the dumped signals agree.