Commit 11 of dbglab promised that the DMA would "run about 20% faster" by keeping the bus for a whole chunk. The DMA test got faster. A week later the firmware team says CPU register accesses "sometimes feel slow" while a DMA runs, and one regression test now hangs.
Nothing reads back wrong, so there is no first wrong value to chase. How do you see where the cycles went, and which part of the design is waiting?
The first instinct is the end-to-end number: the test took 11816 ns instead of 15366 ns, so the change works. The second is a waveform, scrolled by hand, looking for long gaps. Both miss the point. A total says nothing about who paid for the speed-up, and a 1,200-cycle waveform of a busy bus is a wall of handshakes in which a 31-cycle wait looks like any other.
Performance and hang questions are about distributions over time, and eyes are bad at those. You need the design to count for you.
Instrument | Answers | Example in dbglab |
|---|---|---|
Event counter | How often did it happen? | Handshakes per master; words into the peripheral FIFO |
Wait counter | How long did someone wait for it? | Cycles with |
Occupancy and high-water mark | How full did it get? | Peak entries in the peripheral FIFO; cycles in each DMA state |
Latency histogram and maximum | How long did each one take, and the worst? | CPU cycles from |
Count at the handshake. An event is valid && ready in one cycle, not valid high. Counting levels instead of events is the most common counter bug.
Pair work with waiting. 182 DMA handshakes mean little alone; 182 handshakes and 430 wait cycles mean the DMA spends more time asking for the bus than using it.
Keep the tail. For latency, keep a histogram and the maximum, never only the sum. Power-of-two buckets (1, 2-3, 4-7 ...) need one comparator each and cover a wide range.
Snapshot for hangs. Print or read the counters periodically. Between two snapshots in a hang, some counters stop and one keeps climbing. The climbing one names the stage that is waiting.
On the debug loop this is Observe for the bugs that have no wrong value. The numbers do not explain the cause; they say where to look and give you a prediction to test.
The counters live in a probe compiled next to dbglab, so dbglab itself is untouched; the same block could sit in the RTL behind a debug register. It reads the fabric's handshakes, the DMA's state and the peripheral FIFO's pointers.
// not-run: needs dbglab's sources and bench; compile it next to them (command in the Evidence box)
// perf_probe: event counters, a high-water mark and a latency histogram for dbglab, compiled
// next to the design. It only reads signals. +EVERY=<n> prints the counters every n cycles.
`timescale 1ns/1ps
module perf_probe;
localparam int NB = 6; // latency buckets: 1, 2-3, 4-7, 8-15, 16-31, 32+
int unsigned every, cyc = 0;
int unsigned hs [2], waitc [2]; // handshakes, cycles valid && !ready
int unsigned lat_hist [NB], lat_max = 0, lat_now = 0;
int unsigned st_cyc [16]; // DMA cycles per state
int unsigned words = 0, hwm = 0, level;
logic [4:0] rbin_w; // read pointer seen by the write side, binary
function automatic int bucket(int unsigned n);
if (n <= 1) return 0; if (n <= 3) return 1; if (n <= 7) return 2;
if (n <= 15) return 3; if (n <= 31) return 4; return 5;
endfunction
initial if (!$value$plusargs("EVERY=%d", every)) every = 0;
always @(negedge dbglab_tb.clk) if (dbglab_tb.rst_n) begin
cyc++;
for (int m = 0; m < 2; m++) begin
if (dbglab_tb.dut.m_valid[m] && dbglab_tb.dut.m_ready[m]) hs[m]++;
if (dbglab_tb.dut.m_valid[m] && !dbglab_tb.dut.m_ready[m]) waitc[m]++;
end
// CPU latency: cycles from valid to ready, counted per request
if (dbglab_tb.dut.m_valid[0]) begin
lat_now++;
if (dbglab_tb.dut.m_ready[0]) begin
lat_hist[bucket(lat_now)]++;
if (lat_now > lat_max) lat_max = lat_now;
lat_now = 0;
end
end
st_cyc[dbglab_tb.dut.u_dma.state]++;
if (dbglab_tb.dut.u_per.winc) words++;
// occupancy of the peripheral FIFO as the write side sees it
rbin_w = dbglab_tb.dut.u_per.u_fifo.rptr_sync_w;
for (int i = 3; i >= 0; i--) rbin_w[i] = rbin_w[i + 1] ^ dbglab_tb.dut.u_per.u_fifo.rptr_sync_w[i];
level = 5'(dbglab_tb.dut.u_per.u_fifo.wbin - rbin_w);
if (level > hwm) hwm = level;
if (every != 0 && cyc % every == 0) show($sformatf("cycle %0d", dbglab_tb.cycle));
end
function automatic void show(string tag);
$display("PERF %s: hs cpu=%0d dma=%0d wait cpu=%0d dma=%0d dma WAIT=%0d fifo words=%0d hwm=%0d",
tag, hs[0], hs[1], waitc[0], waitc[1], st_cyc[6], words, hwm);
endfunction
final begin
show("end");
$display("PERF cpu latency (cycles valid->ready): 1:%0d 2-3:%0d 4-7:%0d 8-15:%0d 16-31:%0d 32+:%0d max=%0d open=%0d",
lat_hist[0], lat_hist[1], lat_hist[2], lat_hist[3], lat_hist[4], lat_hist[5], lat_max, lat_now);
$display("PERF dma state cycles: IDLE=%0d CHUNK=%0d RD_REQ=%0d RD_RSP=%0d POP=%0d LOAD=%0d WAIT=%0d WR_REQ=%0d WR_RSP=%0d",
st_cyc[0], st_cyc[1], st_cyc[2], st_cyc[3], st_cyc[4], st_cyc[5], st_cyc[6], st_cyc[7], st_cyc[8]);
end
endmodule$ (cd c10 && sh ../probes/run-probe.sh ../probes/perf_probe.sv dma_copy 1) # commit 10
dbglab: test=dma_copy seed=1
PASS test=dma_copy seed=1
tb/dbglab_tb.sv:327: $finish called at 15366000 (1ps)
PERF end: hs cpu=328 dma=182 wait cpu=874 dma=430 dma WAIT=91 fifo words=0 hwm=0
PERF cpu latency (cycles valid->ready): 1:0 2-3:146 4-7:182 8-15:0 16-31:0 32+:0 max=5 open=0
PERF dma state cycles: IDLE=435 CHUNK=25 RD_REQ=430 RD_RSP=91 POP=91 LOAD=91 WAIT=91 WR_REQ=182 WR_RSP=91
$ (cd c11 && sh ../probes/run-probe.sh ../probes/perf_probe.sv dma_copy 1) # commit 11
dbglab: test=dma_copy seed=1
PASS test=dma_copy seed=1
tb/dbglab_tb.sv:327: $finish called at 11816000 (1ps)
PERF end: hs cpu=171 dma=182 wait cpu=833 dma=75 dma WAIT=91 fifo words=0 hwm=0
PERF cpu latency (cycles valid->ready): 1:0 2-3:146 4-7:0 8-15:3 16-31:22 32+:0 max=31 open=0
PERF dma state cycles: IDLE=435 CHUNK=25 RD_REQ=166 RD_RSP=91 POP=91 LOAD=91 WAIT=91 WR_REQ=91 WR_RSP=91Read the DMA first. Both commits make 182 handshakes (91 words read, 91 written). At commit 10 the DMA waited 430 cycles for the bus, and its read-request state alone took 430 cycles for 91 reads: almost five cycles of asking per read. The bottleneck was arbitration, not the RAM. At commit 11 the wait drops to 75 cycles and the test ends 3,550 ns sooner. The speed-up is real, and the counters say exactly where it came from.
Now the CPU. Its total wait barely moved (874 cycles, then 833); if you had only that counter you would say the CPU was unaffected. The histogram says otherwise:
Read the buckets left to right. Commit 10's requests all finish within 5 cycles. Commit 11 makes fewer requests (171, because the CPU polls STATUS fewer times when the DMA finishes sooner), most of them faster, and 25 of them much slower: up to 31 cycles, the length of a locked chunk. That is the firmware team's "sometimes slow". An average would have shown an improvement.
$ sh ../probes/run-probe.sh ../probes/perf_probe.sv dma_burst_backpressure 1 +EVERY=500 # HEAD
dbglab: test=dma_burst_backpressure seed=1
PERF cycle 503: hs cpu=11 dma=36 wait cpu=475 dma=15 dma WAIT=353 fifo words=16 hwm=16
PERF cycle 1003: hs cpu=11 dma=36 wait cpu=975 dma=15 dma WAIT=853 fifo words=16 hwm=16
PERF cycle 1503: hs cpu=11 dma=36 wait cpu=1475 dma=15 dma WAIT=1353 fifo words=16 hwm=16
PERF cycle 2003: hs cpu=11 dma=36 wait cpu=1975 dma=15 dma WAIT=1853 fifo words=16 hwm=16
FAIL test=dma_burst_backpressure seed=1 cycle=2165: WATCHDOG: no bus or stream progress for 2000 cycles; cpu_valid=1 cpu_ready=0 cpu_addr=00003008
PERF end: hs cpu=11 dma=36 wait cpu=2137 dma=15 dma WAIT=2015 fifo words=16 hwm=16
PERF cpu latency (cycles valid->ready): 1:0 2-3:7 4-7:0 8-15:0 16-31:4 32+:0 max=31 open=2010
PERF dma state cycles: IDLE=21 CHUNK=5 RD_REQ=35 RD_RSP=20 POP=17 LOAD=17 WAIT=2015 WR_REQ=16 WR_RSP=16Four snapshots, and the picture is plain. Every handshake counter is frozen (CPU 11, DMA 36); no work is being done. Two counters climb by exactly 500 per snapshot: the CPU's wait and the DMA's WAIT state. Sixteen words went into the FIFO, none after the first snapshot, and its high-water mark is 16, its full depth: the FIFO filled and the sink took nothing out. So the CPU is waiting for the bus, the DMA is waiting in WAIT for FIFO space, and the FIFO is full. The open CPU request has waited 2,010 cycles, and it sits beyond the histogram's 32+ bucket because it never finished. That is the stuck stage, found without a waveform; the deadlock case study turns these facts into the wait-for cycle.
Commit 11 did what it promised for the DMA and moved the cost to the CPU's worst case. Under back-pressure that worst case stops being 31 cycles and becomes forever: the same lock that made the tail is the one in the hang. That gives a prediction to test: a change that releases the bus after every response should bring the CPU maximum back to 5 and make dma_copy slow again. With the case study's fix (assign accept = rsp_fire;) on a copy of HEAD, the probe reports max=5, no request in the 8-31 buckets, and the test ends at 15366 ns: the prediction held, and the trade-off is now measured on both sides.
if (dma_valid) dma_reqs++ and reports 612 DMA requests in dma_copy at commit 10. The DMA moved 91 words. What went wrong?The counter counts cycles with valid high, not handshakes. Cycles with valid high are the 182 handshake cycles plus the 430 waiting cycles, so the number mixes work and waiting. Count valid && ready for requests (182 here: 91 reads and 91 writes) and valid && !ready separately for waiting. The ratio of the two is the useful number.
First the handshake counters: frozen means nothing is moving. Then the wait counters: the ones climbing one per cycle name who is stuck. In a livelock the handshake counters keep climbing, but the counters of finished work (words delivered, DMA runs done) stay flat. Work counters and completion counters together tell a hang from a livelock.
dbglab rebuilt with dbglab/build-history.sh, 2026-10-17, Icarus Verilog 13.0. perf_probe.sv compiled next to dbglab (dbglab unchanged) with iverilog -g2012 -Wno-timescale -I tb -o build/probe.vvp <rtl/files.f> tb/bus_rules.sv tb/dbglab_tb.sv perf_probe.sv and run with vvp -n build/probe.vvp +TEST=dma_copy +SEED=1 at commit 10 (27acd30) and commit 11 (c4a71b5).
Results: commit 10 ends at 15366 ns, commit 11 at 11816 ns; DMA wait cycles 430 and 75; CPU wait cycles 874 and 833; CPU latency maximum 5 and 31 cycles, with 25 of 171 CPU requests waiting 8 or more cycles at commit 11 and none at commit 10.
Hang: the same probe at HEAD (49c5f04) with +TEST=dma_burst_backpressure +SEED=1 +EVERY=500: handshake counts frozen at cpu=11 dma=36 from the first snapshot, CPU wait and DMA WAIT counts rising by 500 per snapshot, FIFO high-water mark 16 (full). Fix check: HEAD copy with assign accept = rsp_fire; in rtl/bus_fabric.sv, +TEST=dma_copy +SEED=1: 15366 ns, CPU latency max 5.
Limits: one design and one test per comparison, simulation only. The probe reads signals in simulation; an RTL counter block costs area and needs its own checks (see the observability lesson). random is not compared across commits because its stimulus depends on timing.