The Observability Triad for UVM: Logs, Metrics, and Traces Your Testbench Already Emits
The Structured Logging post turned the testbench log from prose into a queryable JSONL stream — one signal, made sharp. But a log is only one of three kinds of evidence your testbench produces on every run. Software engineering names the full set the observability triad: logs, metrics, and traces. Your UVM environment already computes all three — it counts transactions, it tracks queue depths, it threads items from sequencer to scoreboard. It just never writes two of them down. This post maps the triad onto the testbench you already have, teaches the debug motion that uses all three signals together, and builds the missing piece: a metrics collector that turns numbers you print once into curves you can query.
- The Problem: One-Signal Debugging
- The Triad: Three Signals from the SRE Canon
- The Mapping: What Each Signal Already Is in UVM
- The Pivot: How the Three Work Together
- Build Your Own: The Metrics Collector
- Querying the Signals
- Quick Reference
The Problem: One-Signal Debugging
The regression test dies at the six-hour wall-clock limit. The last line of a 400 MB log reads UVM_ERROR ... [WATCHDOG] test timeout, and it tells you nothing except that the simulation was still alive and getting nowhere when the clock ran out. It is 2 AM, the nightly is red, and the debug session begins the only way it can: grep -n ERROR run.log to find where the wheels came off, then tail -100000 run.log | less, reading backward from the corpse. Every DV engineer knows this loop. You scroll up through tens of thousands of lines looking for the moment the run turned, reconstructing a six-hour story from the one page of it that happened to print near the end.
Here is what stings about that loop: the testbench was never short on evidence. It counted every transaction that crossed every interface. It watched the depth of every scoreboard queue, every sequencer arbitration queue, every analysis FIFO. It timed every request from launch to completion. Three different kinds of evidence — how much, how deep, how long — were computed continuously, on every clock, for the entire six hours. And exactly one of them was ever written down. That one was prose: UVM_INFO, UVM_ERROR, a human sentence at a time, the weakest and least structured signal the run produced. The numbers that would actually locate the failure were calculated and thrown away.
So the log sits in front of you at 2 AM, and the questions that matter are precisely the ones it cannot answer:
- Was throughput already sagging in the minutes before the watchdog fired, or did the whole world stop at once? A gradual slope and a cliff are different bugs — one is backpressure, the other is a deadlock — and the log flattens both into the same silence.
- When did a scoreboard queue start growing without draining, and which queue? A depth that climbs and never recovers is the fingerprint of a dropped completion, but a depth is a number over time, and the log kept no number and no time.
- Did this run diverge from the fifty that passed before the failure signature ever appeared? For hours this run was statistically indistinguishable from the passing population — then it was not; the log gives you the moment of death but not the moment of departure.
- Where did the six hours actually go — which phase, which interface, which
wait? Wall-clock vanished into some blocking call that never returned, and a flat stream of timestamped sentences will not tell you which one held the whole test hostage.
Read those four again and notice what they have in common: not one is a question about messages. Every one asks about a quantity over time — a rate, a depth, a divergence, a duration — or about the path a single transaction took through the environment. Those are metric questions and trace questions, and you are trying to answer them by grepping a log because the log is the only artifact the run left behind. It is the wrong instrument, aimed at the wrong signal, and no amount of grep skill fixes an instrument that never recorded the measurement.
And every one of those numbers was computed during the run. Throughput was implicit in the transaction count the monitor already kept. Queue depth was a field the scoreboard read on every push and pop. Per-request latency was a subtraction the driver could have done in its sleep. The values existed, live, in the testbench's own memory — and then the objects were garbage-collected and the values went with them. Nothing was missing at runtime. Everything was missing at debug time, because nothing was persisted.
The fix, then, is not a sharper grep and not a bigger tail. It is not even a better logging macro. The fix is to stop discarding two-thirds of the evidence — to collect the other two signals and write them down beside the log, in a form you can query after the run is dead. Software engineering has a name for the discipline of keeping all three, and a well-worn theory of what each one is for. That is where we go next.
The Triad: Three Signals from the SRE Canon
The discipline is observability, rooted in Google's Site Reliability Engineering book and named as three signals — the "three pillars" — by the observability community that built on it. Map them straight onto a testbench and the abstraction stops being abstract.
Logs are discrete, timestamped events — high detail, high volume, one line per thing that happened. They answer what happened here: this transaction, on this interface, at this nanosecond, carried this payload. Your UVM_INFO stream is already this signal, and the Structured Logging post already sharpened it.
Metrics are numeric time series — a name, a value, a timestamp, repeated on a cadence. They are cheap to store and trivial to compare across runs, and they answer how is it trending: is throughput sagging, is that queue growing, is p99 latency drifting from last night's. A metric is the number the log threw away.
Traces are causally linked event chains that share an ID — the story of one transaction as it moves through the environment. They answer where did this request go and where did it stall: sequencer to driver to DUT to monitor to scoreboard, with a timestamp at every hop, so a six-hour disappearance resolves into the one edge that took six hours.
Metrics carry more structure than a bare number, and the Prometheus type system is the vocabulary for it — because the type dictates the query. A counter is monotonically increasing; you never read it raw, you query its rate — transactions issued per microsecond is the derivative of a counter that only ever climbs. A gauge is an instantaneous level that moves both ways; you plot it as-is, because scoreboard queue depth right now is the answer. A histogram buckets a distribution; you query its percentiles, because per-transaction latency is meaningless as a mean and everything as a p50 and p99. Counters get deltas, gauges get raw plots, histograms get percentiles — pick the wrong type and the right query becomes impossible.
Which numbers do you actually collect? Two methodologies answer that, and both return in the next section's inventory. Tom Wilkie's RED method covers every request stream: Rate (how many requests per second), Errors (how many failed), Duration (the latency distribution). Point RED at a UVM interface and it becomes transactions issued, mismatches flagged, and completion latency — a counter, a counter, and a histogram, one of each.
Brendan Gregg's USE method covers every resource instead: Utilization (how busy), Saturation (how much queued work is waiting), Errors. Point USE at a scoreboard or a sequencer arbiter and it becomes occupancy, queue depth, and dropped items — gauge, gauge, counter. RED watches the flow; USE watches the thing the flow runs through, and between them they name most of what a testbench should measure.
One honest caveat, from Honeycomb's Charity Majors: the "three pillars" framing oversells the split. Logs, metrics, and traces are storage formats, not three separate kinds of truth — a single stream of wide, richly attributed events can derive all three, and treating them as three siloed backends is how you end up unable to pivot from one to another mid-debug. That critique lands even harder in DV, and in our favor. Simulation is deterministic and closed-world, and the JSONL sidecar from the Structured Logging post is already that single wide-event stream — one file, every record tagged. We are not building three backends. This post teaches three lenses on the one stream you already have.
The Mapping: What Each Signal Already Is in UVM
The theory is portable, but the payoff is specific: point each of the three signals at a UVM testbench and it lands on something already running. You are not bolting observability onto your environment. You are naming machinery that is already there and writing down two-thirds of what it produces. Here is the whole mapping on one page — the SWE incarnation, where it already lives in your testbench, and the one thing still missing.
| Signal | SWE incarnation | Already in your testbench | The missing piece |
|---|---|---|---|
| Logs | stdout, Splunk, ELK | uvm_report_server, `uvm_info | Structure — solved in the Structured Logging post |
| Metrics | Prometheus, Datadog | Coverage %, scoreboard depths, txn counters, sim-rate | Nobody samples them over time — built below |
| Traces | OpenTelemetry, Jaeger | seq_item lifecycle: sequencer → driver → monitor → scoreboard | A propagated ID — the next post |
Read the table top to bottom and the shape of the post appears: one row is done, one row is built below, one row is teased. Take them in order.
Logs — already sharp
Logs are the row with no work left. The Structured Logging post already took the uvm_report_server stream — the same `uvm_info/`uvm_error messages you have written a thousand times — and turned it from prose into a JSONL sidecar: one JSON object per event, written to a file beside the run. The contract is five fixed fields on every record — run to name the run, ts for the simulation timestamp in nanoseconds, sev for severity, id for the report ID, and comp for the full component path — plus a msg string and whatever domain fields the event carries (an address, a transaction id, a burst length). That is the entire log signal, already structured, already queryable, already shipping. Nothing in this post revisits how to produce it; the depth lives in that post and this section defers to it wholesale.
What this post adds is the other two signals, and it writes them to that same file. A metric is not a new sidecar or a second backend — it is another line in the JSONL stream, distinguished by a single kind field. A metric record carries kind set to metric; a log record carries no kind at all, so the absence of the field is the tag that says "this is a log." One file, two record types, one query surface. That decision — one wide-event stream, not three siloed stores — is exactly the Honeycomb critique from the last section, honored by construction. The log row is closed; the metrics row is where the code starts.
Metrics — the numbers you already print once
Metrics are the meat of the mapping, because this is the signal your testbench computes most eagerly and persists least. The two methodologies from the last section tell you precisely which numbers to keep, and they partition the testbench cleanly: RED treats every interface agent as a service carrying a request stream, and USE treats every testbench structure as a resource that stream flows through.
Point RED at an interface agent. Rate is the transaction count the monitor already increments on every completed item — a counter, queried as issued-per-microsecond. Errors is the scoreboard's mismatch count, the counter that matters most because a single nonzero increment is a failing run — the error signal, already tallied on every compare. Duration is per-transaction latency from launch to completion, a histogram, and it is the leading indicator: latency starts drifting in the buckets long before the throughput counter visibly sags, so the duration signal warns you a run is sick while the rate signal still looks healthy. Rate, errors, duration — a counter, a counter, a histogram, one per interface, all three already living in fields the agent updates every clock.
Point USE at a structure. Utilization is sequencer occupancy — the fraction of time the arbiter is handing out items rather than idle — a gauge. Saturation is queue depth: the scoreboard's pending-compare queue, the analysis FIFO, the response queue, read on every push and pop. That gauge is the one that predicts death — a depth that climbs and never drains is the fingerprint of a dropped completion, visible as a rising curve minutes before the watchdog fires. Errors is the uvm_error count, the same tally the report server keeps. Occupancy, depth, error count — gauge, gauge, counter, one set per resource.
Two more numbers belong to the run as a whole rather than to any single interface or structure. Functional coverage — $get_coverage(), or per-covergroup get_coverage() — is a gauge climbing toward 100, the metric that says whether the run is doing new work or spinning. And sim-rate, the ratio of Δsim-time to Δwall-clock, paired with the monitor's txn-rate counter, is what tells apart two failures a log renders identically. The clock generator does not know or care that the DUT is stuck, so a protocol-level hang leaves sim-rate normal — clocks toggling, sim-time advancing — while the txn-rate counter goes flat, nothing completing. A collapsed sim-rate is a different animal: the simulator itself is struggling — an X-storm, runaway event activity, host memory thrashing — and the DUT is incidental to it. Neither is visible from the message stream; both are one subtraction away from numbers the run already has.
Here is the observation the whole section turns on. Every metric named above — every rate, depth, occupancy, latency, coverage percentage — already exists in your testbench today, as an instantaneous value printed exactly once, in the final report, in the report_phase, as the run winds down. Your scoreboard already prints "12,481 transactions compared, 0 mismatches, max queue depth 34." A metric is that identical number, sampled on an interval instead of totalled at the end. The difference between "prints a total when it dies" and "emits a curve you can replay" is not new measurement — the measurement is done — it is a sampling loop and a writer, roughly 150 lines, built in Build Your Own: The Metrics Collector further down. The values are already in memory. The only missing act is writing them down on a cadence.
Traces — the chain that already exists
Traces are the row this post only teases, because the causal chain is already there in your environment, just implicit. A seq_item is born in the sequence, arbitrated by the sequencer, driven onto the bus by the driver, observed by the monitor, and compared in the scoreboard — sequencer → driver → monitor → scoreboard, a fixed lifecycle every transaction walks. That path is a trace in everything but name. What it lacks is a single propagated ID that survives every hop, so that all the records belonging to one transaction can be pulled out of the stream and laid end to end. The Structured Logging post already threads a txn_id field through its records for exactly this reason; a trace is what you get when that id becomes the spine of a query.
Give the chain a propagated ID and the six-hour-disappearance question from the top of the post becomes answerable directly: follow one transaction across all four components, measure the wall-clock or sim-time spent on each hop, and the one edge that swallowed the run resolves out of the noise. That is latency-per-hop, causally attributed, no grepping required. Building it — the ID scheme, the propagation through the sequence layering, the span-per-hop model — is more than a subsection can hold. Trace IDs and Context Propagation gets its own post; it is the next card in the Foundations row. For now the mapping is enough: the trace, like the metric, is a signal your testbench already emits and simply never writes down.
The Pivot: How the Three Work Together
The three signals are not three dashboards you check in parallel — they are one motion you run in sequence, a loop that walks a metric anomaly down to a root cause: a curve bends, that names a time window; the window plus a txn_id grep names the actor that stalled; the actor's log slice names what it said when it stalled; and if the root cause is not yet in hand, the new fact points you back at a different curve. Software engineers run this loop every time a pager goes off — dashboard to trace to log, narrowing at every hop — and the mapping in the last section is what makes it run on a testbench. Each signal answers a question the previous one could not, and hands the next one a filter.
flowchart LR
M["📈 METRICS
which curve bent, and when?"] -->|"narrows to a time window"| T["🔗 TRACES
which transaction stalled, where?"]
T -->|"identifies the actor"| L["📋 LOGS
what exactly did it say?"]
L -->|"new hypothesis"| M
Watch it work on a real failure — a response-starvation hang, the kind that grep renders as six hours of silence and one dying gasp. Here is what the three signals recorded, laid on a single timeline:
| Sim time | Signal | Evidence |
|---|---|---|
| 28 µs | histogram | p99 response latency starts creeping: 180 ns → 900 ns |
| 32 µs | gauge | scoreboard expected-queue depth begins monotonic growth |
| 36 µs | counter | txn completion rate flatlines at zero |
| 40 µs | log | [WATCHDOG] test timeout — the only line grep would have found |
Read the first column and the whole argument of this post is in the gap between the top row and the bottom one. The failure began at 28 µs. The symptom — the only line the log ever wrote — landed at 40 µs. Twelve microseconds separate the moment the run turned from the moment it announced it turned, and in a message-only workflow those twelve microseconds do not exist. Grep-from-the-end starts at 40 µs, at the watchdog line, and reads backward through prose that was written while everything already looked fine on the surface, hunting for a transition that left no distinctive sentence because the failure was numeric, not textual. That is the search that takes hours: you are reconstructing a slope from a stream that only ever recorded events, scrolling up through thousands of UVM_INFO lines that each say a normal thing happened.
The metrics reader starts somewhere else entirely. The p99 latency histogram — the leading indicator from the mapping, the signal that drifts in the buckets before the rate counter visibly sags — bent at 28 µs, and it bent on the response path specifically. So before opening a single log line, the reader has two things grep never gives you: a named suspect, the response stream, and a bounded window, roughly 28 to 40 µs. The saturation gauge confirms and localizes it — the scoreboard's expected-queue depth starts its monotonic climb at 32 µs, the fingerprint of completions that are launched and never returned, and it names the scoreboard partner as the structure filling up. Two queries in, the shape of the bug is already "the responder stopped feeding the scoreboard," and the window has tightened to six microseconds.
Now the pivot. The metrics have named the where and the when; they cannot say why, because a curve is a shape and not a sentence. So you cross from the metric stream to the log stream through the one field that spans both — the timestamp — and slice the JSONL sidecar to exactly the window the curves drew:
jq 'select(.kind != "metric" and .ts > 30000 and .ts < 36000)' run.sidecar.jsonl # ts is in ns — this is the 30–36 µs window
That is not six hours of log. It is the ~20 lines that fall inside the bent window, and read in order they tell the story the watchdog line could not: the request stream keeps going — req after req issued, monitored, accepted, the outbound side perfectly healthy — while the response stream thins, one returned completion, then a longer gap, then another, then nothing. Requests in, responses trailing off to zero, the scoreboard queue swelling behind them. Twenty lines, read once, and the mechanism is plain: the responder model has stopped producing responses while the driver keeps issuing requests. One more look at the responder's own log lines in that slice and the cause is explicit — its available-credit count reached zero and never recovered. A credit leak in the responder model: it decremented on each request but missed the return path on some completion, bled its credits to nothing, and stalled. The DUT was fine. The testbench starved itself.
Count the work. Same bug, two workflows. Log-only: open a 400 MB file at its tail, grep for the error, then read backward for an hour or more reconstructing a numeric failure from a textual record that never named it, guessing at the window because nothing marks it. Triad: one histogram query names the suspect and the window, one gauge query names the partner and confirms the mechanism, one jq slice reads the twenty lines that explain it. Three queries against one file, a few minutes, and the pivot from which curve bent to what exactly did it say is a single shared ts. The evidence was always there; the difference is that two-thirds of it got written down, and that the writing-down turns a backward scroll into a forward filter.
This is Dave Agans' third rule of debugging, "Quit Thinking and Look," with instruments instead of vibes. Agans' warning is that engineers burn hours theorizing about what might be wrong instead of observing what is wrong — and the honest reason DV engineers theorize is that looking used to mean scrolling a log, which is slow and rarely conclusive, so guessing felt faster. The triad closes that gap. Looking is now three cheap queries that converge on a six-microsecond window, and only then do you open the waveform. The waveform is still the ground truth — that is where a DV debug ends — but a waveform is six hours wide and you cannot stare at all of it. The triad's entire job is to tell you which six microseconds to open. Metrics say when, traces say which transaction, logs say what it said, and the viewer, aimed at last, says why in silicon.
Build Your Own: The Metrics Collector
The mapping section promised the missing piece was small — a sampling loop and a writer, roughly 150 lines, standing between "prints a total when it dies" and "emits a curve you can replay." Here it is, and the line count holds. But the size is the least interesting thing about it. What matters is that the design obeys three rules borrowed straight from the software side of the house, and every one of them is load-bearing. The collector must be passive: it reads the testbench, it never steers it — read-only, zero-time, no objections raised, and critically no RNG touches, because a stray $urandom inside a probe perturbs the calling thread's random state and silently breaks seed-stability of the very run you are trying to observe — read-only with respect to the testbench; a probe may keep its own bookkeeping, a delta baseline or a histogram window, but never touches the object it observes. It must be pluggable: adding a fifth metric is one new class and zero edits to the collector, or the abstraction has failed. And it must be composable: every sample lands in the same JSONL sidecar as the log records from the Structured Logging post, one wide-event stream, with the kind field doing the discrimination. Passivity keeps the instrument from changing the experiment; pluggability keeps the instrument from rotting; composability keeps you on one query surface. Hold those three in mind — every design decision below is one of them, made concrete.
Start with the contract. The whole design inverts a dependency: the collector must not know what a throughput counter or a latency histogram is, only that it can be asked its name, its type, and its current value. SystemVerilog expresses that with an interface class — a pure interface, no implementation, no state — which is the language's answer to dependency inversion.
// The contract every metric source signs. `interface class` = a pure
// interface with no implementation — SV's answer to dependency inversion.
interface class metrics_probe;
pure virtual function string name(); // e.g. "axi_wr_throughput"
pure virtual function string mtype(); // "counter" | "gauge" | "histogram"
pure virtual function string sample_json(); // value as a JSON fragment; MUST NOT touch testbench state
endclass
Three methods, and the third does the real work. sample_json() returns a JSON fragment, not a fixed scalar, and that is deliberate: a gauge can hand back "14" while a histogram hands back "{\"p50\":40,\"p95\":180,\"p99\":900,\"n\":512}", and the collector splices either one into the record without caring which it got. One contract, three metric types, no if (counter) ... else if (histogram) anywhere in the collector. If the phrase "every source signs a contract and the collector iterates over the signatories" sounds familiar, it should — this is the Observer pattern from the patterns series, where the subject holds a list of observers it knows only through their interface. The collector is the subject; the probes are the observers; the interface class is the abstraction that lets the two sides evolve independently.
Now the subject itself.
class tb_metrics_collector extends uvm_component;
`uvm_component_utils(tb_metrics_collector)
protected metrics_probe m_probes[$];
protected time m_interval = 1us; // override: +metrics_interval_ns=<n>
protected int m_fd;
protected string m_run_id;
function new(string name, uvm_component parent);
super.new(name, parent);
endfunction
function void build_phase(uvm_phase phase);
int unsigned iv_ns;
if ($value$plusargs("metrics_interval_ns=%d", iv_ns)) m_interval = iv_ns * 1ns;
if (!uvm_config_db#(string)::get(this, "", "run_id", m_run_id)) m_run_id = "0";
m_fd = $fopen({get_full_name(), ".metrics.jsonl"}, "a");
endfunction
function void register_probe(metrics_probe p);
m_probes.push_back(p);
endfunction
// Passive: no objection raised. The test ends when the test ends;
// the collector just stops being scheduled.
task run_phase(uvm_phase phase);
forever begin
#(m_interval);
sample_all();
end
endtask
protected function void sample_all();
foreach (m_probes[i])
$fdisplay(m_fd, $sformatf(
"{\"run\":\"%s\",\"ts\":%0d,\"kind\":\"metric\",\"name\":\"%s\",\"mtype\":\"%s\",\"value\":%s}",
m_run_id, $time, m_probes[i].name(), m_probes[i].mtype(),
m_probes[i].sample_json()));
$fflush(m_fd);
endfunction
// extract_phase is the phase DESIGNED for pulling data out of the
// testbench — the last complete sample lands even on a clean finish.
function void extract_phase(uvm_phase phase);
sample_all();
$fflush(m_fd);
endfunction
// Every sample is flushed as it lands (sample_all), so a $fatal or a grid
// kill still leaves the last complete window on disk. final_phase just
// closes the handle on a normal shutdown.
function void final_phase(uvm_phase phase);
$fclose(m_fd);
endfunction
endclass
A few things earn their place. The interval is not hardcoded: build_phase reads +metrics_interval_ns=<n> off the command line and falls back to the config_db run_id so the record can be correlated across runs — sample cadence is a run-time knob, not a recompile. The file opens in append mode ("a"), which is what lets these metric lines coexist with log lines in one growing stream. In the format string, note %0d on $time rather than a stringified timestamp: it keeps the ts field a bare JSON number, so jq 'select(.ts > 30000)' — the exact query from the pivot section — compares numerically instead of choking on quotes. And look hard at run_phase: it raises no objection. That single absence is the passivity rule written in code. An objection would keep the test alive to finish sampling, which means the instrument would be extending the experiment — precisely the sin the passive rule forbids. Instead the collector rides extract_phase, the UVM phase designed for pulling data out of the testbench, so the last complete sample lands even on a clean finish, and because sample_all flushes every sample as it lands, even a $fatal or a wall-clock kill — deaths no UVM phase ever sees — still leaves the last complete window on disk; final_phase merely closes the handle on a normal shutdown. The test ends when the test ends; the collector just stops being scheduled. One last note for a single-sidecar setup: swap the $fopen for a handle shared with the report server from the Structured Logging post, and the metric lines and log lines pour into the identical stream — same file, kind discriminates.
That is the whole engine. Everything from here is a probe, and each probe is one small class that signs the contract. First, a counter — per-agent write throughput, delta-sampled.
// Counter: the monitor's analysis port increments; the collector's sample
// reads the delta since last sample. Rate = delta / interval.
class axi_throughput_probe extends uvm_subscriber #(axi_txn) implements metrics_probe;
`uvm_component_utils(axi_throughput_probe)
protected int unsigned m_count, m_last;
function new(string name, uvm_component parent);
super.new(name, parent);
endfunction
function void write(axi_txn t);
m_count++; // hot path: one increment, nothing else
endfunction
virtual function string name(); return "axi_wr_throughput"; endfunction
virtual function string mtype(); return "counter"; endfunction
virtual function string sample_json();
int unsigned delta = m_count - m_last;
m_last = m_count;
return $sformatf("%0d", delta);
endfunction
endclass
The probe subscribes to the monitor's analysis port and its write does exactly one thing on the hot path — increment — because a subscriber that does real work per transaction taxes every run whether or not anyone reads the metric. The type discipline from the theory section shows up here: a counter is never emitted raw, so sample_json() returns the delta since the last sample and stashes the new baseline, handing the querier a per-interval count it can divide into a rate. One subtlety worth calling out for anyone reaching for their linter: metrics_probe::name() does not collide with uvm_object::get_name(). The contract method was named name() precisely so it sits alongside the UVM identity method rather than overriding it — the probe answers to both, and they mean different things.
Now a gauge, and here the implements keyword shows its power. The scoreboard does not need a separate probe object watching it from outside; the scoreboard is the probe. It already knows its own queue depth, so it signs the contract directly.
// Gauge: the scoreboard IS the probe. SV's `implements` keyword lets a
// component sign the metrics contract without inheriting anything new.
class axi_scoreboard extends uvm_scoreboard implements metrics_probe;
`uvm_component_utils(axi_scoreboard)
protected axi_txn m_expected[$];
// ... normal scoreboard duties elided ...
virtual function string name(); return "sb_depth"; endfunction
virtual function string mtype(); return "gauge"; endfunction
virtual function string sample_json();
return $sformatf("%0d", m_expected.size()); // read-only: .size(), no pop
endfunction
endclass
A gauge is an instantaneous level, so sample_json() just reports m_expected.size() as-is — no delta, no reset. And note what it does not do: it calls .size(), never .pop_front(). Reading the depth must not consume the queue, or the instrument would be altering the thing it measures. This is the same saturation gauge that climbed at 32 µs in the pivot timeline — the fingerprint of completions launched and never returned — now emitted on a cadence instead of printed once as "max queue depth 34."
The third type is the histogram, and it is the one the pivot section leaned on hardest.
// Histogram: monitors report request->response latency; the probe sorts
// the current window at sample time and emits percentiles, then resets.
class axi_latency_probe extends uvm_subscriber #(axi_txn) implements metrics_probe;
`uvm_component_utils(axi_latency_probe)
protected time m_window[$];
function new(string name, uvm_component parent);
super.new(name, parent);
endfunction
function void write(axi_txn t);
m_window.push_back(t.rsp_time - t.req_time);
endfunction
virtual function string name(); return "axi_rd_latency"; endfunction
virtual function string mtype(); return "histogram"; endfunction
virtual function string sample_json();
time sorted[$] = m_window; string s;
if (sorted.size() == 0) return "{\"n\":0}";
sorted.sort();
s = $sformatf("{\"p50\":%0d,\"p95\":%0d,\"p99\":%0d,\"n\":%0d}",
sorted[(sorted.size()-1)*50/100], // (n-1)*p/100: always in range
sorted[(sorted.size()-1)*95/100],
sorted[(sorted.size()-1)*99/100],
sorted.size());
m_window.delete();
return s;
endfunction
endclass
The write path stays cheap — one subtraction pushed onto a window — and the expensive step, the sort, happens only at sample time when someone is actually going to read the number. The percentile index (n-1)*p/100 is chosen so it always lands inside the array for any non-empty window, which is why the size-zero case returns early with {"n":0}. Then the window is cleared, so each sample describes the latencies in that interval rather than the run to date. This is the leading indicator made concrete: p99 on the response path is the signal that bent at 28 µs in the pivot timeline — a full 8 µs before the throughput counter flatlined at 36. The histogram warns you a run is sick while the counter still looks healthy, and now that warning is a queryable curve.
Three metric types, three probes, and every one of them lived entirely inside the HDL. The fourth reaches for something SystemVerilog does not have. Sim-rate is Δsim-time over Δwall-clock, and the language has no wall-clock — $time is simulated nanoseconds, and $system() shells out for a status code, not a value you can read back. This is the moment to open the software toolbox and pull out DPI-C. Three lines of C give the testbench a monotonic wall clock.
// SystemVerilog has no wall-clock. $system() returns a status, not a value.
// Three lines of C fix that:
import "DPI-C" function longint tb_epoch_ms();
// tb_epoch.c — compile into the sim with your tool's DPI flow
#include <time.h>
long long tb_epoch_ms(void) {
struct timespec ts;
clock_gettime(CLOCK_MONOTONIC, &ts);
return (long long)ts.tv_sec * 1000 + ts.tv_nsec / 1000000;
}
With a wall clock imported, the probe is another gauge.
// Gauge: sim-nanoseconds advanced per wall-millisecond. Read WITH the
// txn-rate counter: txn rate flat while sim_rate stays normal = protocol
// hang (clocks still toggling, nothing completing); sim_rate collapsed =
// the simulator itself is struggling (X-storm, runaway event activity,
// host memory thrash).
class sim_rate_probe implements metrics_probe;
protected time m_last_sim;
protected longint m_last_wall;
virtual function string name(); return "sim_rate"; endfunction
virtual function string mtype(); return "gauge"; endfunction
virtual function string sample_json();
time now_sim = $time;
longint now_wall = tb_epoch_ms();
real rate = (now_wall == m_last_wall) ? 0.0
: real'(now_sim - m_last_sim) / real'(now_wall - m_last_wall);
m_last_sim = now_sim;
m_last_wall = now_wall;
return $sformatf("%.1f", rate);
endfunction
endclass
The comment carries the diagnostic payload, and it is the one from the mapping section, unchanged: read sim-rate with the txn-rate counter and the pair separates two failures a log renders identically. Txn rate flat while sim-rate stays normal is a protocol hang — clocks toggling, sim-time advancing, nothing completing. Sim-rate collapsed is a different animal — the simulator itself is struggling under an X-storm, runaway event activity, or host memory thrash, and the DUT is incidental. One more structural note: sim_rate_probe extends nothing. It is a plain class, not a uvm_component, because a probe needs only to sign the contract — the collector holds it by its metrics_probe handle and never asks it to be anything more. That is the dependency inversion paying off; the collector's list does not care what class of object it holds. And with four probes in hand, the fifth writes itself: a coverage_pct gauge — $get_coverage() wrapped in the same three-method shape — is the reader's first exercise; it is six lines.
Which leaves the wiring, and the wiring is where the whole design either earns its keep or does not.
function void tb_env::connect_phase(uvm_phase phase);
super.connect_phase(phase);
axi_agent.mon.ap.connect(m_wr_tput.analysis_export);
axi_agent.mon.ap.connect(m_rd_lat.analysis_export);
m_metrics.register_probe(m_wr_tput); // counter
m_metrics.register_probe(m_rd_lat); // histogram
m_metrics.register_probe(m_sb); // gauge — the scoreboard itself
m_metrics.register_probe(m_sim_rate); // gauge — plain class
endfunction
The subscribers hook onto the monitor's analysis port, and then all four probes register with the collector through the same one-line register_probe call — a counter, a histogram, and two gauges, one of which is the scoreboard measuring itself and one of which is a plain non-component class, handled identically because the collector sees only the contract. This is the pluggability rule collecting its debt: adding metric #5, that coverage_pct gauge, means writing one class and adding one register_probe line here — it touches zero lines inside tb_metrics_collector, because the collector was never told what any of its probes are. That is dependency inversion earning its keep, and it is why the whole collector fits in 150 lines while staying open to every metric your testbench will ever want to emit.
Querying the Signals
Everything in the pivot section ran on one query primitive: jq, pointed at the JSONL sidecar, filtering on kind and ts. The filenames below are illustrative, not prescriptive — a metrics sidecar and a log sidecar, shown here as two files. Section 5's collector writes wherever you point its $fopen: one shared stream discriminated by kind, or two files that cat concatenates into one — the queries below run unchanged either way. That is not a coincidence to gloss over — it is the entire payoff of writing one wide-event stream instead of three siloed backends. You do not need a metrics database, a trace viewer, or a query language with a learning curve. You need four one-liners, and you already have three of them memorized from the sections above. Here they are as a toolkit, each doing one job, none of them needing anything more exotic than the jq already on your workstation.
The first turns a single metric into a plottable series — pick a name, drop everything else, keep timestamp and value:
# One metric as CSV — feed to any plotter
jq -r 'select(.kind=="metric" and .name=="sb_depth") | [.ts, .value] | @csv' run.metrics.jsonl
Against the fixture built for this section — sb_depth sampled every microsecond, climbing from 32 µs — this line reads out 0,1, 1000,0, 2000,1, in order, ready for any plotter that takes CSV.
The second answers a narrower question — not the whole series, but the one instant that matters: where does the counter last read nonzero, the sample just before the flatline the pivot section built its whole case around.
# Hang window: last sample where throughput was still nonzero
jq -r 'select(.name=="axi_wr_throughput" and (.value|tonumber) > 0) | .ts' run.metrics.jsonl | tail -1
On the same fixture — throughput steady at 8 through 35 µs, zero from 36 µs on — this returns 35000: one number, ns, and it is the right edge of the window you need to slice next.
The third is the one line that reaches straight into a histogram's structure rather than a scalar, because the percentile is stored inline on every sample and needs no recomputation at query time:
# p99 latency curve — histograms carry their percentiles inline
jq -r 'select(.name=="axi_rd_latency") | [.ts, .value.p99] | @csv' run.metrics.jsonl
Run against the fixture, the p99 column sits flat at 180 through 28 µs and then climbs — 230, 280, 330 — exactly the drift the pivot's histogram query depended on, read straight off .value.p99 with no post-processing.
The fourth is the pivot itself, restated as a reusable line rather than a one-off: metrics named the window, now slice the log stream — the records with no kind field — to that same span.
# The pivot: metrics found the window, now slice the LOG stream to it
jq 'select(.kind != "metric" and .ts > 30000 and .ts < 36000)' run.sidecar.jsonl
Four lines, one file format, no new tool. Piped to a CSV, a metric series is one step from a picture, and a picture is what makes a bent curve visible at a glance instead of buried in a column of numbers. Feed two series through gnuplot and the throughput drop and the depth climb from the pivot's timeline land on one plot, one axis each:
set datafile separator ","
set y2tics
plot "tput.csv" using 1:2 with lines title "wr throughput", \
"depth.csv" using 1:2 with lines title "sb depth" axes x1y2
One PNG per failing run, generated in the regression triage script — the curve is the first debug step.
The real payoff is not one run's plot — it is fifty of them. Run the same jq → CSV pipeline over every passing run from the last week, overlay all fifty curves on the failing run's curve on one axis, same metric, same color for the passing band, one line standing out in the failing run's color. Fifty healthy throughput traces sit in a tight band; the failing run's trace rides inside that band for hours and then peels away from it, and the instant it peels away is not a guess — it is a pixel you can point at. That instant is the debug starting line. It is earlier than the watchdog line by however many microseconds the pivot section found, and it is exactly the moment worth asking "what changed here" about, because the answer to that question is the bug.
Fifty passing runs and one failing run, overlaid, is one query away — but ten thousand runs a night, with dozens of distinct failure signatures tangled together, is a different problem than eyeballing one divergent line on one plot. That is where this series goes next: the Triage category picks up from here, with an Error Fingerprinting card asking what pattern a failure leaves behind when you cannot look at each of ten thousand plots by hand. The signals are captured; querying them at that scale is the next post's problem, not this one's.
Quick Reference
Everything above compresses to one table, one checklist, and a reading list. Bookmark this section; it is the part you come back to at 2 AM instead of re-reading the whole post.
| Signal | UVM source | Collection cost | First question it answers |
|---|---|---|---|
| Logs | uvm_report_server → JSONL sidecar | Done — previous post | What exactly happened at time T? |
| Metrics (counter) | analysis-port subscriber, delta-sampled | ~20 lines/probe | Was it still making progress? |
| Metrics (gauge) | scoreboard/queue .size() via implements | ~10 lines/probe | What was filling up, and when did it start? |
| Metrics (histogram) | latency window, percentiles at sample time | ~30 lines/probe | Was it getting slower before it stopped? |
| Traces | txn_id threading (next post) | One UUID + discipline | Where did THIS transaction stall? |
Adopt the triad in the order that pays off fastest, not the order this post presented it:
- Drop in
tb_metrics_collectorwith thesim_rateprobe — zero testbench coupling, and your regression can already tell a hung DUT from a thrashing simulator. - Register scoreboard-depth (
implements metrics_probe, ~10 lines) and one per-agent throughput probe. - Add the jq → gnuplot step to the fail-triage script: every failing run gets its curves rendered before a human looks at it.
Each step stands alone — step 1 alone already answers the "is the simulator or the DUT stuck" question from the mapping section, without touching a single scoreboard or agent class.
Further reading:
- Google, Site Reliability Engineering — the chapter on monitoring distributed systems, the monitoring foundations under the three-signal framing this post maps onto UVM.
- Peter Bourgon — Metrics, Tracing, and Logging — the post that named the three pillars.
- Charity Majors (Honeycomb) — the "three pillars" critique: logs, metrics, and traces are storage formats, not separate truths.
- Brendan Gregg — the USE method (Utilization, Saturation, Errors), for naming what to measure on any resource.
- Tom Wilkie — the RED method (Rate, Errors, Duration), for naming what to measure on any request stream.
- Prometheus documentation — metric types (counter, gauge, histogram), the vocabulary this post borrows wholesale.
- OpenTelemetry — semantic conventions, the closest thing the industry has to a standard schema for traces.
- David Agans, Debugging — Rule 3, "Quit Thinking and Look," the rule the pivot section runs on.
That closes the loop this post opened. The Structured Logging post gave the testbench its first sharp signal; this one added the two it was throwing away. Next in Foundations: Trace IDs & Context Propagation — the UUID that turns your log stream into traces, and the piece this post kept teasing and deferring. Until then, everything here — logs, metrics, and the queries that connect them — lives on the Debug hub, alongside the rest of the triage toolkit this series is building one card at a time.
Comments (0)
Leave a Comment