In a large regression nobody reads logs top to bottom; triage scripts grep them. That sets the design: fixed field order, one record per line, a severity tag scripts can key on, and a verbosity system so the same testbench whispers in regression and shouts in replay.
Every line carries time, severity, scope, and a transaction id where one applies. With a hierarchical scope such as ENV.AGT0.MON and zero-padded ids such as txn#0042, the life of any transaction comes back from one grep.
[12450] INFO [ENV.AGT0.DRV] txn#0042 sent : WR addr=0x1040 data=0xdead
[12480] INFO [ENV.AGT0.MON] txn#0042 seen : WR addr=0x1040 data=0xdead
[12490] LOG_ERROR [ENV.SCB] txn#0042 wrong : exp=0xdead act=0xbeef
triage greps:
grep "LOG_ERROR" run.log -> all recorded problems
grep "txn#0042" run.log -> full life of the failing transaction
grep -m1 "LOG_ERROR" run.log -> first-problem signature for bucketingThe error level routes into the central problem counter, so logging a problem and failing the test are the same act. A checker cannot complain in the log yet let the test pass.
Level | Value | Regression use | Replay use |
|---|---|---|---|
| 0 | Always on; feeds the verdict counter | Always on |
| 1 | On; unexpected but tolerated events | On |
| 2 | On; milestones and heartbeats | On |
| 3 | Off; per-transaction chatter | On; full detail for one seeded run |
The listing below is complete and runs under Icarus 13 and Verilator. One task filters on a threshold set from a knob, tags each line, and counts recorded problems for the verdict.
It prints two INFO lines, suppresses one DEBUG line at the default threshold, and banners PASS with the exact counts.
module tb_log_demo;
localparam int LOG_ERROR = 0;
localparam int LOG_WARN = 1;
localparam int LOG_INFO = 2;
localparam int LOG_DEBUG = 3;
int threshold;
int err_count = 0;
string scope;
task automatic log_msg(input int lvl, input string msg);
if (lvl <= threshold) begin
if (lvl == LOG_ERROR) begin
$display("[%0t] LOG_ERROR [%s] %s", $time, scope, msg);
err_count = err_count + 1;
end
else if (lvl == LOG_WARN) $display("[%0t] LOG_WARN [%s] %s", $time, scope, msg);
else if (lvl == LOG_INFO) $display("[%0t] LOG_INFO [%s] %s", $time, scope, msg);
else $display("[%0t] LOG_DEBUG [%s] %s", $time, scope, msg);
end
endtask
initial begin
scope = "ENV.AGT0.DRV";
if (!$value$plusargs("VERBOSITY=%d", threshold)) threshold = LOG_INFO;
log_msg(LOG_INFO, "txn#0001 sent : WR addr=0x1040 data=0xdead");
log_msg(LOG_DEBUG, "txn#0001 beats : 4 raw beats, see replay log");
log_msg(LOG_INFO, "progress: 2 of 2 milestones done");
if (err_count == 0)
$display("PASS: logger printed 2 INFO lines and suppressed 1 DEBUG line");
else
$fatal(1, "FAIL: logger recorded a problem on a clean run");
$finish;
end
endmoduleProduction testbenches wrap the same idea in a class with per-component scope objects. The class listing below is a class with no top module, so this course's checks do not run it. Its error level feeds a shared counter, like the procedural logger.
// not-run: class only, no top module
class logger;
static int err_count = 0; // shared problem counter for the verdict
int threshold = 2;
string scope;
function new(string scope_in);
scope = scope_in;
endfunction
task log_msg(int lvl, string msg);
if (lvl == 0) begin
$display("[%0t] LOG_ERROR [%s] %s", $time, scope, msg);
err_count++; // logging a problem fails the test
end
else if (lvl == 1)
$display("[%0t] LOG_WARN [%s] %s", $time, scope, msg);
else if (lvl == 2)
$display("[%0t] LOG_INFO [%s] %s", $time, scope, msg);
else if (lvl <= threshold)
$display("[%0t] LOG_DEBUG [%s] %s", $time, scope, msg);
endtask
endclassThe [CFG] line from the knobs lesson doubles as runtime documentation. Print every effective knob at time zero so the log states exactly what the run did.
A DEBUG log of a million-transaction soak can reach gigabytes and slow the simulation, since formatting strings costs real time. Regression runs at INFO with per-transaction chatter at DEBUG, which costs almost nothing when filtered.
The level check must run before formatting. The fragment below is partial and only illustrates the guard; it uses %h because Icarus 13 does not support %p.
// snippet
if (threshold >= LOG_DEBUG)
log_msg(LOG_DEBUG, $sformatf("raw beat: %h", beat));Prefer a periodic heartbeat over per-transaction INFO noise. One progress line per thousand transactions keeps the log small and still shows liveness.
The problem line was printed with a plain display call that never reached the counter. Error-level logging and the verdict counter must be the same act.
$sformatf call instead of filtering inside the logger alone?An unguarded call builds the string on every transaction and throws it away. The guard skips the formatting work, which is where the simulation time goes.