Monday morning. Over the weekend someone committed a change to DCRouter, and the nightly regression ran the checked hunt of lesson 5.10 with 40 seeds. All 40 failed. The log below is not invented: it was recorded by building the course's checked hunt against DCRouter with that change and running seeds 1 to 40.
Your task: bucket the failures, decide what to debug first, find the cause, and say when you are done. Work through the steps before opening the answers.
Each seed's first error line is in the model below, exactly as printed. The bucketer abstracts what varies between runs of the same failure, first time and flit values, then the output number. (The second log, NIGHT_2, is the next night's; ignore it until step 4.)
"""A night of regression failures, bucketed by signature.
NIGHT_1 is the first error line of each of 40 seeds of DCRouter's checked hunt (lesson 5.10)
after a "commit" that switched on two Bug Zoo bugs, recorded with Verilator and
+verilator+seed+N. NIGHT_2 is the same 40 seeds after the first bucket's cause was fixed.
A signature abstracts the parts of a message that vary between runs of the same failure:
first the time and the flit value, then also the output number.
"""
import re
from collections import Counter
NIGHT_1 = """seed 1: ERROR @31145: out3: out_err 0 on flit 00fc, expected 1
seed 2: ERROR @9705: out3: out_err 0 on flit 004c, expected 1
seed 3: ERROR @7115: out0: out_err 0 on flit 00bc, expected 1
seed 4: ERROR @275: out0: out_err 0 on flit 00a8, expected 1
seed 5: ERROR @6205: out2: out_err 0 on flit 0016, expected 1
seed 6: ERROR @2285: out0: out_err 0 on flit 00a6, expected 1
seed 7: ERROR @24695: out2: out_err 0 on flit 0034, expected 1
seed 8: ERROR @23545: out3: out_err 0 on flit 005e, expected 1
seed 9: ERROR @2465: out3: out_err 0 on flit 00d1, expected 1
seed 10: ERROR @31245: out3: out_err 0 on flit 0010, expected 1
seed 11: ERROR @9535: out1: out_err 0 on flit 000c, expected 1
seed 12: ERROR @100775: out2: out_err 0 on flit 00f8, expected 1
seed 13: ERROR @36475: out0: out_err 0 on flit 00de, expected 1
seed 14: ERROR @22795: out1: out_err 0 on flit 00dd, expected 1
seed 15: ERROR @6545: out2: out_err 0 on flit 00dc, expected 1
seed 16: ERROR @67725: out0: out_err 0 on flit 000e, expected 1
seed 17: ERROR @225: out2: out_err 0 on flit 004b, expected 1
seed 18: ERROR @10385: out1: out_err 0 on flit 0075, expected 1
seed 19: ERROR @2195: out3: out_err 0 on flit 00a2, expected 1
seed 20: ERROR @10975: out1: out_err 0 on flit 00ba, expected 1
seed 21: ERROR @32945: out0: out_err 0 on flit 00bc, expected 1
seed 22: ERROR @38515: out2: out_err 0 on flit 00c4, expected 1
seed 23: ERROR @7715: out1: out_err 0 on flit 00f5, expected 1
seed 24: ERROR @285: out3: out_err 0 on flit 00df, expected 1
seed 25: ERROR @2225: out1: out_err 0 on flit 0022, expected 1
seed 26: ERROR @17265: out0: out_err 0 on flit 00fe, expected 1
seed 27: ERROR @11215: out0: out_err 0 on flit 002e, expected 1
seed 28: ERROR @22535: out2: out_err 0 on flit 006c, expected 1
seed 29: ERROR @9895: out1: out_err 0 on flit 006e, expected 1
seed 30: ERROR @6455: out0: out_err 0 on flit 001f, expected 1
seed 31: ERROR @2475: out0: out_err 0 on flit 00a7, expected 1
seed 32: ERROR @9765: out3: out_err 0 on flit 0063, expected 1
seed 33: ERROR @4535: out1: out_err 0 on flit 00ee, expected 1
seed 34: ERROR @285: out0: out_err 0 on flit 0027, expected 1
seed 35: ERROR @26305: out0: out_err 0 on flit 0029, expected 1
seed 36: ERROR @37875: out1: out_err 0 on flit 00ec, expected 1
seed 37: ERROR @855: out2: out_err 0 on flit 000a, expected 1
seed 38: ERROR @13275: out2: out_err 0 on flit 0083, expected 1
seed 39: ERROR @42145: out1: out_err 0 on flit 0082, expected 1
seed 40: ERROR @11295: out0: out_err 0 on flit 0018, expected 1"""
NIGHT_2 = """seed 1: ERROR @223265: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 2: ERROR @179455: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 3: ERROR @246645: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 4: ERROR @272355: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 5: ERROR @193385: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 6: ERROR @223875: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 7: ERROR @306525: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 8: ERROR @266745: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 9: ERROR @229755: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 10: ERROR @185185: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 11: ERROR @273405: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 12: ERROR @220745: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 13: ERROR @187355: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 14: ERROR @244155: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 15: ERROR @228255: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 16: ERROR @222485: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 17: ERROR @220995: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 18: ERROR @205865: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 19: ERROR @187625: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 20: ERROR @246915: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 21: ERROR @301365: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 22: ERROR @163475: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 23: ERROR @232475: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 24: ERROR @195975: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 25: ERROR @254325: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 26: ERROR @267665: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 27: ERROR @248965: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 28: ERROR @207675: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 29: ERROR @246485: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 30: ERROR @282355: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 31: ERROR @164185: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 32: ERROR @230085: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 33: ERROR @171815: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 34: ERROR @221645: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 35: ERROR @228295: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 36: ERROR @240315: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 37: ERROR @266005: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 38: ERROR @218795: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 39: ERROR @261285: credit audit: 1 flits left output 0 into a stalled sink, expected 4
seed 40: ERROR @223265: credit audit: 1 flits left output 0 into a stalled sink, expected 4"""
def first_errors(log):
return [line.split(": ", 1)[1] for line in log.splitlines()]
def sig_numbers(msg): # abstract time and hex values, keep the output
msg = re.sub(r"@\d+", "@T", msg)
return re.sub(r"\b[0-9a-f]{4}\b", "XXXX", msg)
def sig_outputs(msg): # also abstract which output reported it
return re.sub(r"\bout\d\b", "outN", sig_numbers(msg))
for name, log in [("night 1", NIGHT_1), ("night 2, after the first fix", NIGHT_2)]:
errs = first_errors(log)
raw, by_num, by_out = Counter(errs), Counter(map(sig_numbers, errs)), Counter(map(sig_outputs, errs))
print(f"{name}: {len(errs)} failing seeds, {len(raw)} distinct lines; signatures: {len(by_num)} with outputs kept, {len(by_out)} with outputs abstracted")
for sig, n in by_out.most_common():
print(f" {n:3d} {sig}")
assert len(Counter(map(sig_outputs, first_errors(NIGHT_1)))) == 1 and len(Counter(map(sig_outputs, first_errors(NIGHT_2)))) == 1
assert set(map(sig_outputs, first_errors(NIGHT_1))) != set(map(sig_outputs, first_errors(NIGHT_2)))
print("PASS: each night is one signature once numbers and outputs are abstracted, and fixing the first exposed a second, different failure")It prints:
night 1: 40 failing seeds, 40 distinct lines; signatures: 4 with outputs kept, 1 with outputs abstracted
40 ERROR @T: outN: out_err 0 on flit XXXX, expected 1
night 2, after the first fix: 40 failing seeds, 39 distinct lines; signatures: 1 with outputs kept, 1 with outputs abstracted
40 ERROR @T: credit audit: 1 flits left output 0 into a stalled sink, expected 4
PASS: each night is one signature once numbers and outputs are abstracted, and fixing the first exposed a second, different failureHow to read night 1: 40 failures, 40 different lines, but a single signature once the time, flit value and output are abstracted. Keeping the output number would have produced four buckets for what is clearly one cause: a signature should abstract everything that varies with the random stimulus, and the output a packet happened to go to is one of those things (lesson 13.5).
One signature: a packet's tail arrived without out_err when the scoreboard expected an error report. All 40 seeds, all four outputs.
One bucket, so the choice is which run to debug: the earliest failure. Seeds 17 and 4 fail at time 225 and 275; seed 12 not until 100775.
Read the message as a rule: out_err expected on a tail and not raised breaks R8 (bad CRC is reported) or R5 (length 0 is reported).
What changed: the commit. Bisection (lesson 13.4) is cheap when one commit separates a passing night from a failing one.
The failing tail belongs to a packet sent with a bad CRC, which the scoreboard expects to be reported. Looking at the header of every failing packet in the first few seeds, all of them have the priority bit set; bad packets with priority 0 are reported correctly. The commit touched the error-report logic: for high-priority packets out_err is never raised. This is BUG_13 ("no error report for high priority"). Fix it, and add the observation to the bug report: error reporting must be checked for both priorities.
The tempting conclusion is yes: one bucket, one cause, one fix. Two facts in the log should stop you. Each seed reported many more errors than it printed (the environment prints only the first five; seeds 1, 2 and 3 counted 14, 21 and 17), and a first error hides everything after it. The only way to know whether the bucket was the whole story is to rerun.
With BUG_13 fixed, the same 40 seeds ran again: NIGHT_2 in the model. Every seed still fails, with a different signature: the credit audit (lesson 4.10's hunt checks that exactly four flits leave into a stalled sink) sees only one.
Every seed fails the same deterministic audit at output 0, so random stimulus is not needed to reproduce it. With the sink stalled, flits stop after one, so credits are being lost. Watching the credit counter, a credit returned in the same cycle as a flit is sent is dropped: the counter decrements for the send and ignores the return. That is BUG_9 ("a return in the same cycle is lost"), the second half of the same commit. It was always failing; in night 1 it sat behind BUG_13's errors, beyond the five that were printed.
Observation | Lesson |
|---|---|
40 distinct lines, one signature | Abstract everything that varies with stimulus; over-specific signatures split one cause into many buckets |
Shortest failing seed first | Debug the cheapest reproduction (lesson 13.2) |
Errors after the first were not printed | A first failure masks later ones; one bucket is not proof of one bug |
Fixing the first exposed the second | Rerun after every fix before declaring the regression clean |
A deterministic check failed on every seed | Reproduce with the simplest stimulus that still fails |
Each seed's first errors were BUG_13's, and the environment prints only five errors; BUG_9's credit-audit error came later and was counted but not printed.
Which output a failing packet went to depends on the random stimulus, not the cause; keeping it splits one cause into four buckets.
40 distinct failure lines from a real run were one signature once stimulus-dependent details were abstracted.
The first bug masked a second; fixing and rerunning revealed it.
A regression is debugged when it passes again, not when the first bucket is explained.