Structured Logging for UVM: 12 Patterns That Make Your Testbench Queryable
Open a typical regression triage report: 10,234 failing tests. Open one of the logs: 80 MB of prose. Open another: same shape, different text. Your job is to determine which of these failures are duplicates of which others, and the answer is buried in human-readable strings designed to be skimmed, not queried.
This post is about the discipline that fixes that. Structured logging is the practice of treating every event your testbench emits as a row in a queryable database, not a sentence in a prose document. Once you internalize that one shift, regression triage stops being archaeology and starts being SQL.
We will cover 12 patterns that take a normal UVM testbench from "10K fails to triage" to "10K fails grouped into 12 root causes," with a complete drop-in uvm_report_server you can use Monday morning.
- The Problem: Logs as Prose
- Pattern 1-2: The JSON Foundation
- Pattern 3-5: Identity Threading
- Pattern 6-8: Domain Context
- Pattern 9: The Context-Window Ring Buffer
- Pattern 10: Coverage Integration
- Pattern 11: The Run Header
- Pattern 12: Failure Fingerprints
- 16 More Patterns
- Putting It Together
The Problem: Logs as Prose
A typical UVM error message looks like this:
`uvm_error("DRV", $sformatf("AXI burst error at addr 0x%0h, id=%0d, seq=%s",
addr, id, current_seq.get_name()))
Readable. Useful in a single failing run. Catastrophic at regression scale. When 10,000 failures contain variations of this line — different addresses, different IDs, different sequence names — there is no programmatic way to determine which are the same bug except regex over prose.
The shift is small in code, transformative in capability. Emit the same information as structured fields:
{"ts": 1234567, "sev": "ERROR", "id": "AXI_BURST_ERROR",
"addr": "0x100", "axi_id": 3, "seq": "axi_burst_seq",
"test_id": "axi_smoke_001", "seed": 42, "txn_id": "uuid-abc..."}
Now jq works. grep -F works. SQLite ingestion works. Sentry-style fingerprinting works. The same information, with the same emission cost, becomes queryable.
flowchart LR
A[UVM Components] -- uvm_info / uvm_error --> B[uvm_report_server]
B --> C[Human log
unchanged]
B --> D[JSONL sidecar
structured]
D --> E[jq / SQLite / Sentry]
D --> F[LLM debug bundles]
Pattern 1-2: The JSON Foundation
UVM's uvm_report_server is the single emission point for every log line. Override it once, and every `uvm_info / `uvm_error in your testbench gains structure for free.
Pattern 1: JSON sidecar via custom report server. Emit two streams — the human log unchanged for engineers, a parallel JSONL file for machines.
Pattern 2: Strongly-typed log records as SV classes. Do not reach for $sformatf in components — build a typed record and let the report server serialize it. Compile-time schema enforcement is worth a lot of grief saved later.
Here is a complete drop-in implementation. Compile this into your TB and a JSONL file appears alongside every run:
// File: silicondv_log_server.sv
class silicondv_log_record extends uvm_object;
`uvm_object_utils(silicondv_log_record)
// Required schema fields
string event_id; // e.g., "AXI_BURST_ERROR"
string txn_id; // UUID threaded across components
string seq_name;
longint sim_time_ns;
string severity;
string message;
// Optional structured fields
string protocol_fields[string]; // {"addr":"0x100","len":"4"}
string tags[$]; // ["protocol-error","recovery"]
function new(string name = "log_record");
super.new(name);
endfunction
endclass
class silicondv_report_server extends uvm_default_report_server;
protected int unsigned m_json_fd;
protected static string m_run_uuid;
function new(string name = "silicondv_report_server");
super.new(name);
m_json_fd = $fopen("regression.jsonl", "w");
if (m_run_uuid == "")
m_run_uuid = $sformatf("%0t-%0d", $time, $urandom());
endfunction
// Override the central emission hook
virtual function string compose_report_message(
uvm_report_message report_message,
string report_object_name = "");
string human_line, json_line;
human_line = super.compose_report_message(report_message,
report_object_name);
json_line = $sformatf(
"{\"run\":\"%s\",\"ts\":%0d,\"sev\":\"%s\",\"id\":\"%s\",\"comp\":\"%s\",\"msg\":\"%s\"}",
m_run_uuid,
$time,
severity_to_str(report_message.get_severity()),
report_message.get_id(),
report_object_name,
escape_json(report_message.get_message()));
$fwrite(m_json_fd, "%s\n", json_line);
return human_line; // unchanged for terminal/log file
endfunction
protected function string severity_to_str(uvm_severity sev);
case (sev)
UVM_INFO: return "INFO";
UVM_WARNING: return "WARN";
UVM_ERROR: return "ERROR";
UVM_FATAL: return "FATAL";
default: return "UNKNOWN";
endcase
endfunction
protected function string escape_json(string s);
// Minimal escaping; extend for tabs, newlines, control chars as needed
string r = s;
foreach (r[i])
if (r[i] == "\"")
r = {r.substr(0,i-1), "\\\"", r.substr(i+1,r.len()-1)};
return r;
endfunction
endclass
// Install in top
module tb_top;
initial begin
silicondv_report_server srv = new("report_server");
uvm_report_server::set_server(srv);
run_test();
end
endmodule
From this point on, every UVM message in your testbench is emitted as both human prose and a structured JSON line. The next 10 patterns are extensions of this base.
Pattern 3-5: Identity Threading
A single failing transaction touches a sequence, a driver, the DUT, a monitor, and a scoreboard. By default each component logs independently, with no way to correlate. The fix is a transaction UUID threaded through every component that handles the transaction.
Pattern 3: UUID per uvm_sequence_item. Generate it once, in pre_randomize(), and carry it with the transaction.
class axi_txn extends uvm_sequence_item;
rand bit [31:0] addr;
rand bit [7:0] data[];
string txn_id; // <-- threaded UUID
string parent_txn_id; // parent burst, parent packet, etc.
function void pre_randomize();
super.pre_randomize();
if (txn_id == "")
txn_id = $sformatf("%0t-%0d", $time, $urandom());
endfunction
`uvm_object_utils_begin(axi_txn)
`uvm_field_int(addr, UVM_ALL_ON)
`uvm_field_string(txn_id, UVM_ALL_ON)
`uvm_field_string(parent_txn_id, UVM_ALL_ON)
`uvm_object_utils_end
endclass
Pattern 4: Parent-child linking. When a high-level transaction expands into low-level beats (AXI burst → individual transfers, PCIe TLP → byte-level packets), copy the parent txn_id into the child's parent_txn_id. Now you can reconstruct any hierarchical operation with a single query.
Pattern 5: Sequence stack. When an error fires inside seq_a which was started by seq_b which was started by virtual sequence vseq_c, the log should carry that stack. UVM's get_sequencer().get_arbitration_sequence_q() can supply the active queue; emit it as a structured seq_stack array.
The payoff: a single jq 'select(.txn_id == "uuid-abc")' reconstructs the full lifecycle of any transaction across every component, with sequence-stack context attached.
Pattern 6-8: Domain Context
Generic logs are not enough for real DUTs. A bug that only happens in D3 power state at Gen3 link speeds on clock domain B needs that context attached to every relevant event — not buried in prose.
Pattern 6: Protocol-aware fields. Extend the base log record with protocol-specific structured fields. Do not dump them into a free-text message:
class axi_log_record extends silicondv_log_record;
bit [31:0] addr;
bit [7:0] awid;
bit [3:0] awlen;
string burst_type; // FIXED / INCR / WRAP
// Serialize as structured JSON fields, not embedded strings
virtual function string to_json_fields();
return $sformatf(
",\"addr\":\"0x%0h\",\"awid\":%0d,\"awlen\":%0d,\"burst\":\"%s\"",
addr, awid, awlen, burst_type);
endfunction
endclass
Pattern 7: Power state. Every log line should carry the current power state (D0/D1/D2/D3, voltage rail, current frequency). Most teams put this in uvm_info prose; promoting it to a structured field makes "all failures in D3 at 800 MHz" a one-line query.
Pattern 8: Clock domain ID. Multi-clock designs benefit enormously from a clk_domain field. Errors that cluster by clock domain reveal CDC bugs that are otherwise invisible in flat logs.
Implementation pattern: maintain a singleton log_context object that components update on state transitions. The report server reads the current context on every emission and merges it into the JSON.
Pattern 9: The Context-Window Ring Buffer
This is the single highest-value pattern in this post. The problem: you want UVM_DEBUG-level detail at the point of failure, but you cannot afford UVM_DEBUG verbosity for the entire run. Disk fills, simulation slows, signal-to-noise collapses.
The solution, borrowed from SWE observability (Sentry breadcrumbs, Honeycomb context capture): keep the last N events in a ring buffer, suppress them from disk output, and on UVM_ERROR or UVM_FATAL, flush the entire buffer.
flowchart LR
A[INFO event] --> B{Severity?}
B -- INFO --> C[Push to ring
DEPTH=1500]
B -- ERROR/FATAL --> D[Flush buffer
+ emit current]
C --> E[(suppressed)]
D --> F[JSONL output]
class log_ring_buffer #(int DEPTH = 1500);
protected string m_buf[$];
function void push(string json_line);
m_buf.push_back(json_line);
if (m_buf.size() > DEPTH) void'(m_buf.pop_front());
endfunction
function void flush(int fd);
foreach (m_buf[i]) $fwrite(fd, "%s\n", m_buf[i]);
m_buf.delete();
endfunction
endclass
class silicondv_report_server extends uvm_default_report_server;
log_ring_buffer #(.DEPTH(1500)) m_ring = new();
int m_json_fd;
virtual function string compose_report_message(
uvm_report_message rm, string obj = "");
string json_line = build_json(rm, obj);
if (rm.get_severity() inside {UVM_ERROR, UVM_FATAL}) begin
// Flush 1500 events of pre-failure context, then current
m_ring.flush(m_json_fd);
$fwrite(m_json_fd, "%s\n", json_line);
end else if (rm.get_severity() == UVM_INFO) begin
// Buffer INFO; emit higher severities directly
m_ring.push(json_line);
end
return super.compose_report_message(rm, obj);
endfunction
endclass
Result: 95% of the run produces nothing on the JSONL output. On the rare error, you get 1,500 events of pre-failure context — every transaction, every state change, every assertion — all dumped at once. UVM_DEBUG-level forensics at UVM_LOW-level disk cost.
Pattern 10: Coverage Integration
Functional coverage is the verification team's ground truth for "what did we test." But the linkage between coverage and logs is usually broken — you know a covergroup hit bin 47, but not which test, seed, or transaction triggered it.
The fix is small: auto-emit a structured log on every covergroup sample, with the bin name and value attached. Hook into the same code path that calls sample():
// In your covergroup wrapper class
function void sample_with_log(input axi_txn txn);
cg.sample();
log_event(.event_id("COVERAGE_HIT"),
.txn_id(txn.txn_id),
.fields($sformatf(
"\"cg\":\"axi_cg\",\"sample_addr\":\"0x%0h\"",
txn.addr)));
endfunction
Now "which test hit covergroup bin X?" is a jq query. "What configurations have we never hit?" is the inverse query against the coverage database. Sign-off readiness becomes inspectable.
Pattern 11: The Run Header
Agans's Rule 2 — Make It Fail — requires that any bug be reproducible. The run header is the structured artifact that makes reproduction trivial: a single log event emitted at start_of_simulation_phase containing everything needed to reproduce.
function void start_of_simulation_phase(uvm_phase phase);
super.start_of_simulation_phase(phase);
log_event(.event_id("RUN_HEADER"), .severity("INFO"),
.fields($sformatf(
"\"seed\":%0d,\"tool_version\":\"%s\",\"rtl_hash\":\"%s\",\"tb_hash\":\"%s\",\"plusargs\":\"%s\"",
$get_initial_random_seed(),
`SIMULATOR_VERSION,
`RTL_GIT_HASH,
`TB_GIT_HASH,
get_plusargs_dump())));
endfunction
This single event is the entire "make it fail" replay artifact. Combined with seed-stamped log lines (Pattern 15 in the appendix), reproducing any failure becomes a one-liner.
Pattern 12: Failure Fingerprints
Sentry, Rollbar, and Bugsnag pioneered the idea that errors should be grouped automatically by a stable hash. The same principle works for verification: emit a fingerprint with every error, derived from the failing assertion ID, the last sequence kind, and a DUT state signature. Errors that share a fingerprint are duplicates.
function string compute_fingerprint(uvm_report_message rm, string last_seq_kind);
// Stable across re-runs; identifies the failure shape, not the run instance
return $sformatf("%s|%s|%s",
rm.get_id(),
last_seq_kind,
get_dut_state_signature());
endfunction
With this field in every error JSON, your triage script collapses 10,234 failures into roughly a dozen unique fingerprints. The same algorithm that takes hours of human deduplication takes seconds:
jq -r 'select(.sev=="ERROR") | .fingerprint' regression/*.jsonl \
| sort | uniq -c | sort -rn
Sample output:
4127 AXI_BURST_ERROR|axi_burst_seq|state_idle_to_active
2891 PCIE_TLP_TIMEOUT|pcie_mem_rd_seq|state_l0
1450 SCB_MISMATCH|axi_mixed_seq|state_active
823 RAL_PREDICT_FAIL|reg_access_seq|state_idle
...
You went from "10,234 failures, unknown structure" to "12 buckets, ranked by frequency" in one command.
16 More Patterns (for future posts)
This post covered the dozen that move the needle most. The catalog continues:
- Severity-stratified files — split
errors.jsonl,warnings.jsonl,info.jsonlfor fast CI gating. - Versioned schema field — backward compatibility when the log shape evolves.
- Seed in every log line — not just the run header, so any cut log is still reproducible.
- Pre/post state-diff snapshots — emit before/after register state on key events.
- SVA-triggered structured events — bind SVA fires to log emissions with triggering signal values.
- Latency histograms per transaction type — emit summary events every N transactions.
- Stall reason codes — structured cause tracking for every backpressure event.
- Hierarchical log namespacing —
soc.cpu.l1cache.missfor SoC bring-up. - Per-IP verbosity control — debug one IP at HIGH while others stay LOW.
- Plusarg log filters —
+log_filter=axi,!pciefor surgical noise reduction. - NDJSON streaming output — one event per line; ideal for
tail -f+jqpipelines. - SQLite-loadable schema — run SQL across an entire regression's logs.
- OpenTelemetry export — feed protocol traces into Jaeger or Tempo.
- Verdi / DVE TCL commands embedded — one-click jump from log line to waveform.
- DPI-C bridges to Python logging — live tail of testbench events in your SWE tooling.
- Pre-built LLM debug bundles — token-budget-aware extraction for GenAI debug.
Each of these will get its own deep-dive post — see the Debug page for the full methodology map.
Putting It Together
You can adopt structured logging incrementally. The order that maximizes payoff per hour of effort:
- Day 1: Install the JSON-emitting
uvm_report_server(Pattern 1). Zero changes to test code; you get a parallel JSONL file alongside every run. - Day 2: Add UUID stamping to your sequence item base class (Pattern 3). All transactions are now correlatable.
- Week 1: Emit a run header (Pattern 11). Every failure is now reproducible from a single log event.
- Week 2: Add the context-window ring buffer (Pattern 9). The single highest-value debug capability in this post.
- Week 4: Implement failure fingerprinting (Pattern 12). Regression triage stops being a person-week and starts being a script.
Each step compounds with the others. By the end of the month, your testbench logs are queryable, your transactions are traceable, your failures are deduplicated, and your debug context is automatic. Every later technique on the Debug page — Delta Debugging, GenAI context bundles, AI-assisted similar-bug retrieval — builds on this foundation.
Structured logging is not a tool. It is the discipline that makes every other debug technique possible.
Comments (0)
Leave a Comment