It passed at the last release

The irq_w1c test checks dbglab's interrupt logic. It passed at the v0.1 release, and now it fails on every seed. Eleven commits have landed since: FIFO changes, DMA speed-ups, a refactor, comment fixes. Nobody remembers touching the interrupt logic. Which commit broke it?

What people usually do, and why it fails

The usual approach is to read the commit log, pick the commit that looks most likely, and debug from there. Here the DMA changes look risky, because the interrupt fires when a DMA run finishes. But a hunch is a probe with no information: if it is wrong, you have spent an hour and ruled out one commit of eleven. And the guilty commit here says No functional change intended in its message. Nobody would pick it by eye.

The other habit is to start from the waveform at HEAD, which works but throws away the most useful fact you have: a version that passes. When you have a good version and a bad one, history is the cheapest place to localise.

The method: bisection as information

Every test of a commit answers one yes-or-no question, so it can at best halve the suspects. Starting from N candidate commits, you need about

tests: 11 commits take 4, 100 take 7, 1,000 take 10. Reading commits one by one takes up to N. Bisection applies when four things are true:

1. A known good version. You have run the test there and it passed, not "it probably worked".

2. A known bad version. It fails there, the same way it fails in the report.

3. A test that decides on its own. A command whose exit status means good or bad, with no human reading a waveform at each step.

4. One change in behaviour between them. If the test flips from pass to fail more than once in the range, bisect finds a flip, not necessarily yours.

git bisect run reads the exit status: 0 is good, 1 to 127 is bad, except 125, which means skip this commit, I cannot tell. dbglab's tb/run.sh was written for this: 0 on PASS, 1 on FAIL, 125 when the design does not build.

The picture

Read the bars from the top. The suspects are the commits that could be the first bad one. Each answer cuts the bar roughly in half, and the last bar is a single commit.

Do it: bisecting dbglab

Check both ends first

$ git log --oneline v0.1..HEAD | wc -l
      11
$ git checkout -q v0.1 && tb/run.sh irq_w1c 1
dbglab: test=irq_w1c seed=1
PASS test=irq_w1c seed=1
$ git checkout -q main && 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

Eleven suspects, a good end and a bad end that fails the way the report says. Now let git drive.

Run it

$ git bisect start HEAD v0.1
Bisecting: 5 revisions left to test after this (roughly 3 steps)
[27acd3070be8abc6d2e39268f12788f0d15688ee] periph: deepen the async FIFO to 16 entries
$ git bisect run tb/run.sh irq_w1c 1
running 'tb/run.sh' 'irq_w1c' '1'
dbglab: test=irq_w1c seed=1
FAIL test=irq_w1c seed=1 cycle=116: IRQ: irq=1 while CTRL=00 enables no interrupt
Bisecting: 2 revisions left to test after this (roughly 1 step)
[a60b6f711da8e202872a42f92fbdedcbcb811ab8] periph: power gate model with output isolation
running 'tb/run.sh' 'irq_w1c' '1'
dbglab: test=irq_w1c seed=1
PASS test=irq_w1c seed=1
Bisecting: 0 revisions left to test after this (roughly 1 step)
[026f8bfe1f4ed59ec2d8f33c866509ac9d197dc1] csr: collect register reset values in dbglab_pkg
running 'tb/run.sh' 'irq_w1c' '1'
dbglab: test=irq_w1c seed=1
FAIL test=irq_w1c seed=1 cycle=116: IRQ: irq=1 while CTRL=00 enables no interrupt
Bisecting: 0 revisions left to test after this (roughly 0 steps)
[2e634669a2a015b1bd6667c4ab6af67b1538307b] Fix comments in the fabric and the DMA; README register map
running 'tb/run.sh' 'irq_w1c' '1'
dbglab: test=irq_w1c seed=1
PASS test=irq_w1c seed=1
026f8bfe1f4ed59ec2d8f33c866509ac9d197dc1 is the first bad commit
...
bisect found first bad commit

Read it one probe at a time, with the figure beside it:

• Probe 1, commit 10 (deepen the FIFO): FAIL. The bug is at 10 or earlier, so 11 to 16 are cleared without being run.

• Probe 2, commit 7 (power gate): PASS. The bug arrived after 7. Suspects: 8, 9, 10.

• Probe 3, commit 9 (reset values): FAIL. Suspects: 8 or 9.

• Probe 4, commit 8 (comment fixes): PASS. So 9 is the first bad commit.

• Notice the cycle: 116 here, 84 at HEAD. Commit 11 made the DMA faster, so the same failure happens earlier. The same bug can print a different line at a different commit, which matters when your test greps for an exact message.

git bisect log keeps the session as a replayable script. Save it in the bug report, then end the session with git bisect reset, which returns you to where you started:

$ git bisect log
# bad: [49c5f04d1124aaeab1dc902884d49b7d1b4b8e75] tb: report cycles and sim time in the PASS line
# good: [fa71142bbf1e3b00c39daa8d3595e8135da704e7] tb: seeded random test and regression script
git bisect start 'HEAD' 'v0.1'
# bad: [27acd3070be8abc6d2e39268f12788f0d15688ee] periph: deepen the async FIFO to 16 entries
git bisect bad 27acd3070be8abc6d2e39268f12788f0d15688ee
...
# first bad commit: [026f8bfe1f4ed59ec2d8f33c866509ac9d197dc1] csr: collect register reset values in dbglab_pkg

What the evidence says: read the guilty diff

Bisect gives you a commit, not a cause. Read its diff with the symptom in mind: irq is high while the bench believes CTRL enables no interrupt.

$ git show 026f8bf
...
    csr: collect register reset values in dbglab_pkg
...
    One table of reset values instead of literals spread through the
    reset branch. No functional change intended.
...
-      scratch_q <= '0; ctrl_q <= '0; done_q <= 1'b0;
-      src_q <= '0; dst_q <= '0; len_q <= '0;
+      scratch_q <= SCRATCH_RST; ctrl_q <= CTRL_RST; done_q <= 1'b0;
+      src_q <= SRC_RST; dst_q <= DST_RST; len_q <= LEN_RST;
...
+  localparam logic [31:0] SCRATCH_RST = 32'h0000_0000;
+  localparam logic [7:0]  CTRL_RST    = 8'h01;
...

CTRL used to reset to 0; the refactor made it 01, and bit 0 of CTRL is the done-interrupt enable. Note that CTRL=00 in the failure message is the bench's model of CTRL, not the register: the model still believes the documented reset value. That is the hypothesis: CTRL now resets with the done interrupt enabled, so the first DMA run raises irq. It predicts two things you can check: CTRL reads 01 straight after reset, and irq rises the cycle the first DMA run sets STATUS.done.

$ ../probes/run-probe.sh ../probes/ctrl_probe.sv irq_w1c 1
dbglab: test=irq_w1c seed=1
cycle 5: reset released, CTRL=01
cycle 84: irq rises, CTRL=01 STATUS.done=1
FAIL test=irq_w1c seed=1 cycle=84: IRQ: irq=1 while CTRL=00 enables no interrupt

Both predictions hold. (ctrl_probe.sv prints CTRL at reset release and at the first rise of irq; it is compiled next to the design, the technique from the debug loop.) Setting CTRL_RST back to 8'h00 makes irq_w1c pass in both simulators. Four test runs and one diff took you from "something in eleven commits" to one line of the package.

Traps: four ways bisection lies

The test fails for a different reason in the middle

This is the trap that bites most often. The random test with seed 16 fails at HEAD on an unknown value. Bisect it the obvious way:

$ tb/run.sh random 16
dbglab: test=random seed=16
FAIL test=random seed=16 cycle=686: SCOREBOARD: RAM word 759 (address 00001bdc) read xxxxxxxx, expected 00000000 (last written by DMA run #3)
$ git bisect start HEAD v0.1
...
$ git bisect run tb/run.sh random 16
...
[03ebdc1fd778231df2f3dca283af1764db17f11e] dma: one width for the beat counters
FAIL test=random seed=16 cycle=12811: STREAM: word #203 = 5484683d, expected 3caa023d
...
03ebdc1fd778231df2f3dca283af1764db17f11e is the first bad commit

At commit 13 the same seed fails differently: another bug arrives one commit before yours and fails this seed first. Bisect saw "fail" and blamed commit 13, which never adds an X. The cure is a test for the bug's own signature that answers skip (125) for any other failure. Keep the script outside the repository (or at least untracked), so that every commit is tested by the same script and no checkout can change or remove it:

1
2
3
4
5
6
7
8
9
10
11

#!/bin/sh
# git bisect run helper: is THIS bug here?  usage: is-x-bug.sh <test> <seed>
# 0 = good (passes), 1 = bad (fails with the X read), 125 = skip (fails some other way, or no build)
out=$(tb/run.sh "$1" "$2")
case $? in
  0)   exit 0 ;;
  125) exit 125 ;;
esac
echo "$out" | grep FAIL
echo "$out" | grep -q 'read xxxxxxxx' && exit 1
exit 125

$ git bisect start HEAD v0.1
...
$ git bisect run ../bisect/is-x-bug.sh random 16
...
[03ebdc1fd778231df2f3dca283af1764db17f11e] dma: one width for the beat counters
running '../bisect/is-x-bug.sh' 'random' '16'
FAIL test=random seed=16 cycle=12811: STREAM: word #203 = 5484683d, expected 3caa023d
Bisecting: 2 revisions left to test after this (roughly 2 steps)
...
There are only 'skip'ped commits left to test.
The first bad commit could be any of:
03ebdc1fd778231df2f3dca283af1764db17f11e
b357bd84b7252b54097cac920e6a14cadda7503c
We cannot bisect more!
error: bisect run cannot continue any more
$ git bisect start HEAD v0.1
...
$ git bisect run ../bisect/is-x-bug.sh random 17
...
b357bd84b7252b54097cac920e6a14cadda7503c is the first bad commit

Now bisect is honest: it cannot tell 13 from 14 with this seed, and says so. A seed that the other bug does not reach first (17) settles it at commit 14, the real home of the X. An honest "one of two" beats a confident wrong answer.

Bisecting the wrong range

Give a bad commit as the good end and bisect still returns an answer. Here commit 10 already fails irq_w1c:

$ git bisect start HEAD 27acd30
Bisecting: 2 revisions left to test after this (roughly 2 steps)
[03ebdc1fd778231df2f3dca283af1764db17f11e] dma: one width for the beat counters
$ git bisect run tb/run.sh irq_w1c 1
...
c4a71b585e287d527b9c2a827a3969bca0334445 is the first bad commit

It blames commit 11, the first commit after the "good" end, because every commit it tested failed. That is why you run the test at both ends before you start.

A flaky test

If the test sometimes fails on a good commit, one wrong answer sends bisect into the wrong half, and every later step is spent there. dbglab is deterministic, so this does not happen here, but a regression with a real race does. Make the test reliable first (Part 1 covers how), or have the script run each commit several times and call it bad only if any run shows the bug's signature.

A commit that does not build

A commit that breaks the build cannot answer. If your script calls it bad, bisect blames the build break. dbglab's run.sh returns 125 when the compile fails, so bisect skips that commit and tests its neighbours. Many skips widen the answer to a range, as in the seed 16 run above.

Try it: bisect a history yourself

The trainer below holds the same history as dbglab: 16 commits, v0.1 at commit 5, HEAD bad. Find the first bad commit by clicking commits to test, or press "Test the middle" to do what git bisect does (when two commits are equally central, git may pick the other one). Then raise the chance that a bad commit passes one run, and watch a single unlucky pass send the search the wrong way; more runs per test is the cure from the traps above.

Related topics

• Part 3 · Localise

• The debug loop

• Case study: the deadlock under back-pressure (bisected to commit 11)

• Case study: the reset value that changed