Sixty-six red lines and thirty minutes

Monday's nightly of dbglab ran every test over twenty seeds and 66 of 140 runs failed. The triage meeting is at ten: the CSR owner, the DMA owner, the engineer who owns the power domain, two verification engineers and you, chairing. Everyone has seen the red. Release candidate builds stop until the regression is understood.

Thirty minutes, six people, 66 failures. What has to be true when people stand up?

What people usually do, and why it fails

The common meeting opens the regression page and starts at the top. The first failure is a hang, so someone shares a waveform, and the DMA owner and a verification engineer spend twelve minutes reasoning about the arbiter. The next three failures are the same hang on other seeds. Then come twenty interrupt failures, which someone says "are probably the same thing". The meeting ends with half the list unread and the action "everyone look at their blocks".

Three things went wrong, and none is about skill. The unit was wrong: runs, not bugs, so the same hang was discussed four times and two different bugs were merged in passing. The preparation happened in the room: grouping, finding the repro and checking history are mechanical jobs, done slowly by six people watching one screen. And the output was wrong: a meeting that ends with opinions about causes, rather than owned experiments, has to happen again tomorrow.

The method: prepare with scripts, decide in the room

A triage meeting is the Report step done for a whole regression. Its output is not a diagnosis; it is a set of bug reports, each with an owner who will take it to Reproduce and beyond. Run it to these rules:

1. Automate the preparation and post it before the meeting. For every failure: the signature, the shortest repro, the first bad commit and the files that commit touched. All of it is scripts, minutes of machine time.

2. One row per signature. A signature is the failure message with the run-specific numbers taken out. Keep apart anything that is a different mechanism (an unknown value against a wrong real value, a hang against a mismatch).

3. Two or three minutes a row. Read the facts, agree the owner, agree the next experiment. If two people start reasoning about the cause, write their names down as a follow-up and move on.

4. Each row leaves with four things: one named person (not a team), one experiment, the prediction that experiment tests, and when the result is due.

5. Order by harm, not by count. Silent wrong data and hangs first; twenty runs of one bug are still one bug.

6. The next meeting starts from results. Each row comes back confirmed, refuted, merged with another row or split in two.

The test of convergence is simple: at the end, the number of signatures without an owner and an experiment is zero, and from one meeting to the next the number of open signatures falls.

The picture

Do it: prepare Monday's triage

The regression

$ rm -f build/*.log; tb/regress.sh icarus $(seq 1 20)
smoke                    seed 1      PASS
...
irq_w1c                  seed 1      FAIL
...
random                   seed 20     FAIL
66 failing run(s)

One number, 66, and it is the wrong one to discuss. The logs are in build/, one per run, each with its FAIL line.

From runs to signatures

The script below takes the run-specific parts out of every FAIL line (seed, cycle, addresses, data, word and run numbers) and groups what is left. It keeps an unknown value as X, because an X and a wrong real value come from different mechanisms. For each group it names the run that fails earliest, the cheapest repro.

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

# not-run: reads dbglab's build logs after tb/regress.sh (output below is from a real run)
"""triage.py: group a regression's FAIL lines into signatures, one row per likely bug.
usage: python3 triage.py build/*.log      (run from the dbglab folder after tb/regress.sh)
A signature is the FAIL line with the run-specific parts taken out: seed, cycle, addresses,
data values, word and run numbers. An unknown value (xxxxxxxx) is kept, because X and a wrong
real value are different mechanisms. Each row names the shortest failing run as the repro."""
import os
import re
import sys

def signature(line):
    body = line.split(": ", 1)[1]                      # drop "FAIL test=.. seed=.. cycle=.."
    test = re.search(r"test=(\S+)", line).group(1)
    body = re.sub(r"\b[0-9a-f]{8}\b", lambda m: "X" if m.group(0) == "xxxxxxxx" else "<hex>", body)
    body = body.replace("xxxxxxxx", "X")
    body = re.sub(r"(word|run) #?\d+", r"\1 <n>", body)
    body = re.sub(r"\b\d+\b", "<n>", body)
    return f"{test}: {body}"

groups = {}
for path in sys.argv[1:]:
    sim = os.path.basename(path).split("-")[0]         # build/<sim>-<test>-<seed>.log
    with open(path) as f:
        for line in f:
            if not line.startswith("FAIL"):
                continue
            seed = int(re.search(r"seed=(\d+)", line).group(1))
            cycle = int(re.search(r"cycle=(\d+)", line).group(1))
            groups.setdefault(signature(line.strip()), []).append((cycle, seed, sim))

print(f"{sum(len(v) for v in groups.values())} failing runs, {len(groups)} signatures")
for i, (sig, runs) in enumerate(sorted(groups.items(), key=lambda kv: -len(kv[1])), 1):
    cycle, seed, sim = min(runs)
    seeds = ",".join(str(r[1]) for r in sorted(runs, key=lambda r: r[1]))
    test = sig.split(":")[0]
    print(f"\nS{i}  {len(runs)} run(s)  seeds {seeds}")
    print(f"    {sig}")
    print(f"    repro: tb/run.sh {test} {seed} {sim}   (fails at cycle {cycle})")

$ python3 -I ../tools/triage.py build/icarus-*-*.log
66 failing runs, 5 signatures

S1  20 run(s)  seeds 1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20
    dma_burst_backpressure: WATCHDOG: no bus or stream progress for <n> cycles; cpu_valid=<n> cpu_ready=<n> cpu_addr=<hex>
    repro: tb/run.sh dma_burst_backpressure 1 icarus   (fails at cycle 2165)

S2  20 run(s)  seeds 1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20
    irq_w1c: IRQ: irq=<n> while CTRL=<n> enables no interrupt
    repro: tb/run.sh irq_w1c 1 icarus   (fails at cycle 84)

S3  20 run(s)  seeds 1,2,3,4,5,6,7,8,9,10,11,12,13,14,15,16,17,18,19,20
    periph_power: STREAM: pstream_valid is unknown
    repro: tb/run.sh periph_power 1 icarus   (fails at cycle 431)

S4  3 run(s)  seeds 10,13,20
    random: SCOREBOARD: RAM word <n> (address <hex>) read <hex>, expected <hex> (last written by DMA run <n>)
    repro: tb/run.sh random 13 icarus   (fails at cycle 3701)

S5  3 run(s)  seeds 16,17,19
    random: SCOREBOARD: RAM word <n> (address <hex>) read X, expected <hex> (last written by DMA run <n>)
    repro: tb/run.sh random 19 icarus   (fails at cycle 415)

Read the shape before the details. Three signatures fail on every seed: deterministic, cheap to reproduce, and probably caused by a fixed sequence in the test rather than by random stimulus. Two fail on a few seeds of random only, and they differ in one word: S4 reads a wrong real value, S5 reads X. The repro for each is the earliest failure, so S5 is debugged on seed 19 at cycle 415, not on seed 17 at cycle 7949.

A first bad commit for every row

Each repro passes at the v0.1 release and fails at HEAD, so history can localise all five before the meeting. A loop around git bisect run does it unattended:

1
2
3
4
5
6
7
8
9
10
11

#!/bin/sh
# bisect-all.sh: for each "test seed" pair given, find the first bad commit between v0.1 and HEAD.
# usage: bisect-all.sh "test seed" ...   (run from the dbglab folder; the tree must be clean)
for pair in "$@"; do
  set -- $pair
  git bisect start HEAD v0.1 > /dev/null
  first=$(git bisect run tb/run.sh "$1" "$2" 2>&1 | sed -n 's/^\([0-9a-f]\{7\}\)[0-9a-f]* is the first bad commit/\1/p')
  runs=$(git bisect log | grep -c '^git bisect \(good\|bad\)')
  git bisect reset > /dev/null 2>&1
  printf '%-26s seed %-3s first bad %s  (%s runs)  %s\n' "$1" "$2" "$first" "$runs" "$(git log -1 --format=%s "$first")"
done

$ ../tools/bisect-all.sh "dma_burst_backpressure 1" "irq_w1c 1" "periph_power 1" "random 13" "random 19"
dma_burst_backpressure     seed 1   first bad c4a71b5  (4 runs)  dma: keep the bus for a whole chunk
irq_w1c                    seed 1   first bad 026f8bf  (4 runs)  csr: collect register reset values in dbglab_pkg
periph_power               seed 1   first bad 122e88a  (4 runs)  periph_pd: isolate only the outputs that leave the peripheral
random                     seed 13  first bad 03ebdc1  (3 runs)  dma: one width for the beat counters
random                     seed 19  first bad b357bd8  (4 runs)  csr: no reset on the DMA address and data registers

Nineteen simulations, 2.7 seconds. Five signatures, five different commits. That is strong evidence for five different bugs, and it answers the question every triage gets stuck on ("are these the same thing?") before anyone has an opinion. git show --stat adds the files: S1 touched bus_fabric.sv, dbglab_top.sv and dma_engine.sv; S2 csr_block.sv and dbglab_pkg.sv; S3 one line of periph_pd.sv; S4 dma_engine.sv; S5 csr_block.sv. The files name the owners. One more cheap fact goes on S5's row: tb/run.sh random 19 verilator passes, and with XRAND=1, which starts unreset flops at random values, it fails at the same cycle. That is the fingerprint of a register with no reset.

A bisect points at the commit that changed the verdict; it is a strong hint, not a root cause (see bisection in history for the ways it lies). The minutes say "first bad commit", never "cause".

The meeting: twelve minutes, five rows

With the table posted an hour earlier, the meeting only decides. The minutes below are illustrative (dbglab has no team), but every fact in them comes from the runs above, and each prediction is one that a lesson of this course tests for real.

Notice the order: the hang and the two silent data corruptions first, the interrupt last, although S2 has twenty failures and S4 three. Notice the balance too: S1 and S4 both land on the DMA, so S4 goes to a verification engineer with the DMA owner as reviewer, instead of queuing behind the hang. And nobody explained a cause. Each prediction can be wrong, which is the point: Tuesday's meeting reads five results, not five opinions.

What the evidence says

The preparation did the work people usually do in the room: 66 failures became five signatures, five repros and five first-bad commits in about fourteen seconds of machine time. What was left for the people was what only people can do: choose an owner, balance the load, and agree a falsifiable next step. That is why the meeting can converge in minutes.

Traps

Related topics

• Part 11 · Debug as a Team

• A bug report others can act on

• Keeping several hypotheses alive

• Bisection in history

• Ownership and hand-offs