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

First-Error Excerpt and Triage Context

A verdict tells somebody a test failed and a signature tells them which group it belongs to. Neither tells them where to start. The thing that does is a short excerpt around the first error — a few lines before it, the error itself, a few lines after — carrying the log line number and the simulation time. It takes one pass over the log and constant memory, and the two halves of the window need two different mechanisms, which is the one part that is easy to get wrong.

Intermediate13 min readPerlPart IIUVM Logs

Part II · Module 21 · Chapter 21.10 · First-Error Excerpt and Triage Context

1. One Excerpt, Seven Lines

Azvya Education Pvt. Ltd.VLSI Mentor

excerpt.pl

use strict;
use warnings;

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 ($BEFORE, $AFTER) = (3, 3);

# One pass, bounded memory: a ring buffer for the lines before (18.10) and a
# countdown for the lines after. Never holds more than BEFORE+AFTER lines.
sub excerpt {
    my ($file) = @_;
    open my $fh, "<", $file or return undef;
    my (@window, @after, $hit, $ln, $countdown);
    $ln = 0;
    while (my $l = <$fh>) {
        $ln++;
        chomp $l;
        if (defined $countdown && $countdown > 0) {
            push @after, "$ln: $l";
            $countdown--;
            last if $countdown == 0;
            next;
        }
        if (!$hit && $l !~ $COUNT_LINE && $l =~ $MSG && $1 eq "UVM_ERROR") {
            $hit = { line => $ln, time => $4, id => $6, text => $7,
                     before => [@window] };
            $countdown = $AFTER;
            next;
        }
        next if $l =~ $COUNT_LINE;
        push @window, "$ln: $l";
        shift @window if @window > $BEFORE;
    }
    close $fh;
    return undef unless $hit;
    $hit->{after} = \@after;
    return $hit;
}

my @FILES = sort glob("logs/batch/*.log");
my @with;
for my $f (@FILES) {
    my $e = excerpt($f);
    next unless $e;
    my ($short) = $f =~ m{([^/]+)\.log$};
    push @with, { test => $short, %$e };
}
printf "%d logs, %d have a first error with an excerpt\n", scalar @FILES, scalar @with;

my $ex = $with[0];
printf "\n%s -- first error at log line %d, simulation time %s, ID [%s]\n",
    $ex->{test}, $ex->{line}, $ex->{time}, $ex->{id};
printf "%s\n", "-" x 68;
for my $l (@{ $ex->{before} }) { my $s = $l; $s =~ s/uvm_test_top\.env\.agent\.mon //; printf "    %s\n", $s }
{ my $s = "$ex->{line}: UVM_ERROR [$ex->{id}] $ex->{text}"; printf " >> %s\n", $s }
for my $l (@{ $ex->{after} })  { my $s = $l; $s =~ s/uvm_test_top\.env\.agent\.mon //; printf "    %s\n", $s }
printf "%s\n", "-" x 68;

printf "\nthe excerpt is %d lines (%d before + 1 + %d after)\n",
    scalar(@{ $ex->{before} }) + 1 + scalar(@{ $ex->{after} }),
    scalar @{ $ex->{before} }, scalar @{ $ex->{after} };

# ---- the size of the report, which is the whole constraint
my $log_lines = 0;
open my $fh, "<", "logs/batch/$ex->{test}.log" or die $!;
$log_lines++ while <$fh>;
close $fh;
printf "\nthat log is %d lines; the excerpt is %d (%.0f%% of it)\n",
    $log_lines, scalar(@{ $ex->{before} }) + 1 + scalar(@{ $ex->{after} }),
    100 * (scalar(@{ $ex->{before} }) + 1 + scalar(@{ $ex->{after} })) / $log_lines;
my $total_excerpt = 0;
$total_excerpt += scalar(@{ $_->{before} }) + 1 + scalar(@{ $_->{after} }) for @with;
printf "across all %d failing tests the excerpts total %d lines\n",
    scalar @with, $total_excerpt;
printf "  the full logs total %d lines\n", do {
    my $t = 0;
    for my $f (@FILES) { open my $h, "<", $f or next; $t++ while <$h>; close $h }
    $t;
};

# ---- bounded memory, asserted
print "\nis the memory bounded? the window never exceeds BEFORE lines:\n";
printf "  BEFORE=%d AFTER=%d, so at most %d lines are held at any moment,\n",
    $BEFORE, $AFTER, $BEFORE + $AFTER;
printf "  whatever the log size. The excerpt for a 2-million-line log is the\n";
printf "  same %d lines.\n", $BEFORE + 1 + $AFTER;

# ---- and the stop: the scan ends as soon as the excerpt is complete
print "\nand the scan STOPS once the excerpt is complete (last if countdown==0),\n";
print "so a failure on line 9 of a huge log costs 12 lines of reading, not the\n";
print "whole file. The first error is usually early, which is what makes this\n";
print "worth doing.\n";
printf "  first-error line numbers across the %d failing tests: %s\n",
    scalar @with, join(",", map { $_->{line} } @with[0 .. ($#with > 7 ? 7 : $#with)]);

Azvya Education Pvt. Ltd.VLSI Mentor

Captured output

40 logs, 22 have a first error with an excerpt

test_04 -- first error at log line 8, simulation time 70000, ID [SCBD]
--------------------------------------------------------------------
    5: UVM_INFO tb/uvm_style_tb.v(0) @ 40000: [PHASE] phase main_phase begin
    6: UVM_WARNING tb/uvm_style_tb.v(0) @ 50000: [LATE] response arrived 2 cycles late
    7: UVM_WARNING tb/uvm_style_tb.v(0) @ 60000: [LATE] response arrived 2 cycles late
 >> 8: UVM_ERROR [SCBD] data mismatch exp=0000001c got=00 addr=0x00000040
    9: UVM_ERROR tb/uvm_style_tb.v(0) @ 80000: [SCBD] data mismatch exp=0000002c got=00 addr=0x00000044
    10: UVM_ERROR tb/uvm_style_tb.v(0) @ 90000: [SCBD] data mismatch exp=00000034 got=00 addr=0x00000048
    11: UVM_INFO tb/uvm_style_tb.v(0) @ 110000: [PHASE] phase main_phase end
--------------------------------------------------------------------

the excerpt is 7 lines (3 before + 1 + 3 after)

that log is 20 lines; the excerpt is 7 (35% of it)
across all 22 failing tests the excerpts total 154 lines
  the full logs total 757 lines

is the memory bounded? the window never exceeds BEFORE lines:
  BEFORE=3 AFTER=3, so at most 6 lines are held at any moment,
  whatever the log size. The excerpt for a 2-million-line log is the
  same 7 lines.

and the scan STOPS once the excerpt is complete (last if countdown==0),
so a failure on line 9 of a huge log costs 12 lines of reading, not the
whole file. The first error is usually early, which is what makes this
worth doing.
  first-error line numbers across the 22 failing tests: 8,8,8,9,8,9,8,9

That block is what should appear in a regression report beside each failing test:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

test_04 -- first error at log line 8, simulation time 70000, ID [SCBD]
    5: UVM_INFO    @ 40000: [PHASE] phase main_phase begin
    6: UVM_WARNING @ 50000: [LATE] response arrived 2 cycles late
    7: UVM_WARNING @ 60000: [LATE] response arrived 2 cycles late
 >> 8: UVM_ERROR [SCBD] data mismatch exp=0000001c got=00 addr=0x00000040
    9: UVM_ERROR  @ 80000: [SCBD] data mismatch exp=0000002c got=00 addr=0x00000044
   10: UVM_ERROR  @ 90000: [SCBD] data mismatch exp=00000034 got=00 addr=0x00000048
   11: UVM_INFO   @ 110000: [PHASE] phase main_phase end

Seven lines, and they contain the whole situation: the phase it was in, the routine warnings around it, the first mismatch with its address, that two more followed immediately at consecutive addresses, and that the phase then ended. An engineer reading that does not need the log.

The two UVM_ERROR lines after the first are also the evidence for Chapter 21.5's argument: consecutive addresses, consecutive times, one cause.

2. Before And After Need Different Mechanisms

This is the part worth getting right, and it is why the excerpt takes one pass instead of two.

The lines before: a ring buffer. You do not know a line is interesting until you reach the error, by which time it has already gone past. So you keep the last N as you go — Chapter 18.10's push then shift:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

push @window, "$ln: $l";
shift @window if @window > $BEFORE;

The lines after: a countdown. By then you do know, so there is nothing to remember — you simply collect the next N:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

if (defined $countdown && $countdown > 0) {
    push @after, "$ln: $l";
    $countdown--;
    last if $countdown == 0;
    next;
}

Trying to use one mechanism for both is what produces the two-pass version: find the error's line number in pass one, then re-read the file and slice around it in pass two. That works and costs twice the I/O, and on a compressed log read through a pipe (Chapter 18.10) it is not even possible — you cannot seek backwards in a pipe.

And the same copy rule as Chapter 21.6: before => [@window] takes a snapshot. Storing \@window would hand out a reference to a buffer that keeps shifting, and by the end of the file the "context before the error" would be the last three lines of the log — a wrong answer that looks entirely plausible (Chapter 7.13).

3. Bounded By Construction

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

BEFORE=3 AFTER=3, so at most 6 lines are held at any moment,
whatever the log size. The excerpt for a 2-million-line log is the
same 7 lines.

That is the property that matters, and it is worth separating from the ratio. The measurement says the excerpt is 35% of its log — which is unimpressive, because this fixture's logs are twenty lines long. On a real two-million-line simulation log the same code produces the same seven lines, and the ratio becomes 0.0004%.

So do not read 35% as the result. The result is that the output size does not depend on the input size, which is what makes the excerpt safe to generate for every failing test in a regression without the report becoming unreadable: 22 failing tests gave 154 lines of excerpt, and would still give 154 lines if each log were a gigabyte.

The second bound is the early stop:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

last if $countdown == 0;

The scan ends as soon as the excerpt is complete. The measured first-error line numbers are 8,8,8,9,8,9,8,9 — always early, because a failing test usually fails soon after it starts doing real work. So the cost of producing an excerpt is usually a dozen lines of reading, not a file.

That is a real saving across a regression, and it has one honest caveat: a test whose first error comes at line 1,900,000 costs the whole file. The early stop is an optimisation for the common case, not a guarantee.

4. The Three Coordinates

An excerpt without coordinates is a fragment somebody has to go and find. Three fields fix that, and each answers a different question:

The log line number — line 8. Where to look in the file. This is the one that turns an excerpt into a pointer, and it must come from the script's own counter rather than $., which does not reset between files (Chapter 13.8) and would be wrong for every log after the first.

The simulation time — @ 70000. Where to put the waveform cursor, which is the actual next step for most failures.

The ID — [SCBD]. Which subsystem, and therefore who should look at it and which signature group it belongs to (Chapter 21.9).

How wide should the window be? Three either side is the value here, and the reasoning is a budget rather than a preference.

The report has a size limit set by whether anybody reads it. Twenty-two failing tests at seven lines each is 154 lines — a page and a half, readable. The same twenty-two at twenty-five lines each is 550 lines, which nobody will read, and then the excerpts stop being read at all.

So pick the width from the report's total, not from how much context feels nice per failure. If a regression has two hundred failures, three lines either side is already 1,400 lines and the right move is to group by signature first (Chapter 21.9) and emit one excerpt per signature, not per test.

That last point is the one worth taking away: an excerpt per cause is almost always more useful than an excerpt per test, because the tests in a signature group have, by construction, nearly identical excerpts.

5. What To Remember

A verdict says a test failed; a signature says which group; an excerpt says where to start.
Measured: 22 failing tests, a 7-line excerpt each (3 before, the error, 3 after).
Seven lines contained the whole situation — phase, routine warnings, the first mismatch with its address, the two that followed at consecutive addresses.
Before and after need different mechanisms. Before is a ring buffer (18.10); after is a countdown.
You do not know a line matters until later — which is the entire reason for the ring buffer.
One pass, not two. The two-pass version cannot work on a log read through a pipe, because a pipe cannot seek backwards.
Order inside the loop: countdown branch first, !$hit guard on the error test, window push last.
!$hit matters or the second error overwrites the first and the excerpt centres on the wrong line.
Push last so the error line never enters its own "before" window (21.6 asserted the same).
Snapshot with [@window], not \@window — a live reference ends up holding the last lines of the file (7.13).
Measured: at most 6 lines held at any moment, whatever the log size.
Do not read the 35% ratio as the result — these logs are 20 lines. The result is that output size is independent of input size.
22 failing tests gave 154 lines of excerpt, and would still give 154 lines on gigabyte logs.
The scan stops when the excerpt is complete. Measured first-error lines were 8 or 9 — always early.
The early stop is an optimisation, not a guarantee — a late first error costs the whole file.
Carry three coordinates: log line number, simulation time, ID.
Use your own line counter, not $. (13.8) — it does not reset between files.
Pick the window width from the REPORT's total size, not per failure.
With many failures, emit one excerpt per SIGNATURE, not per test (21.9) — grouped tests have nearly identical excerpts.

Chapter 21.11 closes the module by assembling everything into the artefact the whole chain exists to produce: one aligned row per test that a dashboard can ingest without being taught anything about UVM.

Where this fits

Part of the Perl curriculum.