Extracting UVM_INFO

Part II · Module 21 · Chapter 21.3 · Extracting UVM_INFO

1. The Volume Problem

use strict;
use warnings;

# verbose.log is a real Icarus run of tb/uvm_style_tb.v in its verbose mode:
# one UVM_INFO per transaction, which is what a UVM_MEDIUM log looks like.
my $LOG = "logs/verbose.log";
my $SUMMARY_COUNT = qr/^(?:#\s*)?UVM_\w+\s*:\s*\d+\s*$/;

# the UVM message layout (21.1): SEVERITY file(line) @ time: path [ID] text
my $MSG = qr/^(?:\#\s*)?(UVM_\w+)\s+(?:(\S+?)\((\d+)\)\s+)?\@\s*(\d+)\s*:\s*(\S*)\s*\[(\w+)\]\s*(.*)$/;

my (@info, %by_id, $total_lines);
open my $fh, "<", $LOG or die "$LOG: $!";
while (my $l = <$fh>) {
    $total_lines++;
    next if $l =~ $SUMMARY_COUNT;
    next unless $l =~ $MSG;
    my ($sev, $file, $line, $time, $path, $id, $text) = ($1, $2, $3, $4, $5, $6, $7);
    next unless $sev eq "UVM_INFO";
    push @info, { time => $time, id => $id, text => $text, path => $path };
    $by_id{$id}++;
}
close $fh;

printf "%s: %d lines, %d UVM_INFO messages parsed\n\n", $LOG, $total_lines, scalar @info;
printf "%-10s %s\n", "ID", "COUNT";
printf "%-10s %d\n", $_, $by_id{$_} for sort { $by_id{$b} <=> $by_id{$a} || $a cmp $b } keys %by_id;

# ---- the IDs that carry signal, as an ALLOW-LIST (data, not logic)
my %KEEP = map { $_ => 1 } qw(PHASE CFG SCBD RNTST);
my @kept = grep { $KEEP{ $_->{id} } } @info;
printf "\nfiltered to the allow-list (%s): %d of %d messages\n",
    join(",", sort keys %KEEP), scalar @kept, scalar @info;
printf "  reduction: %.1fx\n", @kept ? (scalar @info) / (scalar @kept) : 0;
printf "  @ %-8s [%-6s] %s\n", $_->{time}, $_->{id}, $_->{text} for @kept;

# ---- the alternative: keep the FIRST and LAST of every ID
my (%first, %last);
for my $m (@info) {
    $first{ $m->{id} } = $m unless exists $first{ $m->{id} };
    $last{  $m->{id} } = $m;
}
my $fl = 0;
for my $id (sort keys %first) {
    $fl += ($first{$id} == $last{$id}) ? 1 : 2;
}
printf "\nkeeping the FIRST and LAST of each ID instead: %d messages (%.1fx)\n",
    $fl, (scalar @info) / $fl;
print "  this needs no allow-list, so it survives a testbench that invents a\n";
print "  new ID -- but it keeps two lines of pure noise per noisy ID.\n";

# ---- what is NOT in the log
print "\nwhat the log does NOT contain:\n";
my $has_verbosity = 0;
open my $f2, "<", $LOG or die $!;
while (my $l = <$f2>) { $has_verbosity = 1 if $l =~ /UVM_(?:NONE|LOW|MEDIUM|HIGH|FULL|DEBUG)\b/ }
close $f2;
printf "  a VERBOSITY level on any message?  %s\n", ($has_verbosity ? "yes" : "NO");
print "  so you cannot filter by verbosity after the fact -- the level decided\n";
print "  what got PRINTED, and is not recorded in what was printed.\n";

logs/verbose.log: 149 lines, 137 UVM_INFO messages parsed

ID         COUNT
DRV        64
MON        64
SCBD       4
PHASE      3
CFG        1
RNTST      1

filtered to the allow-list (CFG,PHASE,RNTST,SCBD): 9 of 137 messages
  reduction: 15.2x
  @ 0        [RNTST ] Running test my_test...
  @ 10000    [PHASE ] phase reset_phase begin
  @ 20000    [CFG   ] num_txn=64 mode=burst
  @ 40000    [PHASE ] phase main_phase begin
  @ 82000    [SCBD  ] scoreboard checkpoint reached
  @ 114000   [SCBD  ] scoreboard checkpoint reached
  @ 146000   [SCBD  ] scoreboard checkpoint reached
  @ 178000   [SCBD  ] scoreboard checkpoint reached
  @ 198000   [PHASE ] phase main_phase end

keeping the FIRST and LAST of each ID instead: 10 messages (13.7x)
  this needs no allow-list, so it survives a testbench that invents a
  new ID -- but it keeps two lines of pure noise per noisy ID.

what the log does NOT contain:
  a VERBOSITY level on any message?  NO
  so you cannot filter by verbosity after the fact -- the level decided
  what got PRINTED, and is not recorded in what was printed.

128 of 137 informational messages come from two IDs. DRV and MON print once per transaction, which is exactly what they are for — and it means the nine lines that tell you something about the run are 6.6% of the informational volume.

The nine that survive are worth reading, because they are the shape of what you want from any log:

@ 0        [RNTST] Running test my_test...
@ 10000    [PHASE] phase reset_phase begin
@ 20000    [CFG  ] num_txn=64 mode=burst
@ 40000    [PHASE] phase main_phase begin
@ 82000    [SCBD ] scoreboard checkpoint reached
...
@ 198000   [PHASE] phase main_phase end

Which test ran, what it was configured with, which phases it reached, and that the scoreboard got to four checkpoints. That is a run's story in nine lines.

2. The Regex This Module Reuses

One pattern carries the whole module, so it is worth reading carefully:

my $MSG = qr/^(?:\#\s*)?(UVM_\w+)\s+(?:(\S+?)\((\d+)\)\s+)?\@\s*(\d+)\s*:\s*(\S*)\s*\[(\w+)\]\s*(.*)$/;

Seven fields out of the UVM layout Chapter 21.1 established: severity, file, line, time, path, ID, text. Four decisions in it matter:

(?:\#\s*)? for the Questa prefix. Chapter 21.1 measured that without this, a Questa transcript yields zero matches.

The file(line) group is OPTIONAL. (?:(\S+?)\((\d+)\)\s+)? — because UVM's own banner line is UVM_INFO @ 0: reporter [RNTST] Running test..., with no file or line at all. A pattern that requires them silently drops the line that names the test.

\[(\w+)\] captures the ID, which is the field everything downstream keys on — the filtering here, and Chapter 21.9's failure signatures.

(.*)$ takes the rest as text, ungreedily bounded by the end of line rather than by any assumption about what is in it.

With seven capture groups, $1 through $7 stop being readable, so Chapter 11.11's named captures are worth the extra characters in production code:

if ($l =~ /^(?<sev>UVM_\w+)\s+ ... \[(?<id>\w+)\]\s*(?<text>.*)$/x) {
    push @info, { time => $+{time}, id => $+{id}, text => $+{text} };
}

3. Allow-List Or First-And-Last

Two filtering strategies, both measured, with a real trade between them.

An allow-list of IDs: 9 of 137, a 15.2x reduction.

my %KEEP = map { $_ => 1 } qw(PHASE CFG SCBD RNTST);

It is data rather than logic, which is Chapter 20.5's rule, and it gives exactly the lines you asked for. Its weakness is that it fails closed in the wrong direction: a testbench that starts printing a new, important ID is silently filtered out, and nothing says so.

First and last of each ID: 10 messages, a 13.7x reduction.

for my $m (@info) {
    $first{ $m->{id} } = $m unless exists $first{ $m->{id} };
    $last{  $m->{id} } = $m;
}

It needs no list at all, so it survives a new ID appearing. Its weakness is that it keeps two lines of pure noise for every noisy ID — the first and last DRV message are of no interest to anybody.

Use both, for different jobs. The allow-list for the summary a human reads; first-and-last plus the per-ID counts for the "what is in this log" inventory you run when a log is unfamiliar. The counts alone are often the most useful output of the whole exercise: DRV 64, MON 64, SCBD 4, PHASE 3 tells you the shape of the run before you read a single message.

4. Verbosity Is Not In The Log

The measurement's last line is the one that changes how you have to work:

a VERBOSITY level on any message?  NO

UVM's verbosity — UVM_NONE, UVM_LOW, UVM_MEDIUM, UVM_HIGH, UVM_FULL, UVM_DEBUG — is a filter applied when the message is issued. It decides what gets printed. It is not recorded in what was printed.

So two things people expect to be able to do, and cannot:

"Re-filter this log at UVM_LOW." Impossible. The information was never written down. The only way to get a lower-verbosity log is to re-run with a different +UVM_VERBOSITY, which means another simulation.

"Tell me which messages were UVM_HIGH." Also impossible, for the same reason.

What you can do instead is filter by ID, which is in every line — and that is why the [ID] field is the single most valuable part of the UVM message layout for anybody processing logs. It is also an argument for how a testbench should be written: an ID per subsystem and per event class gives whoever reads the log later a handle that verbosity does not.

5. What To Remember

• Informational messages are most of the volume and little of the information.
• Measured: 128 of 137 INFO messages came from two IDs (DRV, MON) — one per transaction, as intended.
• The signal was 9 lines, 6.6% of the INFO volume: the test name, the phases, the configuration and the scoreboard checkpoints.
• One regex carries the module: severity, file, line, time, path, ID, text.
• Allow the Questa # prefix in it (21.1), or a whole transcript yields nothing.
• Make the file(line) group optional — UVM's own banner line has neither, and it names the test.
• Use named captures with seven fields (11.11); $7 is unreadable.
• Skip the summary's own count lines first (18.4) — grep -c '^UVM_INFO ' gives 138 where there are 137 messages.
• An allow-list of IDs gave a 15.2x reduction and is data, not logic (20.5) — but a new important ID is filtered out silently.
• First-and-last of each ID gave 13.7x, needs no list, and keeps two noise lines per noisy ID.
• Use both: the allow-list for a human summary, first-and-last plus counts for an inventory of an unfamiliar log.
• The per-ID counts alone tell you the shape of the run before you read any message.
• Measured: the verbosity level is NOT in the log. It decided what was printed and is not recorded in what was printed.
• So you cannot re-filter by verbosity — only re-run with a different +UVM_VERBOSITY.
• Filter by [ID], which is in every line — and write testbenches that use IDs meaningfully, because that is the only handle a log reader gets.
• Keep the full log compressed (18.10) and emit the filtered version as a separate, stamped artefact (19.6).

Chapter 21.4 takes the severity that nobody looks at until it matters. A warning that fires once a week is invisible in a single log and obvious across a hundred, which makes grouping rather than counting the useful operation.