Extracting UVM_FATAL

Part II · Module 21 · Chapter 21.6 · Extracting UVM_FATAL

1. Four Fatals In Forty Logs

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 $CONTEXT = 4;                     # lines of context to keep before a fatal

# A ring buffer (18.10): push, then shift once it is full. Constant memory,
# and at any moment it holds the last $CONTEXT lines seen.
sub scan_fatal {
    my ($file) = @_;
    open my $fh, "<", $file or die "$file: $!";
    my (@window, $hit, $ln, $hit_line);
    $ln = 0;
    while (my $l = <$fh>) {
        $ln++;
        chomp $l;
        if (!$hit && $l =~ $MSG && $1 eq "UVM_FATAL") {
            $hit = { time => $4, id => $6, text => $7, line => $ln,
                     before => [@window] };          # a COPY, taken now
            $hit_line = $ln;
            next;
        }
        next if $l =~ $SUMMARY_COUNT;
        push @window, "$ln: $l";
        shift @window if @window > $CONTEXT;
    }
    close $fh;
    return $hit;
}

my @with_fatal;
for my $f (@FILES) {
    my $h = scan_fatal($f);
    next unless $h;
    my ($short) = $f =~ m{([^/]+)\.log$};
    push @with_fatal, { test => $short, %$h };
}

printf "%d logs scanned, %d contain a UVM_FATAL\n\n", scalar @FILES, scalar @with_fatal;
printf "%-10s %-7s %-9s %s\n", "TEST", "LINE", "TIME", "the fatal message";
printf "%-10s %-7d %-9s [%s] %s\n", $_->{test}, $_->{line}, $_->{time}, $_->{id}, $_->{text}
    for @with_fatal;

print "\nthe fatal names the SYMPTOM. the lines before it name the CAUSE:\n";
my $ex = $with_fatal[0];
printf "\n%s, the %d lines before the fatal:\n", $ex->{test}, $CONTEXT;
for my $l (@{ $ex->{before} }) {
    my $show = $l;
    $show =~ s/uvm_test_top\.env\.agent\.mon //;     # trim the path for width
    printf "    %s\n", $show;
}
printf "  >>> %d: UVM_FATAL [%s] %s\n", $ex->{line}, $ex->{id}, $ex->{text};

print "\nread the two together:\n";
printf "  the fatal says : %s\n", $ex->{text};
my ($cause) = grep { /UVM_ERROR/ } @{ $ex->{before} };
if ($cause) {
    my ($ctext) = $cause =~ /\]\s*(.*)$/;
    printf "  the line before: %s\n", ($ctext // $cause);
    print "  one of those is actionable and it is not the fatal.\n";
}

print "\nwhy a ring buffer and not 'remember everything':\n";
printf "  the window holds at most %d lines at any time, whatever the log size.\n", $CONTEXT;
print "  Collecting all lines so you can slice backwards later is the one\n";
print "  approach that cannot run on a log larger than memory (18.10).\n";

print "\nand the ordering trap:\n";
print "  the fatal check runs BEFORE the line is pushed onto the window, so\n";
print "  the window holds the lines strictly BEFORE the fatal. Pushing first\n";
print "  would put the fatal itself in its own context window.\n";
my $self = grep { /UVM_FATAL/ } @{ $ex->{before} };
printf "  does the fatal appear inside its own context window?  %s\n",
    ($self ? "YES -- bug" : "no");

40 logs scanned, 4 contain a UVM_FATAL

TEST       LINE    TIME      the fatal message
test_09    10      90000     [AXI] cannot continue after illegal burst
test_18    10      90000     [AXI] cannot continue after illegal burst
test_27    10      90000     [AXI] cannot continue after illegal burst
test_36    13      120000    [AXI] cannot continue after illegal burst

the fatal names the SYMPTOM. the lines before it name the CAUSE:

test_09, the 4 lines before the fatal:
    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_WARNING tb/uvm_style_tb.v(0) @ 70000: [RETRY] transaction retried once
    9: UVM_ERROR tb/uvm_style_tb.v(0) @ 80000: [AXI] burst crossed a 4KB boundary at addr=0x00000ffc
  >>> 10: UVM_FATAL [AXI] cannot continue after illegal burst

read the two together:
  the fatal says : cannot continue after illegal burst
  the line before: burst crossed a 4KB boundary at addr=0x00000ffc
  one of those is actionable and it is not the fatal.

why a ring buffer and not 'remember everything':
  the window holds at most 4 lines at any time, whatever the log size.
  Collecting all lines so you can slice backwards later is the one
  approach that cannot run on a log larger than memory (18.10).

and the ordering trap:
  the fatal check runs BEFORE the line is pushed onto the window, so
  the window holds the lines strictly BEFORE the fatal. Pushing first
  would put the fatal itself in its own context window.
  does the fatal appear inside its own context window?  no

Four of forty runs ended in a fatal, all four with the same message. Which is itself worth noticing: a fatal message is usually one of a small, fixed set, because it is issued by the few places in a testbench that call uvm_fatal — a timeout watchdog, an illegal-transaction check, a configuration failure. The message tells you which of those fired. It does not tell you why.

2. Symptom And Cause, Side By Side

The measurement puts the two lines together:

the fatal says : cannot continue after illegal burst
the line before: burst crossed a 4KB boundary at addr=0x00000ffc

The fatal is a statement about the testbench. It could not continue. That is true, and it is not something anybody can fix.

The line before is a statement about the design, and it carries the address — 0x00000ffc, four bytes short of a 4KB boundary, which is the entire bug in one number.

So the operation worth automating is not "find the fatal" but "find the fatal and the lines before it". Reporting the fatal alone produces a regression summary where four tests failed for a reason nobody can act on, which is how a report earns the reputation of being useless.

The four lines of context in the measurement show what a window buys. Two LATE warnings that are background noise (Chapter 21.4 measured them at 100% of runs), a RETRY, and then the error that matters. The window does not need to be clever, only present — a human reading four lines sorts the relevant from the routine instantly, which is the thing a script does badly and a reader does for free.

3. The Ring Buffer

The context comes from Chapter 18.10's ring buffer, which is two lines:

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

At most four lines are held at any moment, whatever the log size. Chapter 18.10 measured the alternative directly: collecting every line so you can slice backwards later is the one approach that cannot run on a log bigger than memory, and simulation logs are exactly where that bites — a long regression log is gigabytes.

One subtlety in the capture:

$hit = { ..., before => [@window] };      # a COPY, taken now

[@window] makes a new array reference from the current contents. Without the copy — storing \@window — the saved reference would keep pointing at the live buffer, which continues to shift as the rest of the file is read, and by the end of the scan the "context" would be the last four lines of the log. Chapter 7.13's point about what gets shared when you copy nested data, in the one place where getting it wrong produces a plausible-looking wrong answer rather than an error.

4. Check Before Push

The order of two statements decides whether the output is right:

if (!$hit && $l =~ $MSG && $1 eq "UVM_FATAL") {
    $hit = { ... before => [@window] };
    next;                                  # the fatal does NOT go in the window
}
...
push @window, "$ln: $l";

The fatal is tested before the line is pushed. So the window holds the lines strictly before it. Push first and the fatal line lands in its own context window, where it is both the thing you found and part of its own explanation — a small bug that makes every excerpt one line less useful and is easy to not notice.

The measurement asserts it rather than assuming it:

does the fatal appear inside its own context window?  no

That is the habit this track keeps returning to. The assertion costs one line, and without it the only way to find the bug is to read an excerpt carefully enough to notice the duplicated line — which is exactly the kind of reading nobody does on output that looks plausible.

5. A Fatal Is Not The Same As A Failure

Three distinctions that matter for Chapter 21.8's verdict, and they are easy to collapse:

A fatal always means the test did not complete its intended work. The testbench stopped early, deliberately.

A fatal does not always mean a design bug. A configuration error, a missing file, a bad plusarg, or a testbench assumption that no longer holds all produce fatals, and none is a design failure.

A failure does not require a fatal. Eighteen of the twenty-two failing tests in Chapter 21.5's measurement reported errors and finished normally. Errors and fatals are independent evidence.

So in the verdict, a fatal is stronger evidence than an error count but a different kind: it says the run is not a valid measurement of the design, which is closer to Chapter 21.2's NO_FINISH than to FAIL. A test that went fatal at time 90000 of a planned million did not test the design — it tested the first 9%.

Which is why a report should carry both, and why Chapter 21.11's per-test row has a separate column for each. 3 errors, 0 fatals, finished and 3 errors, 1 fatal, stopped at 9% are different situations with the same error count.

6. What To Remember

• Measured: 4 of 40 runs ended in a fatal, all four with the same message.
• Fatal messages come from a small fixed set — the few places a testbench calls uvm_fatal.
• The fatal names the symptom: "cannot continue". A statement about the testbench, not the design.
• The line before names the cause, with the address: "burst crossed a 4KB boundary at addr=0x00000ffc".
• Automate "the fatal AND the lines before it", never the fatal alone.
• A window does not need to be clever, only present — a reader sorts relevant from routine for free.
• Four lines is a reasonable default: narrower misses the cause, wider stops being an excerpt.
• Keep the log line number beside it so the reader can jump for more (21.10).
• Optionally filter the routine lines out of the window using 21.4's log-count data.
• The ring buffer is push then shift ... if @window > N — constant memory whatever the log size (18.10).
• Store [@window], a copy, not \@window — a live reference ends up holding the last four lines of the file (7.13).
• Check for the fatal BEFORE pushing the line, or the fatal appears inside its own context window.
• Assert that it does not — one line, and otherwise the bug is invisible in plausible-looking output.
• A fatal always means the test did not complete its work.
• A fatal does not always mean a design bug — configuration, a missing file, a stale assumption.
• A failure does not require a fatal: 18 of 22 failing tests finished normally with errors.
• In the verdict a fatal is closer to NO_FINISH than to FAIL — the run is not a valid measurement of the design.
• Report errors and fatals in separate columns (21.11) — the same error count means different things with and without one.

Chapter 21.7 turns to the block at the end of the log. UVM prints its own severity counts, and comparing them against your own line counts is the cheapest parser self-test available — because when the two disagree, one of them is wrong and you get to find out which.