Perl Part II · Module 21 · Simulation and UVM Log Analysis

Per-Test UVM Summaries

Everything in this module exists to produce one artefact: a table with one row per test that somebody can read in a minute and a dashboard can ingest without being taught anything about UVM. This chapter assembles it — the scan, the severity counts, the completion check, the verdict rule, the first-error signature — and spends its last section on the one column that is a judgement rather than a measurement, because getting that judgement wrong is what turns a useful report into one nobody opens.

Advanced14 min readPerlPart IIUVM Logs

Part II · Module 21 · Chapter 21.11 · Per-Test UVM Summaries

1. Forty Tests, Forty Rows

Azvya Education Pvt. Ltd.VLSI Mentor

summarise.pl

use strict;
use warnings;

# The whole module, assembled: scan (21.1-21.3), count severities (21.4-21.6),
# cross-check the summary (21.7), decide a verdict (21.8), sign the first
# error (21.9). One row per test, in a form a dashboard ingests unchanged.
my $COUNT_LINE = qr/^(?:#\s*)?(UVM_\w+)\s*:\s*(\d+)\s*$/;
my $MSG = qr/^(?:\#\s*)?(UVM_\w+)\s+(?:(\S+?)\((\d+)\)\s+)?\@\s*(\d+)\s*:\s*(\S*)\s*\[(\w+)\]\s*(.*)$/;
my @FINISH = (
  qr/^(?:#\s*)?\$finish\b/, qr/^\$finish at simulation time/,
  qr/^Simulation complete via \$finish/, qr/^#\s*\*\* Note: \$finish/,
);

sub signature {
    my ($id, $text) = @_;
    my $s = $text;
    $s =~ s/0x[0-9a-fA-F]+/0xADDR/g;
    $s =~ s/\b[0-9a-fA-F]{4,}\b/HEX/g;
    $s =~ s/\b\d+\b/N/g;
    $s =~ s/\[N\]/[IDX]/g;
    return "$id: $s";
}

sub evidence {
    my ($file) = @_;
    my %e = (err => 0, warn => 0, fatal => 0, info => 0, finish => 0, summary => 0);
    return (%e, no_log => 1) unless -e $file;
    return (%e, empty  => 1) if     -z $file;
    open my $fh, "<", $file or return (%e, unreadable => 1);
    my $ln = 0;
    while (my $l = <$fh>) {
        $ln++;
        $e{summary} = 1 if $l =~ /^(?:#\s*)?---\s*UVM Report Summary\s*---/;
        if ($l =~ $COUNT_LINE) { $e{"stated_$1"} = $2; next }
        for my $f (@FINISH) { $e{finish} = 1 if $l =~ $f }
        next unless $l =~ $MSG;
        my ($sev, $time, $id, $text) = ($1, $4, $6, $7);
        $e{info}++  if $sev eq "UVM_INFO";
        $e{warn}++  if $sev eq "UVM_WARNING";
        $e{fatal}++ if $sev eq "UVM_FATAL";
        if ($sev eq "UVM_ERROR") {
            $e{err}++;
            unless (defined $e{first_id}) {
                @e{qw(first_id first_time first_line)} = ($id, $time, $ln);
                $e{first_sig} = signature($id, $text);
            }
        }
    }
    close $fh;
    return %e;
}

my @RULE = (
  [ "NO_LOG",  sub { $_[0]{no_log} } ],
  [ "EMPTY",   sub { $_[0]{empty} } ],
  [ "UNREAD",  sub { $_[0]{unreadable} } ],
  [ "CRASH",   sub { !$_[0]{finish} } ],
  [ "FAIL",    sub { $_[0]{fatal} || $_[0]{err} } ],
  [ "PASS",    sub { 1 } ],
);
sub verdict { my (%e)=@_; for my $r (@RULE) { return $r->[0] if $r->[1]->(\%e) } return "UNKNOWN" }

my @FILES = sort glob("logs/batch/*.log");
my @rows;
for my $f (@FILES) {
    my ($test) = $f =~ m{([^/]+)\.log$};
    my %e = evidence($f);
    my $v = verdict(%e);
    # 21.7's cross-check, carried as a flag rather than as prose
    my $mismatch = (defined $e{stated_UVM_ERROR} && $e{stated_UVM_ERROR} != $e{err})
                 ? "ERRCOUNT" : "-";
    push @rows, {
        test => $test, verdict => $v, err => $e{err}, warn => $e{warn},
        fatal => $e{fatal}, finish => ($e{finish} ? "yes" : "no"),
        first_id => ($e{first_id} // "-"), first_time => ($e{first_time} // "-"),
        sig => ($e{first_sig} // "-"), check => $mismatch,
    };
}

# ---- the table: fixed columns, aligned, one row per test
my @COLS = ( ["TEST",10], ["VERDICT",8], ["ERR",4], ["WARN",5], ["FATAL",6],
             ["FIN",4], ["FIRST_ID",9], ["FIRST_TIME",11], ["CHK",5] );
printf join(" ", map { "%-$_->[1]s" } @COLS) . "\n", map { $_->[0] } @COLS;
for my $r (@rows) {
    printf join(" ", map { "%-$_->[1]s" } @COLS) . "\n",
        $r->{test}, $r->{verdict}, $r->{err}, $r->{warn}, $r->{fatal},
        $r->{finish}, $r->{first_id}, $r->{first_time}, $r->{check};
}

# ---- the roll-up a dashboard actually displays
my %tally;
$tally{ $_->{verdict} }++ for @rows;
printf "\n%d tests: %s\n", scalar @rows,
    join(", ", map { "$_ $tally{$_}" } sort keys %tally);

my %by_sig;
push @{ $by_sig{ $_->{sig} } }, $_->{test} for grep { $_->{sig} ne "-" } @rows;
printf "\n%d distinct first-error signatures among the failures:\n", scalar keys %by_sig;
for my $s (sort { @{ $by_sig{$b} } <=> @{ $by_sig{$a} } || $a cmp $b } keys %by_sig) {
    printf "  %2d  %s\n", scalar @{ $by_sig{$s} }, $s;
}

printf "\nparser cross-check (21.7) flagged %d of %d rows\n",
    scalar(grep { $_->{check} ne "-" } @rows), scalar @rows;
print "  it compares the ERROR count only, deliberately: 21.7 measured that\n";
print "  the INFO counts differ by one in every log for a known, benign\n";
print "  reason, and a check that fires on every row is one nobody reads.\n";
# show what checking INFO instead would have produced
my $info_mismatch = 0;
for my $f (@FILES) {
    my %e = evidence($f);
    $info_mismatch++ if defined $e{stated_UVM_INFO} && $e{stated_UVM_INFO} != $e{info};
}
printf "  had it compared INFO as well it would have flagged %d of %d rows.\n",
    $info_mismatch, scalar @FILES;

# ---- machine-readable, same data, no alignment
print "\nthe same rows as TSV, for a dashboard to ingest:\n";
print join("\t", qw(test verdict errors warnings fatals finished first_id first_time)), "\n";
for my $r (@rows[0 .. 4]) {
    print join("\t", $r->{test}, $r->{verdict}, $r->{err}, $r->{warn},
                     $r->{fatal}, $r->{finish}, $r->{first_id}, $r->{first_time}), "\n";
}
print "  ... (" . (scalar(@rows) - 5) . " more rows)\n";

Azvya Education Pvt. Ltd.VLSI Mentor

Captured output

TEST       VERDICT  ERR  WARN  FATAL  FIN  FIRST_ID  FIRST_TIME  CHK  
test_01    PASS     0    2     0      yes  -         -           -    
test_02    PASS     0    2     0      yes  -         -           -    
test_03    PASS     0    3     0      yes  -         -           -    
test_04    FAIL     3    2     0      yes  SCBD      70000       -    
test_05    FAIL     2    2     0      yes  PROTO     70000       -    
test_06    PASS     0    3     0      yes  -         -           -    
test_07    PASS     0    3     0      yes  -         -           -    
test_08    FAIL     3    2     0      yes  SCBD      70000       -    
test_09    FAIL     1    3     1      yes  AXI       80000       -    
test_10    FAIL     2    2     0      yes  PROTO     70000       -    
test_11    PASS     0    2     0      yes  -         -           -    
test_12    FAIL     3    3     0      yes  SCBD      80000       -    
test_13    FAIL     1    2     0      yes  TIMING    70000       -    
test_14    PASS     0    3     0      yes  -         -           -    
test_15    FAIL     2    3     0      yes  PROTO     80000       -    
test_16    FAIL     3    2     0      yes  SCBD      70000       -    
test_17    PASS     0    3     0      yes  -         -           -    
test_18    FAIL     1    3     1      yes  AXI       80000       -    
test_19    PASS     0    2     0      yes  -         -           -    
test_20    FAIL     5    2     0      yes  SCBD      70000       -    
test_21    PASS     0    4     0      yes  -         -           -    
test_22    PASS     0    2     0      yes  -         -           -    
test_23    PASS     0    2     0      yes  -         -           -    
test_24    FAIL     3    3     0      yes  SCBD      80000       -    
test_25    FAIL     2    2     0      yes  PROTO     70000       -    
test_26    FAIL     1    2     0      yes  TIMING    70000       -    
test_27    FAIL     1    3     1      yes  AXI       80000       -    
test_28    FAIL     3    3     0      yes  SCBD      80000       -    
test_29    PASS     0    2     0      yes  -         -           -    
test_30    FAIL     2    3     0      yes  PROTO     80000       -    
test_31    PASS     0    2     0      yes  -         -           -    
test_32    FAIL     3    2     0      yes  SCBD      70000       -    
test_33    PASS     0    3     0      yes  -         -           -    
test_34    PASS     0    3     0      yes  -         -           -    
test_35    FAIL     2    3     0      yes  PROTO     80000       -    
test_36    FAIL     4    3     1      yes  SCBD      80000       -    
test_37    PASS     0    2     0      yes  -         -           -    
test_38    PASS     0    2     0      yes  -         -           -    
test_39    FAIL     1    3     0      yes  TIMING    80000       -    
test_40    FAIL     5    2     0      yes  SCBD      70000       -    

40 tests: FAIL 22, PASS 18

4 distinct first-error signatures among the failures:
  10  SCBD: data mismatch exp=HEX got=N addr=0xADDR
   6  PROTO: req asserted while busy at cycle N
   3  AXI: burst crossed a 4KB boundary at addr=0xADDR
   3  TIMING: setup violation on data[IDX] at N ps

parser cross-check (21.7) flagged 0 of 40 rows
  it compares the ERROR count only, deliberately: 21.7 measured that
  the INFO counts differ by one in every log for a known, benign
  reason, and a check that fires on every row is one nobody reads.
  had it compared INFO as well it would have flagged 40 of 40 rows.

the same rows as TSV, for a dashboard to ingest:
test	verdict	errors	warnings	fatals	finished	first_id	first_time
test_01	PASS	0	2	0	yes	-	-
test_02	PASS	0	2	0	yes	-	-
test_03	PASS	0	3	0	yes	-	-
test_04	FAIL	3	2	0	yes	SCBD	70000
test_05	FAIL	2	2	0	yes	PROTO	70000
  ... (35 more rows)

Forty logs in, forty rows out, and three summaries beneath them. That table is the deliverable — everything in Chapters 21.1 to 21.10 is machinery for producing it.

2. The Columns

Nine columns, and each is there because somebody asks for it:

TEST — the key everything joins on.

VERDICT — the one word from Chapter 21.8's rule table. Not derived here; the rule lives in one place and this column reports it.

ERR, WARN, FATAL — three separate columns, not one severity field. Chapter 21.6 measured why: 3 errors, 0 fatals and 3 errors, 1 fatal are different situations, and collapsing them loses the distinction between a test that failed and one that stopped.

FIN — did it finish. Chapter 21.2 measured that this is the column that catches a crashed run which has no errors at all, and it belongs in the table rather than only inside the verdict, because FAIL with FIN no and FAIL with FIN yes mean different things to whoever reads the row.

FIRST_ID and FIRST_TIME — Chapter 21.5's two most valuable fields: who complained first, and where to put the waveform cursor.

CHK — the parser's own cross-check, which section 4 is about.

What is deliberately not a column:

The first error's text. It is long, it varies per test, and it destroys the alignment. The signature appears in the roll-up instead, which groups it.

The log path. Derivable from the test name, and it doubles the width of every row.

Any wall-clock time. It belongs in the regression's own records, not in a log summary — and Chapter 21.2 established that the log cannot supply it anyway.

The column widths come from a table, not from literals scattered through the printf:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

my @COLS = ( ["TEST",10], ["VERDICT",8], ["ERR",4], ... );
printf join(" ", map { "%-$_->[1]s" } @COLS) . "\n", map { $_->[0] } @COLS;

The format string is built from the same data that produces the header, so a column cannot be widened in the header and not in the rows — the classic way an aligned table stops being aligned three months after it was written.

Chapter 4.6's printf with a computed width, and it is the same instinct as Chapter 20.5's family table and Chapter 18.8's spelling table: the thing that varies goes in data, and the code reads the data.

3. What A Human Reads And What A Dashboard Ingests

The script emits both, and they are different artefacts:

The aligned table and roll-up, for a person:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

40 tests: FAIL 22, PASS 18

4 distinct first-error signatures among the failures:
  10  SCBD: data mismatch exp=HEX got=N addr=0xADDR
   6  PROTO: req asserted while busy at cycle N
   3  AXI: burst crossed a 4KB boundary at addr=0xADDR
   3  TIMING: setup violation on data[IDX] at N ps

Twenty-two failures, four causes. That three-line roll-up is the most useful output of the entire module, and it is Chapter 21.9's signatures doing the work. An engineer reads it and knows there are four things to investigate, not twenty-two.

The TSV, for a machine:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

test	verdict	errors	warnings	fatals	finished	first_id	first_time
test_01	PASS	0	2	0	yes	-	-
test_04	FAIL	3	2	0	yes	SCBD	70000

Same data, no alignment, one header line. Tab-separated rather than comma-separated for the reason Chapter 13.14 gives: a UVM message can contain a comma and will not contain a tab, so TSV needs no quoting and no escaping.

Emit both from one pass. They are two renderings of the same rows, and a script that computes the rows twice will eventually disagree with itself.

And the ordering is sort glob(...) — Chapter 17.3's directory read with Chapter 17.8's sort — so two runs on the same logs produce byte-identical output, which is what makes the result diffable against yesterday's.

4. The Column That Is A Judgement

CHK is the only column that is not a measurement, and the measurement around it is the point:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

parser cross-check (21.7) flagged 0 of 40 rows
  it compares the ERROR count only, deliberately
  had it compared INFO as well it would have flagged 40 of 40 rows.

Zero of forty is the right answer, and forty of forty was one line of code away.

Chapter 21.7 measured that the stated UVM_INFO count differs from a line count by exactly one in every log, for a known and benign reason — a banner line printed outside the report task. So a cross-check that compared every severity would flag every row in every regression, forever, and within a week nobody would look at the column.

So the check is scoped to the severity that decides the verdict:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

my $mismatch = (defined $e{stated_UVM_ERROR} && $e{stated_UVM_ERROR} != $e{err})
             ? "ERRCOUNT" : "-";

Three things make that defensible rather than lazy:

The scope is a decision, written down. The script says why in its own output rather than leaving the next reader to wonder whether INFO was forgotten.

The alternative is measured, not assumed. had it compared INFO as well it would have flagged 40 of 40 is a number the script computes, so the justification is evidence rather than an argument.

defined guards it, so a log with no summary block (a crashed run) reports - rather than comparing against a missing value.

This is Chapter 20.7's measured lesson arriving from a different direction, and it is the one worth carrying out of this module.

There, a QC checker fired sixteen times with fifteen false positives, and the fix was to stop reporting module ports as dangling nets. Here, a cross-check that would have fired on 100% of rows is scoped down before it is ever shipped.

Both are the same rule: a check that fires when nothing is wrong destroys the checks that fire when something is. The cost is not the wasted line — it is that the reader stops reading the column, and the one row that matters goes past with the forty that do not.

The discipline that follows is small and worth making a habit: when you add a check, run it on inputs you believe are good and count how often it fires. If the answer is "always", it is not a check yet. That one number — 40 of 40 — is what turned this column from a plausible idea into a scoped one.

5. What To Remember

The whole module exists to produce one table: one row per test, readable in a minute.
Measured: 40 logs in, 40 rows out, FAIL 22 / PASS 18.
Keep ERR, WARN and FATAL as separate columns — 3 errors, 1 fatal differs from 3 errors, 0 fatals (21.6).
Keep FIN as its own column, not only inside the verdict: FAIL+FIN no and FAIL+FIN yes read differently (21.2).
Carry FIRST_ID and FIRST_TIME — who complained first and where the waveform cursor goes (21.5).
Leave the first error's TEXT out — it varies per test and destroys alignment. The signature appears in the roll-up instead.
Build the format string from the same table as the header (4.6), or the header and the rows drift apart.
Measured: 22 failures, 4 signatures. That three-line roll-up is the module's most useful output (21.9).
Emit a human table and a machine TSV from ONE pass — two renderings of the same rows, never two computations.
Use TSV, not CSV — a UVM message contains commas and never tabs, so no quoting is needed (13.14).
sort glob(...) (17.3, 17.8) so two runs are byte-identical and the output is diffable against yesterday's.
Measured: the cross-check flagged 0 of 40 rows — and would have flagged 40 of 40 if scoped to all severities.
Scope a check to the severity that decides the verdict, and say so in the output.
Measure the alternative rather than asserting it — "40 of 40" is evidence, not an argument.
Guard it with defined so a crashed run with no summary reports - rather than comparing against nothing.
A check that fires when nothing is wrong destroys the checks that fire when something is (20.7).
When you add a check, run it on good inputs and count how often it fires. If the answer is "always", it is not a check yet.

That closes Module 21. You can take a directory of simulation logs and produce a verdict you can defend: normalise the three simulators' shells so the UVM content beneath them is tool-independent, ask whether the run finished before counting anything, filter informational volume down to the lines that carry signal, group warnings by rarity rather than frequency, keep each failure's first error with its time and identifier, capture the lines before a fatal in bounded memory, cross-check your counts against UVM's own, decide between four outcomes with an ordered rule whose every branch you have proved can fire, collapse a list of failures into a handful of signatures verified in both directions, cut a bounded excerpt that does not grow with the log, and assemble the lot into one table for a person and one for a machine.

Where this fits

Part of the Perl curriculum.