It fails until you look at it

A block with four accumulators fails about a third of its random seeds: one register ends with the wrong total. The engineer on it turns on the driver's verbose mode to see each command's result, reruns a failing seed, and it passes. Every seed passes in verbose mode. The ticket is about to be closed as "cannot reproduce with logging".

A bug that vanishes when observed is called a heisenbug. Is this one real, and if it is, how do you look at it without making it hide?

What people usually do, and why it fails

The common conclusions are "it was a glitch in the old build" or "verbose mode fixed it, ship verbose mode". Both assume the logging is a window. In a simulation it is part of the program: it can take simulated time, consume random numbers or touch the design, and any of those changes the run you are trying to watch.

The first defence is mechanical: compare the failing line of the quiet run with the observed run. If they differ, the observation changed the run, and nothing it shows describes the original failure.

The method: three ways to disturb, one way not to

1. Compare quiet and observed runs of the same seed. Same FAIL line, same cycle: the observation is safe. Anything else: it disturbed the run.

2. Observe from the side. A monitor watches the pins, samples on the clock edge and drives nothing. It needs no wait and no handshake.

3. Keep debug out of the stimulus generator. Use a separate generator for anything random in debug code, or none at all.

4. Never read with side effects. Use backdoor or shadow reads of counters and status, not bus reads of clear-on-read registers.

5. Record cheaply and print later when printing is slow: a flight recorder costs one write per cycle.

The picture: a wait opens the gap

Do it: one bug, four ways to log it

The design adds a value to one of four registers in two stages: read in the first cycle, write the sum in the second. A command to the same register in the very next cycle reads the old value and one addition is lost. The fix forwards the sum still in flight. The bench sends 20 commands with random gaps of 0 to 15 cycles. +LOG=1 makes the driver log each result, which means waiting a cycle to read it; +LOG=2 logs the same facts from a passive monitor; +LOG=3 logs one command in four, picked with the stimulus generator, and never waits.

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

// acc4: four 8-bit accumulators. A command adds cmd_add to register cmd_addr, in two stages:
// read in the first cycle, write the sum in the second.
// The bug: a command to the same register in the very next cycle reads the old value, because
// the sum of the command ahead of it is not written yet. One of the two additions is lost.
module acc4 #(parameter bit FIX = 0) (
  input  logic       clk, rst_n, cmd_valid,
  input  logic [1:0] cmd_addr,
  input  logic [7:0] cmd_add,
  output logic [7:0] acc [4]
);
  logic       v_q;
  logic [1:0] a_q;
  logic [7:0] sum_q, rd;
  // the fix forwards the sum still in flight to a command for the same register
  assign rd = (FIX && v_q && a_q == cmd_addr) ? sum_q : acc[cmd_addr];
  always_ff @(posedge clk or negedge rst_n)
    if (!rst_n) begin
      v_q <= 1'b0; a_q <= '0; sum_q <= '0;
      for (int i = 0; i < 4; i++) acc[i] <= '0;
    end else begin
      v_q <= cmd_valid;
      if (cmd_valid) begin a_q <= cmd_addr; sum_q <= rd + cmd_add; end
      if (v_q) acc[a_q] <= sum_q;
    end
endmodule

// heis_tb: 20 seeded commands with gaps of 0 to 15 idle cycles, checked against a model at the
// end. +LOG=0 quiet; +LOG=1 the driver logs each command's result (and waits a cycle to read it);
// +LOG=2 a passive monitor logs the same thing; +LOG=3 the driver logs one command in four, picked
// with the stimulus generator. +SEED=<n>; +FIX=1 uses the fixed design.
// With no plusargs it runs seeds 1 to 100 in all four modes and checks the lesson's claims.
`timescale 1ns/1ps

$ iverilog -g2012 -o h.vvp heis_tb.sv && vvp -n h.vvp
seeds 1-100 failing: quiet 31, driver logging 0, passive monitor 31, sampled log 25 (60 seeds agree with quiet)
PASS: the driver's logging hides the bug; the passive monitor sees every failure
$ for m in 0 1 2 3; do vvp -n h.vvp +SEED=8 +LOG=$m | grep -E "^(PASS|FAIL)"; done
FAIL seed=8 log=0: acc[2]=238, expected 164 (0 lines logged)
PASS seed=8 log=1: all four registers match (20 lines logged)
FAIL seed=8 log=2: acc[2]=238, expected 164 (20 lines logged)
PASS seed=8 log=3: all four registers match (5 lines logged)

Read the four lines of seed 8. Quiet, it fails: acc[2] is 238, not 164. With the driver logging, it passes. With the passive monitor, it fails with exactly the same line, which is the check that the monitor did not disturb the run. With the sampled log, which never waits, it passes too. Over 100 seeds, the waiting log hid all 31 failures; the sampled log made a different test, failing 25 seeds and agreeing with the quiet run on only 60. Verilator printed the same lines.

What each log shows

$ vvp -n h.vvp +SEED=8 +LOG=2
  mon: t=35000 acc[0] <- 13
  mon: t=115000 acc[3] <- 177
...
  mon: t=565000 acc[2] <- 182
  mon: t=575000 acc[2] <- 214
  mon: t=615000 acc[0] <- 77
...
$ vvp -n h.vvp +SEED=8 +LOG=1
  drv: t=40000 acc[0] <- 13
  drv: t=130000 acc[3] <- 177
...
  drv: t=630000 acc[2] <- 182
  drv: t=650000 acc[2] <- 140
  drv: t=700000 acc[0] <- 77

The monitor's log shows the failure directly: two writes to acc[2] 10 ns apart, at 565 and 575 ns. acc[2] had not been written before, so the first command added 182 and the second added 214; the second sum, 214, was computed from the old value 0 before 182 had been written. That is the back-to-back hazard, at the cycle it happens. The driver's log shows the same two commands 20 ns apart, at 630 and 650 ns, and the second sum is 140, which is 182 + 214 in 8 bits: correct. The log is accurate, about a run that is not the failing one.

$ vvp -n h.vvp +SEED=8 +LOG=3
  drv: t=110000 sent acc[2] += 105
  drv: t=230000 sent acc[1] += 61
...
PASS seed=8 log=3: all four registers match (5 lines logged)

The sampled log takes no time at all, and still hides the bug. Each decision to print draws one number from the generator that also picks the commands, so after the first such draw every address, value and gap is different from the quiet run: the same seed, a different test. This is the random-stability effect from determinism and seeds, arriving through debug code.

What the evidence says

The bug is real and deterministic: seed 8 fails every quiet run. Two of the three logging methods changed the test, one by time and one by randomness, and both made seed 8 pass. Only the passive monitor kept the failing line identical, and it showed the hazard at its cycle. The fix (forward the in-flight sum) passes seed 8 quietly, which is the test that matters: a fix must be proven on the quiet run, not on the observed one.

Outside simulation the same three disturbances have physical forms. A scope probe adds load to a marginal net; reading a chip's state over scan stops its clocks; adding trace signals to an emulator or FPGA build re-places the design. When a lab failure changes with the instrument, the bring-up course treats that as data about the failure, not as a fix.

Traps

Related topics

• Part 8 · Intermittent Failures

• Next: an intermittent on dbglab

• Logging that helps

• UVM: debugging the testbench