Fourteen hundred lines and no answer

dbglab's random test fails with seed 10. The bench names the damage precisely:

FAIL test=random seed=10 cycle=4895: SCOREBOARD: RAM word 808 (address 00001ca0) read d5202ff9, expected b6c3311c (last written by DMA run #29)

Someone added debug prints to the bus a while ago, and the run's log has 1,404 lines. The question is simple: did DMA run #29 ever write address 0x1ca0? Can the log answer it?

What people usually do, and why it fails

Most debug prints are written in a hurry, to answer one question on one afternoon, and then left in. They look like this, from the same run:

$ ../probes/run-probe.sh ../probes/bus_log_v1.sv random 10 +VERB=3 +OLD | tail -9
DMA wrote 70c8976c
DMA wrote 2681e9be
DMA wrote 2a3c40ba
DMA finished
CPU  read 00000002
CPU wrote 00000002
CPU  read 00000000
CPU  read d5202ff9
FAIL test=random seed=10 cycle=4895: SCOREBOARD: RAM word 808 (address 00001ca0) read d5202ff9, expected b6c3311c (last written by DMA run #29)

Try to answer the question. There is no address, so you cannot search for 0x1ca0. There is no cycle, so you cannot line the prints up with the FAIL line at cycle 4895. There is no run number, so you cannot tell which "DMA wrote" lines belong to run #29; you would have to count "DMA started" lines by hand. The only line you can connect to the failure is the last read, and only because the data matches.

When prints like these do not answer the question, the usual next step is to add more of them, then a waveform, then a day.

The method: a log line is a record, not a sentence

Logging is part of Observe. A log does not replace a waveform; it covers the whole run cheaply, so you can find where to look before you dump anything. Five rules make it useful:

1. One event per line, starting with the time. Use the bench's cycle counter (and the clock domain, if there are several), so every line can be compared with a FAIL message.

2. Fixed fields, in a fixed order, as key=value. Level, source, id, event, then details. grep 'run=29 ' and awk need no guessing.

3. Ids that match the bench. If the scoreboard says "DMA run #29", the log says run=29. Count the same way (here, both count DMA starts).

4. Log at boundaries. One line when a transaction completes at an interface, not one per signal change. The interface is where ownership changes, so that is where blame is decided.

5. Levels by reader. Level 1 for what a person reads by default, higher levels for what a script reads. Each level should be useful on its own.

The picture: what one line must carry

Do it: a structured log of the same run

The logger

A small module compiled next to dbglab watches both bus masters and prints one line when each transaction completes, plus one line when each DMA run starts and finishes. It only reads the design:

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
46
47
48
49
50

// not-run: needs dbglab's sources and bench; compile it next to them (command in the Evidence box)
// txn_log: one line per finished bus transaction and per DMA run, for grep and awk.
//   +VERB=<n>  0 nothing, 1 DMA run start and done, 2 also DMA transactions, 3 also CPU ones
// Every line: cyc=<bus cycle> lvl=<INFO|DBG> who=<master> <id> ev=<event> <fields as key=value>
`timescale 1ns/1ps
module txn_log;
  import dbglab_pkg::*;
  int unsigned verb, run = 0, n_cpu = 0;    // run counts DMA starts, as the bench's "DMA run #n"
  bit          pend [2];                    // per master: request accepted, response not yet seen
  bit          pw   [2];
  logic [31:0] pa   [2], pd [2];
  int unsigned pc   [2];
  string       who;
  initial if (!$value$plusargs("VERB=%d", verb)) verb = 1;

  function automatic string rs(input logic [1:0] r);
    return r == RESP_OKAY ? "OK" : r == RESP_SLVERR ? "SLVERR" : r == RESP_DECERR ? "DECERR" : "BAD";
  endfunction

  always @(posedge dbglab_tb.clk) begin
    #0.5;                                   // just after the edge
    if (dbglab_tb.dut.u_dma.start && !dbglab_tb.dut.u_dma.busy) begin
      run++;
      if (verb >= 1)
        $display("cyc=%0d lvl=INFO who=dma run=%0d ev=START len=%0d src=%h dst=%h ctrl=%h", dbglab_tb.cycle, run,
                 dbglab_tb.dut.dma_len, dbglab_tb.dut.dma_src, dbglab_tb.dut.dma_dst, dbglab_tb.dut.dma_ctrl);
    end
    if (dbglab_tb.dut.u_dma.done && verb >= 1)
      $display("cyc=%0d lvl=INFO who=dma run=%0d ev=DONE err=%b", dbglab_tb.cycle, run, dbglab_tb.dut.dma_err);
  end

  for (genvar m = 0; m < 2; m++) begin : g_m          // m = 0 the CPU port, m = 1 the DMA
    always @(posedge dbglab_tb.clk) begin
      if (dbglab_tb.dut.m_rvalid[m] && pend[m]) begin   // the response ends the transaction
        pend[m] = 1'b0;
        if (m == 0) n_cpu++;
        if (verb >= 3 - m) begin                         // DMA from level 2, CPU from level 3
          who = m ? $sformatf("dma run=%0d", run) : $sformatf("cpu op=%0d", n_cpu);
          $display("cyc=%0d lvl=DBG who=%s ev=%s addr=%h data=%h resp=%s lat=%0d", dbglab_tb.cycle, who,
                   pw[m] ? "WR" : "RD", pa[m], pw[m] ? pd[m] : dbglab_tb.dut.m_rdata,
                   rs(dbglab_tb.dut.m_resp), dbglab_tb.cycle - pc[m]);
        end
      end
      if (dbglab_tb.dut.m_valid[m] && dbglab_tb.dut.m_ready[m]) begin   // the request is taken
        pend[m] = 1'b1; pw[m] = dbglab_tb.dut.m_write[m]; pa[m] = dbglab_tb.dut.m_addr[m];
        pd[m] = dbglab_tb.dut.m_wdata[m]; pc[m] = dbglab_tb.cycle;
      end
    end
  end
endmodule

The same nine events at the end of the run now read:

$ ../probes/run-probe.sh ../probes/txn_log.sv random 10 +VERB=3 > t3.log
$ tail -9 t3.log
cyc=4848 lvl=DBG who=dma run=29 ev=WR addr=00001be0 data=70c8976c resp=OK lat=1
cyc=4853 lvl=DBG who=dma run=29 ev=WR addr=00001be4 data=2681e9be resp=OK lat=1
cyc=4858 lvl=DBG who=dma run=29 ev=WR addr=00001be8 data=2a3c40ba resp=OK lat=1
cyc=4859 lvl=INFO who=dma run=29 ev=DONE err=0
cyc=4861 lvl=DBG who=cpu op=576 ev=RD addr=0000200c data=00000002 resp=OK lat=1
cyc=4864 lvl=DBG who=cpu op=577 ev=WR addr=0000200c data=00000002 resp=OK lat=1
cyc=4867 lvl=DBG who=cpu op=578 ev=RD addr=0000200c data=00000000 resp=OK lat=1
cyc=4894 lvl=DBG who=cpu op=579 ev=RD addr=00001ca0 data=d5202ff9 resp=OK lat=1
FAIL test=random seed=10 cycle=4895: SCOREBOARD: RAM word 808 (address 00001ca0) read d5202ff9, expected b6c3311c (last written by DMA run #29)

Read the lines against the FAIL message. Run #29's last write went to 0x1be8 at cycle 4858, and the run finished at 4859 without an error. The CPU then polls STATUS (0x200c) and clears done, and at cycle 4894 reads 0x1ca0, the failing read, one cycle before the bench reports it. Every line can now be found by when, who, which run and which address.

Levels: how much each reader needs

$ for v in 0 1 2 3; do ../probes/run-probe.sh ../probes/txn_log.sv random 10 +VERB=$v | wc -l; done
       2
      60
     825
    1404

Level 0 is the bench's own two lines. Level 1 adds 58 lines, one start and one done per DMA run: a person can read that. Level 2 adds the DMA's 765 transactions, and level 3 the CPU's 579, for scripts. On the 90,623-cycle run from the dump strategy lesson, the cost is small next to a waveform:

Even level 3, every transaction of the whole run, is 2.1 MB and 11% more run time; the full waveform of the same run was 36.8 MB and 63% more. A log at the boundaries is the one record you can afford to keep for the whole run.

Ask the log a question

Did DMA run #29 write address 0x1ca0? One grep:

$ grep 'addr=00001ca0' t3.log
cyc=4894 lvl=DBG who=cpu op=579 ev=RD addr=00001ca0 data=d5202ff9 resp=OK lat=1
$ grep 'run=29 ' t3.log | grep -c 'ev=WR'
52

Nothing on the bus ever wrote 0x1ca0 in this run; the only access is the failing read. And run #29 made 52 writes. The model thinks run #29 wrote word 808, and the hardware disagrees. (The trailing space in 'run=29 ' stops it matching run 290.)

Now a wider question that no single print could answer: did any other run write a different number of words than it was asked for? An awk script reads each line's key=value fields into an array and compares the writes of every run that ended without an error with its len:

1
2
3
4
5
6
7

# short-runs.awk: DMA runs that ended without an error but wrote fewer or more words than LEN.
{ delete f; for (i = 1; i <= NF; i++) { split($i, kv, "="); f[kv[1]] = kv[2] } }
f["ev"] == "START"                  { len[f["run"]] = f["len"] }
f["who"] == "dma" && f["ev"] == "WR" { wr[f["run"]]++ }
f["ev"] == "DONE" && f["err"] == 0 && wr[f["run"]] != len[f["run"]] {
  print "run " f["run"] ": len " len[f["run"]] ", wrote " wr[f["run"]] + 0 ", done at cycle " f["cyc"]
}

$ ../probes/run-probe.sh ../probes/txn_log.sv random 10 +VERB=2 > t2.log
$ awk -f short-runs.awk t2.log
run 29: len 308, wrote 52, done at cycle 4859
$ awk -f short-runs.awk big2.log          # the 90,623-cycle run, 13,627 lines
run 591: len 294, wrote 38, done at cycle 90578

One run out of 29 is short, by exactly 256 words, and on the long run one out of 591, again by 256. The log has localised the failure to one DMA run and handed you a hypothesis (a counter that wraps at 256) before you opened a waveform. The debug loop lesson takes that hypothesis to its fix.

What the evidence says

The free-text log and the structured one record the same events. Only the fields differ, and the fields decided whether the log could answer anything. With a cycle, an address and a run id, a grep proved the RAM word was never written, and a seven-line awk script found the short run in a 13,627-line log in a tenth of a second. Comparing two such logs, one from a passing run and one from a failing one, is the subject of comparing a good and a bad run.

Traps

Related topics

• Part 2 · Observe

• Comparing a good and a bad run

• Assertions as always-on probes

• UVM: debugging the testbench