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

Extracting UVM_ERROR

Errors are what decide a verdict, and the natural instinct is to collect all of them. A test that reports five errors is usually reporting one problem five times, because a scoreboard that has lost synchronisation complains about every packet that follows. This chapter measures that effect across forty real runs, and the result changes what a regression report should contain: the first error with its identifier and simulation time, plus a count, which together are usually enough to start work without opening the log.

Intermediate12 min readPerlPart IIUVM Logs

Part II · Module 21 · Chapter 21.5 · Extracting UVM_ERROR

1. Twenty-Two Failing Logs, One Line Each

Azvya Education Pvt. Ltd.VLSI Mentor

errors.pl

use strict;
use warnings;

my @FILES = sort glob("logs/batch/*.log");
my $SUMMARY_COUNT = 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 (@per_log, $total_err, %id_all, %id_first);
for my $f (@FILES) {
    open my $fh, "<", $f or die "$f: $!";
    my ($n, $first, $lineno, $fatal) = (0, undef, 0, 0);
    my $ln = 0;
    while (my $l = <$fh>) {
        $ln++;
        next if $l =~ $SUMMARY_COUNT;          # 18.4, and it bit my own shell check
        next unless $l =~ $MSG;
        my ($sev, $time, $id, $text) = ($1, $4, $6, $7);
        $fatal++ if $sev eq "UVM_FATAL";
        next unless $sev eq "UVM_ERROR";
        $n++;
        $total_err++;
        $id_all{$id}++;
        unless (defined $first) {
            $first = { time => $time, id => $id, text => $text };
            $lineno = $ln;
            $id_first{$id}++;
        }
    }
    close $fh;
    my ($short) = $f =~ m{([^/]+)\.log$};
    push @per_log, { test => $short, n => $n, fatal => $fatal,
                     first => $first, line => $lineno };
}

my @failing = grep { $_->{n} > 0 } @per_log;
printf "%d logs, %d with at least one UVM_ERROR, %d error messages in total\n\n",
    scalar @FILES, scalar @failing, $total_err;

printf "%-10s %-7s %-7s %-9s %-8s %s\n", "TEST", "ERRORS", "FATALS", "FIRST @", "ID", "first error text";
for my $p (@failing) {
    printf "%-10s %-7d %-7d %-9s %-8s %s\n", $p->{test}, $p->{n}, $p->{fatal},
        $p->{first}{time}, $p->{first}{id}, $p->{first}{text};
}

print "\nIDs across ALL errors vs IDs across FIRST errors only:\n";
printf "%-10s %-14s %s\n", "ID", "all errors", "first errors";
for my $id (sort { ($id_all{$b} // 0) <=> ($id_all{$a} // 0) || $a cmp $b } keys %id_all) {
    printf "%-10s %-14d %d\n", $id, $id_all{$id}, ($id_first{$id} // 0);
}
printf "  distinct IDs over all errors: %d ; over first errors only: %d\n",
    scalar keys %id_all, scalar keys %id_first;
my ($top) = sort { $id_all{$b} <=> $id_all{$a} } keys %id_all;
printf "  %s is %.0f%% of ALL errors but only %.0f%% of FIRST errors\n",
    $top, 100 * $id_all{$top} / $total_err,
    100 * ($id_first{$top} // 0) / scalar @failing;
print "  -- counting every error over-weights the cause that REPEATS.\n";

print "\nhow much is kept:\n";
printf "  reporting every error  : %d lines\n", $total_err;
printf "  first error + a count  : %d lines (%.1fx less)\n",
    scalar @failing, $total_err / scalar @failing;

print "\nwhy the FIRST error and not the last, or all of them:\n";
my ($multi) = grep { $_->{n} >= 4 } @failing;
if ($multi) {
    printf "  %s reports %d errors. Its first is [%s] at %s.\n",
        $multi->{test}, $multi->{n}, $multi->{first}{id}, $multi->{first}{time};
    print "  The later ones are at later simulation times, downstream of it --\n";
    print "  a scoreboard that has lost sync reports every subsequent packet.\n";
    print "  Reporting all 5 suggests five problems; the first one is the lead.\n";
}

Azvya Education Pvt. Ltd.VLSI Mentor

Captured output

40 logs, 22 with at least one UVM_ERROR, 53 error messages in total

TEST       ERRORS  FATALS  FIRST @   ID       first error text
test_04    3       0       70000     SCBD     data mismatch exp=0000001c got=00 addr=0x00000040
test_05    2       0       70000     PROTO    req asserted while busy at cycle 15
test_08    3       0       70000     SCBD     data mismatch exp=00000038 got=00 addr=0x00000080
test_09    1       1       80000     AXI      burst crossed a 4KB boundary at addr=0x00000ffc
test_10    2       0       70000     PROTO    req asserted while busy at cycle 30
test_12    3       0       80000     SCBD     data mismatch exp=00000054 got=00 addr=0x000000c0
test_13    1       0       70000     TIMING   setup violation on data[5] at 413 ps
test_15    2       0       80000     PROTO    req asserted while busy at cycle 45
test_16    3       0       70000     SCBD     data mismatch exp=00000070 got=00 addr=0x00000100
test_18    1       1       80000     AXI      burst crossed a 4KB boundary at addr=0x00001ffc
test_20    5       0       70000     SCBD     data mismatch exp=0000008c got=00 addr=0x00000140
test_24    3       0       80000     SCBD     data mismatch exp=000000a8 got=00 addr=0x00000180
test_25    2       0       70000     PROTO    req asserted while busy at cycle 75
test_26    1       0       70000     TIMING   setup violation on data[2] at 426 ps
test_27    1       1       80000     AXI      burst crossed a 4KB boundary at addr=0x00002ffc
test_28    3       0       80000     SCBD     data mismatch exp=000000c4 got=00 addr=0x000001c0
test_30    2       0       80000     PROTO    req asserted while busy at cycle 90
test_32    3       0       70000     SCBD     data mismatch exp=000000e0 got=00 addr=0x00000200
test_35    2       0       80000     PROTO    req asserted while busy at cycle 105
test_36    4       1       80000     SCBD     data mismatch exp=000000fc got=00 addr=0x00000240
test_39    1       0       80000     TIMING   setup violation on data[7] at 439 ps
test_40    5       0       70000     SCBD     data mismatch exp=00000118 got=00 addr=0x00000280

IDs across ALL errors vs IDs across FIRST errors only:
ID         all errors     first errors
SCBD       38             10
PROTO      8              6
AXI        4              3
TIMING     3              3
  distinct IDs over all errors: 4 ; over first errors only: 4
  SCBD is 72% of ALL errors but only 45% of FIRST errors
  -- counting every error over-weights the cause that REPEATS.

how much is kept:
  reporting every error  : 53 lines
  first error + a count  : 22 lines (2.4x less)

why the FIRST error and not the last, or all of them:
  test_20 reports 5 errors. Its first is [SCBD] at 70000.
  The later ones are at later simulation times, downstream of it --
  a scoreboard that has lost sync reports every subsequent packet.
  Reporting all 5 suggests five problems; the first one is the lead.

Forty runs, twenty-two with errors, fifty-three error messages — and the table gives each failing test one line: how many errors, whether it also went fatal, and the first error's time, ID and text.

That table is the useful artefact. test_09 1 error 1 fatal first [AXI] @ 80000 burst crossed a 4KB boundary is enough to know what happened and who should look at it, without opening anything.

2. Why The First Error

Look at test_20: five errors. Its first is [SCBD] data mismatch exp=3f got=00 addr=0x40 at time 70000, and the later four are at later times.

Five errors is one problem reported five times. A scoreboard compares expected against actual; once it has lost synchronisation — one dropped packet, one wrong address — every subsequent comparison fails too. The fifth error is not new information, it is the first error still being true.

So the first error is privileged for a concrete reason, not as a convention:

It is the earliest moment the design and the model disagreed. Everything after it is downstream in simulation time, and debugging starts at the earliest divergence.

The last error is the least informative. It is the furthest from the cause and often reflects a testbench that has given up rather than a design that has misbehaved.

All of them is the wrong amount. Fifty-three lines across twenty-two tests is a page of output where twenty-two lines carry the same information, measured at 2.4x less.

$first is captured with unless (defined $first), not with a flag or a counter:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

unless (defined $first) {
    $first = { time => $time, id => $id, text => $text };
    $lineno = $ln;
    $id_first{$id}++;
}

Two details earn their place. defined, not truth (Chapter 2.7) — a first error whose text is empty or whose time is 0 is still a first error, and a truth test would keep looking.

The line number comes from the script's own counter $ln, incremented for every line read, rather than from $.. Chapter 13.8 measured why: $. does not reset between files, so in a loop over forty logs it keeps climbing and every line number after the first file is wrong. One my $ln = 0; inside the per-file loop is the fix.

3. All Errors And First Errors Are Different Populations

Now the measurement that should change how a report is built:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

ID      all errors  first errors
SCBD    38          10
PROTO   8           6
AXI     4           3
TIMING  3           3

SCBD is 72% of ALL errors but only 45% of FIRST errors

Counting every error over-weights whichever cause repeats itself. SCBD dominates the error volume because that is what a de-synchronised scoreboard does. It does not dominate the causes: of twenty-two failing tests, ten begin with a scoreboard mismatch and twelve begin with something else.

The practical consequence, which is where this goes wrong in real reports:

Ranked by total errors, the conclusion is "the scoreboard is the problem, 72% of errors" — and somebody spends a day on the scoreboard.

Ranked by first errors, the conclusion is "there are four distinct problems and the scoreboard is slightly under half of them" — which is true, and which puts the protocol, AXI and timing failures back on the list.

Chapter 21.4 found the same structural point for warnings from the other direction: the number you count determines the conclusion you reach, and the obvious number is usually the wrong one. There, occurrences hid a rare warning; here, occurrences inflate a repeating one.

A live confirmation of Chapter 18.4, which happened while this module's fixture was being built.

The shell check grep -l '^UVM_ERROR ' logs/batch/*.log | wc -l reported 40 of 40 logs contain an error. The true number is 22.

The cause is the report summary's own line:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

UVM_ERROR :    0

It begins with UVM_ERROR followed by a space, so it matches '^UVM_ERROR ' — in every log, including every passing one. The anchored pattern was right; the summary line defeats it anyway.

The script above gets the right answer because its first act on every line is

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

next if $l =~ /^(?:#\s*)?UVM_\w+\s*:\s*\d+\s*$/;

Chapter 18.4 measured this hazard on a synthesis log and it is the single most frequent bug in this module's subject. Worth noting that it caught me in a one-line shell check, which is exactly where it catches everybody — a quick grep -c typed at a prompt gets no review.

4. What To Keep Beside It

Four fields, and each answers a question somebody will ask:

The ID. [SCBD], [AXI], [TIMING] — which subsystem complained, and the key Chapter 21.9 groups by to turn a hundred failures into a handful of causes.

The simulation time. @ 70000 — where to put the cursor in the waveform. This is the single most valuable field for whoever picks up the failure.

The log line number. Where to look in the log, which Chapter 21.10 uses to cut a bounded excerpt.

The count. Not for triage, but for comparison: a test that failed with 3 errors last week and 47 this week has changed in a way the verdict alone does not show.

And one field worth not keeping: the file and line from the message's own file(line) field. It names the testbench source that issued the message, which is nearly always the same scoreboard line for every mismatch — informative once, noise in a table.

5. What To Remember

A test reporting five errors is usually reporting one problem five times.
Measured: 40 runs, 22 with errors, 53 error messages.
The first error is the earliest divergence between design and model; everything after is downstream in simulation time.
The last error is the least informative — furthest from the cause.
First error plus a count is 2.4x less output and the same information.
Capture the first with unless (defined $first) (2.7) — a time of 0 or empty text is still a first error.
Count lines with your own counter, not $. (13.8): $. does not reset between files, so every line number after the first log is wrong.
Measured: SCBD is 72% of all errors and 45% of first errors.
Counting every error over-weights the cause that repeats — a de-synchronised scoreboard complains about every later packet.
Ranked by total errors you conclude one problem; ranked by first errors you find four.
The number you count determines the conclusion — occurrences hid a rare warning in 21.4 and inflate a repeating error here.
grep -l '^UVM_ERROR ' reported 40 of 40 where 22 is right — the summary's own UVM_ERROR : 0 line matches in every log, including passing ones (18.4).
Skip the summary-count pattern first, and remember a quick shell grep -c gets no review.
Keep four fields: ID, simulation time, log line number, count.
The simulation time is the most valuable — it is where the waveform cursor goes.
Do not keep the message's own file(line) — it names the testbench line that issued it, the same one every time.

Chapter 21.6 takes the severity that ends a run. A fatal names the symptom, and the lines immediately before it name the cause — which makes the useful operation keeping a bounded window of context rather than extracting a field.

Where this fits

Part of the Perl curriculum.