Extracting UVM_WARNING

Part II · Module 21 · Chapter 21.4 · Extracting UVM_WARNING

1. Forty Logs, Four Warning IDs

use strict;
use warnings;

# logs/batch holds 40 REAL Icarus runs of tb/uvm_style_tb.v in batch mode,
# seeds 1..40. Which warnings appear depends on the seed, which is how a
# regression behaves: most runs look alike and a few do not.
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 (%occurrences, %logs_with, %first_text, $total_warn);
for my $f (@FILES) {
    open my $fh, "<", $f or die "$f: $!";
    my %seen_here;
    while (my $l = <$fh>) {
        next if $l =~ $SUMMARY_COUNT;
        next unless $l =~ $MSG;
        next unless $1 eq "UVM_WARNING";
        my ($id, $text) = ($6, $7);
        $occurrences{$id}++;
        $total_warn++;
        $first_text{$id} //= $text;
        $seen_here{$id} = 1;
    }
    close $fh;
    $logs_with{$_}++ for keys %seen_here;
}

printf "%d logs, %d UVM_WARNING messages in total\n\n", scalar @FILES, $total_warn;

printf "%-10s %-13s %-14s %s\n", "ID", "OCCURRENCES", "LOGS (of 40)", "first text seen";
for my $id (sort { $logs_with{$b} <=> $logs_with{$a} || $a cmp $b } keys %logs_with) {
    printf "%-10s %-13d %-14s %s\n", $id, $occurrences{$id},
        sprintf("%d (%.0f%%)", $logs_with{$id}, 100 * $logs_with{$id} / scalar @FILES),
        $first_text{$id};
}

print "\nthe two numbers answer different questions:\n";
printf "  LATE: %d occurrences but %d logs -- it fires %.1f times in EVERY run,\n",
    $occurrences{LATE}, $logs_with{LATE}, $occurrences{LATE} / $logs_with{LATE};
print "        so it is background, and a per-run count tells you nothing.\n";
printf "  ARBSTALL: %d occurrences in %d logs -- rare, and a single log would\n",
    $occurrences{ARBSTALL}, $logs_with{ARBSTALL};
print "        show it as one warning among several and look like nothing.\n";

# ---- what a single log shows, for comparison
my $one = "logs/batch/test_05.log";
my $n = 0;
open my $fh, "<", $one or die $!;
while (my $l = <$fh>) { next if $l =~ $SUMMARY_COUNT; $n++ if $l =~ /^(?:#\s*)?UVM_WARNING\b/ }
close $fh;
printf "\nseen from inside ONE log (%s): %d warnings. No way to tell which is\n",
    ($one =~ m{([^/]+)$})[0], $n;
print "routine and which is the one that matters.\n";

# ---- rarity is the signal
print "\nwarnings ranked by RARITY (the triage order):\n";
for my $id (sort { $logs_with{$a} <=> $logs_with{$b} || $a cmp $b } keys %logs_with) {
    my $pct = 100 * $logs_with{$id} / scalar @FILES;
    printf "  %-10s in %2d of %d logs (%3.0f%%)  %s\n", $id, $logs_with{$id},
        scalar @FILES, $pct,
        ($pct <= 10 ? "<-- investigate first" : $pct >= 90 ? "background noise" : "");
}

40 logs, 100 UVM_WARNING messages in total

ID         OCCURRENCES   LOGS (of 40)   first text seen
LATE       80            40 (100%)      response arrived 2 cycles late
RETRY      13            13 (32%)       transaction retried once
CLKJIT     5             5 (12%)        clock jitter exceeded budget by 17 ps
ARBSTALL   2             2 (5%)         arbiter stalled for 57 cycles

the two numbers answer different questions:
  LATE: 80 occurrences but 40 logs -- it fires 2.0 times in EVERY run,
        so it is background, and a per-run count tells you nothing.
  ARBSTALL: 2 occurrences in 2 logs -- rare, and a single log would
        show it as one warning among several and look like nothing.

seen from inside ONE log (test_05.log): 2 warnings. No way to tell which is
routine and which is the one that matters.

warnings ranked by RARITY (the triage order):
  ARBSTALL   in  2 of 40 logs (  5%)  <-- investigate first
  CLKJIT     in  5 of 40 logs ( 12%)  
  RETRY      in 13 of 40 logs ( 32%)  
  LATE       in 40 of 40 logs (100%)  background noise

One hundred warnings across forty runs, from four IDs — and the four behave completely differently.

2. Occurrences Or Logs: Two Numbers

The table has two count columns and they answer different questions:

LATE       80 occurrences   40 of 40 logs (100%)
ARBSTALL    2 occurrences    2 of 40 logs (5%)

LATE fires 2.0 times in every single run. It is background: a property of the testbench or the design that has been true since somebody wrote the check. Its occurrence count tells you how long the run was, not whether anything is wrong.

ARBSTALL appears in two runs out of forty. Two occurrences total, one per affected run.

The distinction is worth the extra line of code because the two numbers fail in opposite directions. A per-run count makes LATE look like the problem. A total count makes ARBSTALL look negligible. Only in how many runs separates a universal condition from a rare one:

my %seen_here;                       # per log
...
$seen_here{$id} = 1;                 # a set (6.9), so repeats collapse
...
$logs_with{$_}++ for keys %seen_here;   # once per log, after the file closes

The %seen_here set reset per file is the whole mechanism, and the for keys after the file closes rather than inside the loop is what makes it one count per log instead of one per occurrence.

3. Rarity Is The Signal

Now the finding. Ranked by rarity:

ARBSTALL   in  2 of 40 logs (  5%)  <-- investigate first
CLKJIT     in  5 of 40 logs ( 12%)
RETRY      in 13 of 40 logs ( 32%)
LATE       in 40 of 40 logs (100%)  background noise

That is the exact inverse of the occurrence ranking. The warning with the most occurrences is the one to ignore; the one with the fewest is the one to look at.

Which means the default report — sorted by count, descending, as every warning summary ever written — puts the least interesting warning at the top and buries the interesting one at the bottom. It is not merely unhelpful; it is actively misleading, because the reader's attention goes to the first row.

The reasoning behind rarity being the signal is worth making explicit:

A warning in 100% of runs is a property of the setup. It fires whether the design is good or bad, so it carries no information about this run. It should be either fixed or waived explicitly — and a waiver list is the right place for it, not a report.

A warning in 5% of runs is correlated with something. A seed, a configuration, a piece of traffic, a time of day. That correlation is a lead, and the two affected runs are a small enough set to read.

The middle is where real degradation hides. A check at 32% that was at 5% last month is the "slow-creeping problem" this chapter's purpose names — and seeing it requires comparing against the previous regression, which is the same baseline comparison Chapter 20.7 built for cell counts.

4. One Log Cannot Tell You Any Of This

The measurement's middle section is the honest limit:

seen from inside ONE log (test_05.log): 2 warnings. No way to tell which is
routine and which is the one that matters.

Two warnings. Both look identical in structure — same severity, same layout, a plausible-sounding message each. Nothing in the log says one has fired in every run for a year and the other has fired twice ever.

So warning analysis is inherently a cross-log operation, and that has two practical consequences:

A per-test report should list warnings, not judge them. Chapter 21.11's per-test summary carries a warning count precisely because a count is all a single log supports.

The grouping belongs at the regression level, run once over the whole log directory, with the previous run's numbers beside it. That is the only place the information exists.

Reading the whole directory is glob (Chapter 17.3), and the sort on it is not cosmetic: Chapter 17.8's rule means two runs of this script on the same logs produce byte-identical output, which is what makes the result diffable against last week's.

5. What To Remember

• Warnings are read all at once, on the day a failure turns out to have been announcing itself.
• Measured: 40 real runs, 100 warnings, 4 IDs — behaving completely differently.
• Count occurrences AND the number of logs containing each ID — two numbers, two questions.
• LATE: 80 occurrences, 40 of 40 logs — 2.0 per run, every run. Background.
• ARBSTALL: 2 occurrences, 2 of 40 logs — rare, and correlated with something.
• A per-run count makes the universal warning look like the problem; a total count makes the rare one look negligible.
• Use a per-log set (6.9) reset for each file, and increment the log count after the file closes.
• Measured: the rarity ranking is the exact inverse of the occurrence ranking.
• So the default count-descending report puts the least interesting warning first and buries the interesting one — misleading, not merely unhelpful.
• 100% means a property of the setup — fix it or waive it explicitly, do not report it every day.
• 5% means correlated with something, and two runs is a readable set.
• The middle band is where degradation hides — 32% today that was 5% last month.
• Rank by rarity; do not threshold on it. A universal warning can be a serious bug and a rare one can be known behaviour.
• Automate the CHANGE, not the judgement: "0 of 40 last week, 2 of 40 today" is a fact a script can own.
• One log cannot distinguish routine from rare — nothing in it records how often the check fires elsewhere.
• A per-test report lists warnings; the regression-level pass groups them (21.11).
• glob the directory and sort it (17.3, 17.8), so the output is diffable against last week's.

Chapter 21.5 turns to the severity that decides the verdict. The useful output for an error is not the count on its own — it is the count plus the first one, with its ID and simulation time, which between them are usually enough to start work without opening the log.