The report

Two streams share one output port through a small round-robin arbiter, arb2. Release v1.4 went out last month. Today the system team writes (illustrative):

The block's regression is green on both releases:

$ for t in v1.3 v1.4; do git checkout -q $t; echo "$t: $(../perf-check.sh +NOBUDGET | grep PASS)"; done
v1.3: PASS: 500 words from each master in order
v1.4: PASS: 500 words from each master in order

Between the two tags there are five commits, all to arb2.sv, and their messages say "rename", "comment", "lint" and one timing change. The block's tests check every word's value and order, and none of them checks how many cycles it took.

Stop here if you want to try it. The arbiter and its bench are below. What is the first number you would want, and how would you find the commit?

The hunt

The arbiter and a bench that counts

The arbiter's three versions are in one file. REG_GRANT=0 is v1.3's, where the grant is picked from this cycle's valids. REG_GRANT=1, FIX=0 is v1.4's: the grant became a register, so in_ready no longer depends on in_valid through the pick logic. FIX=1 is the fix we will reach. The bench is the old functional test plus three counters and a budget, the pattern from performance bugs: with both masters back to back, 1,000 transfers may take at most 1,004 cycles. +NOBUDGET turns the budget off, which is what the old test was.

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
42
43
44
45

`timescale 1ns/1ps
// arb2: two valid/ready masters share one output, round robin.
//   REG_GRANT=0: the original. The grant is picked from this cycle's valids, so in_ready
//                depends combinationally on in_valid (a long path, and a lint warning).
//   REG_GRANT=1: the grant is a register, so in_ready comes from a flop.
//     FIX=0: the register is loaded only while it is empty and cleared after each transfer,
//            so every transfer is followed by an idle cycle.
//     FIX=1: the register picks the next owner in the same cycle a transfer completes.
module arb2 #(parameter bit REG_GRANT = 1, parameter bit FIX = 1) (
  input  logic            clk, rst_n,
  input  logic [1:0]      in_valid,
  output logic [1:0]      in_ready,
  input  logic [1:0][7:0] in_data,
  output logic            out_valid,
  input  logic            out_ready,
  output logic [7:0]      out_data,
  output logic            out_src
);
  logic       last;                                    // the master served last
  logic [1:0] gnt_q, gnt;
  logic       fire;
  // round robin: with both valid, the master not served last wins
  function automatic logic [1:0] pick(input logic [1:0] req, input logic prev);
    if (req == 2'b11) return prev ? 2'b01 : 2'b10;
    return req;
  endfunction
  assign gnt       = REG_GRANT ? gnt_q : pick(in_valid, last);
  assign out_valid = |(gnt & in_valid);
  assign out_data  = gnt[1] ? in_data[1] : in_data[0];
  assign out_src   = gnt[1];
  assign in_ready  = gnt & {2{out_ready}};
  assign fire      = out_valid && out_ready;
  always_ff @(posedge clk or negedge rst_n)
    if (!rst_n) begin gnt_q <= '0; last <= 1'b1; end
    else begin
      if (fire) last <= gnt[1];
      if (FIX) begin
        if (fire)                       gnt_q <= (in_valid & ~gnt) != 2'b00 ? (in_valid & ~gnt) : gnt;  // hand over, or keep
        else if (!(|(gnt_q & in_valid))) gnt_q <= pick(in_valid, last);                              // owner has nothing
      end else begin
        if (gnt_q == 2'b00) gnt_q <= pick(in_valid, last);
        else if (fire)      gnt_q <= 2'b00;              // release, re-arbitrate next cycle
      end
    end
endmodule

Observe: the number

Same bench, three builds. The counters are the ones from counters and performance probes: work (transfers), time (cycles), and waiting (cycles with a word ready, a ready sink, and no transfer).

$ iverilog -g2012 -Parb_tb.REG_GRANT=0 -o a0.vvp arb_tb.sv && vvp -n a0.vvp
PERF: 1000 transfers in 1000 cycles, 1.00 cycles per transfer, idle cycles with a word waiting=0
PASS: 500 words from each master in order (REG_GRANT=0 FIX=1)
...
$ iverilog -g2012 -Parb_tb.FIX=0 -o ab.vvp arb_tb.sv && vvp -n ab.vvp
PERF: 1000 transfers in 2000 cycles, 2.00 cycles per transfer, idle cycles with a word waiting=1000
FAIL: PERF: 2000 cycles for 1000 transfers, budget 1004
...

• v1.3's arbiter: 1.00 cycles per transfer, one word every cycle, no idle cycles. That is the rate the system team had.

• v1.4's: 2.00, and exactly 1000 idle cycles for 1000 transfers. Not contention, which would give an untidy number, but one idle cycle per transfer, every time.

• The budget line fails. The same bench that printed PASS in the report now fails, and that is the tool for the next step.

Localise: bisect on cycles

The old test passes at every commit, so it cannot drive a bisection:

$ for c in $(git rev-list --reverse main); do git checkout -q $c; echo "$(git log -1 --format=%h) $(../perf-check.sh +NOBUDGET | tail -1)"; done
f1bdad0 PASS: 500 words from each master in order
dffd540 PASS: 500 words from each master in order
d7855ea PASS: 500 words from each master in order
353a3b1 PASS: 500 words from each master in order
fbdb9d3 PASS: 500 words from each master in order
de28814 PASS: 500 words from each master in order
b957a81 PASS: 500 words from each master in order
3c7969f PASS: 500 words from each master in order

With the budget on, it fails on v1.4 and passes on v1.3, so it can. The script builds whatever arb2.sv the commit has with the bench (kept outside the repository, so every commit is tested by the same bench) and returns git's codes: 0 good, 1 bad, 125 skip if it does not compile.

1
2
3
4
5
6
7
8

#!/bin/sh
# perf-check.sh: build arb2.sv from the current directory with the bench from the case study
# (saved next to this script) and run it. Exit 0 = pass, 1 = fail (functional or budget),
# 125 = does not compile (git bisect skips it).
here=$(cd "$(dirname "$0")" && pwd)
iverilog -g2012 -o "$here/arb_bisect.vvp" arb2.sv "$here/bench.sv" 2>/dev/null || exit 125
vvp -n "$here/arb_bisect.vvp" "$@" | grep -E "^(PERF|PASS|FAIL)"
vvp -n "$here/arb_bisect.vvp" "$@" | grep -q "^PASS" || exit 1

$ git bisect start v1.4 v1.3
Bisecting: 2 revisions left to test after this (roughly 1 step)
[fbdb9d37c770c82bfe1eb17b64863cf8118dfdbb] arb2: register the grant to cut the valid-to-ready path
$ git bisect run ../perf-check.sh
running '../perf-check.sh'
PERF: 1000 transfers in 2000 cycles, 2.00 cycles per transfer, idle cycles with a word waiting=1000
FAIL: PERF: 2000 cycles for 1000 transfers, budget 1004
Bisecting: 0 revisions left to test after this (roughly 0 steps)
[353a3b1ae5892e213c79dabb6b86e427e00a6af8] arb2: comment the grant path
running '../perf-check.sh'
PERF: 1000 transfers in 1000 cycles, 1.00 cycles per transfer, idle cycles with a word waiting=0
PASS: 500 words from each master in order
fbdb9d37c770c82bfe1eb17b64863cf8118dfdbb is the first bad commit
commit fbdb9d37c770c82bfe1eb17b64863cf8118dfdbb
...
    arb2: register the grant to cut the valid-to-ready path
...

Two runs. The bisection itself is the one you already know; the only new part is a test that fails on time instead of on a value. The guilty commit is the timing change, which is no surprise in hindsight, and the reason it was not suspected is in its message: it was a fix. Its diff, trimmed to the logic:

$ git show fbdb9d3
...
-  assign gnt       = pick(in_valid, last);   // valid -> pick -> ready: one long path
+  assign gnt       = gnt_q;                           // registered: in_ready no longer depends on in_valid
...
-    if (!rst_n) last <= 1'b1;
-    else if (fire) last <= gnt[1];
+    if (!rst_n) begin gnt_q <= '0; last <= 1'b1; end
+    else begin
+      if (fire) last <= gnt[1];
+      if (gnt_q == 2'b00) gnt_q <= pick(in_valid, last);
+      else if (fire)      gnt_q <= 2'b00;
+    end

Read the last two added lines as a timeline. A cycle with a transfer clears the grant. The next cycle has no grant, so nothing moves, and the register loads a new pick. The cycle after that moves a word. One transfer, one idle cycle, forever.

Observe again: the bubble in a waveform

Read the two halves as two copies of the same block fed the same traffic, and count words.

• Slots 0, 2, 4, 6, 8, bad copy: grant_bad holds 1 or 2 and a word moves (00, 80, 01, 81, 02).

• Slots 1, 3, 5, 7, 9, bad copy: grant_bad is 0, out_valid_bad is 0 and no word moves, although both masters are waiting. This is the release cycle from the diff.

• Good copy, every slot: the grant alternates 1, 2, 1, 2 with no gap, and ten words move in ten slots: the round robin hands over in the same cycle a transfer completes.

Hypothesise and test: one idle cycle per transfer, at any load

Hypothesis: each transfer costs one extra cycle in which the grant register reloads, whatever the traffic. That predicts something the full-load run cannot show: at half load, where masters often have nothing to send, the idle cycles with a word waiting should still equal the number of transfers, exactly, while the original arbiter should have none. If the cost came from contention instead, half load would shrink it.

$ vvp -n a0.vvp +LOAD=50 | grep -E "^PERF"        # v1.3's arbiter
PERF: 1000 transfers in 1179 cycles, 1.17 cycles per transfer, idle cycles with a word waiting=0
$ vvp -n ab.vvp +LOAD=50 | grep -E "^PERF"        # v1.4's
PERF: 1000 transfers in 2095 cycles, 2.09 cycles per transfer, idle cycles with a word waiting=1000

Exactly 1000 again. Each word now waits one cycle for the grant to load (or reload), at any load. The hypothesis survives a test it could have failed, and it says what the fix must do: decide the next owner in the cycle the transfer happens, not in the cycle after.

The fix and the lesson

Fix: hand over in the transfer cycle, and keep the register

Reverting the commit would bring the long valid-to-ready path back, and that path was the reason for the change. The better fix keeps gnt_q as a register and loads it on the transfer itself: the other master if it is waiting, otherwise the same owner. Only when the owner has nothing does it pick afresh.

// snippet: the fix (FIX=1), arb2's grant register
        if (fire)                       gnt_q <= (in_valid & ~gnt) != 2'b00 ? (in_valid & ~gnt) : gnt;  // hand over, or keep
        else if (!(|(gnt_q & in_valid))) gnt_q <= pick(in_valid, last);                              // owner has nothing

in_ready is still gnt & out_ready with gnt straight from a flop, so the timing improvement stays.

Prove: full rate, and the honest number at half load

$ iverilog -g2012 -o a.vvp arb_tb.sv && vvp -n a.vvp
PERF: 1000 transfers in 1001 cycles, 1.00 cycles per transfer, idle cycles with a word waiting=1
PASS: 500 words from each master in order (REG_GRANT=1 FIX=1)
...
$ vvp -n a.vvp +LOAD=50 | grep -E "^PERF"
PERF: 1000 transfers in 1369 cycles, 1.36 cycles per transfer, idle cycles with a word waiting=223

At full load the fix is back to one word per cycle and passes the budget; Verilator gives the same lines. At half load it is not free: 223 times a master that held the grant ran dry while the other was waiting, and a registered grant needs a cycle to notice. That is the real price of the timing fix: 1.36 cycles per transfer against v1.3's 1.17 at this load, about 14% fewer words per cycle, far from half. Whether it is acceptable depends on the traffic the port must carry, so write it in the change's review, with the table.

Prevent: make the regression count cycles

The bug escaped because no test could fail on time. The cure is the cycle budget in the block's bench, which now fails v1.4 and passes the fix, and a pinned test, as in the regression test that pins the bug: full-load traffic with a budget of transfers plus a small fill allowance. Add one review question for every timing fix that adds a register to a control path: in the cycle after this register changes, what does the circuit do? Here the honest answer was "nothing".

Which step won this hunt? Localise. Once a test failed on cycles, the commit was two runs away and its diff explained itself. Test then turned "one idle cycle per transfer" from a reading of the diff into a number checked at a second load.

Related topics

• Part 10 · Case Studies

• Part 5: performance bugs

• Counters and performance probes

• Bisection in history

• Bisection across configurations

• RTL: bus arbitration

• Case study: the deadlock under back-pressure