Perl Part II · Module 24 · Coverage and Regression Reporting
Storing One Result Record per Test
Every report in this module — the summary, the mail digest, the CSV, the nightly table, the HTML page, the trend diff — reads the same structure. So the structure is worth getting right once, before anything is printed. This chapter decides what one test's result holds, builds it from a real regression of 36 logs, and measures three ways the obvious code fills it in wrongly while still producing a table that looks entirely reasonable.
Intermediate12 min readPerlPart IIRegression Reporting
Part II · Module 24 · Chapter 24.1 · Storing One Result Record per Test
1. The Record
A regression produces one log per run. A report needs rather less than the log: enough to put a row in a table and enough to find the log again when the row looks wrong. That is five fields.
use strict;
use warnings;
# ---- one record per log. Five fields plus the log path, decided once here
# and read unchanged by every report in this module.
sub read_log {
my ($path) = @_;
my %r = (log => $path, test => undef, seed => undef, verdict => "UNKNOWN",
errors => 0, warnings => 0, simtime => undef, first_id => undef,
naive_errors => 0, complete => 0, budget => 0);
open my $fh, "<", $path or return \%r;
while (my $l = <$fh>) {
$r{test} = $1 if $l =~ /^TEST:\s+(\S+)/;
$r{seed} = $1 if $l =~ /^SEED:\s+(\d+)/;
$r{simtime} = $1 if $l =~ /^SIMTIME:\s+(\d+)/;
$r{budget} = 1 if $l =~ /^UVM_FATAL\s.*\[BUDGET\]/;
# the naive count, for comparison only
$r{naive_errors}++ if $l =~ /^UVM_ERROR/;
# a MESSAGE line carries a file and a line number; the summary line
# does not. That is the whole difference.
if ($l =~ /^UVM_ERROR\s+\S+\(\d+\)/) {
$r{msg_errors}++;
$r{first_id} = $1 if !defined $r{first_id} && $l =~ /\[(\w+)\]/;
}
$r{msg_warnings}++ if $l =~ /^UVM_WARNING\s+\S+\(\d+\)/;
# the summary block is authoritative when the run reached it (21.7)
if ($l =~ /^\*\* Report counts by severity/) { $r{complete} = 1 }
$r{sum_errors} = $1 if $l =~ /^UVM_ERROR\s*:\s*(\d+)/;
$r{sum_warnings} = $1 if $l =~ /^UVM_WARNING\s*:\s*(\d+)/;
$r{verdict} = "PASS" if $l =~ /^TEST PASSED/;
$r{verdict} = "FAIL" if $l =~ /^TEST FAILED/;
}
close $fh;
$r{errors} = $r{complete} ? $r{sum_errors} : ($r{msg_errors} || 0);
$r{warnings} = $r{complete} ? $r{sum_warnings} : ($r{msg_warnings} || 0);
# a verdict is a state, not a count (21.8)
$r{verdict} = "TIMEOUT" if $r{budget} && $r{verdict} eq "UNKNOWN";
return \%r;
}
my @logs = sort glob("logs/*.log");
my @recs = map { read_log($_) } @logs;
printf "logs read: %d\n\n", scalar @logs;
printf "%-18s %-5s %-8s %6s %5s %-8s %-9s %s\n",
"TEST", "SEED", "VERDICT", "ERRS", "WARN", "SIMTIME", "FIRST_ID", "NAIVE";
for my $r (@recs) {
printf "%-18s %-5s %-8s %6d %5d %-8s %-9s %d\n",
$r->{test} // "(none)", $r->{seed} // "-", $r->{verdict},
$r->{errors}, $r->{warnings}, $r->{simtime} // "-",
$r->{first_id} // "-", $r->{naive_errors};
}
# ---- 1. the naive count is wrong, and wrong in the worst direction
print "\n==== counting UVM_ERROR the obvious way ====\n";
my @wrong = grep { $_->{naive_errors} != $_->{errors} } @recs;
printf "runs where the naive count differs: %d of %d\n", scalar @wrong, scalar @recs;
my @false = grep { $_->{errors} == 0 && $_->{naive_errors} > 0 } @recs;
printf "PASSING runs the naive count gives a non-zero error count: %d\n", scalar @false;
printf " %-18s seed %-5s verdict %-5s errors %d, naive %d\n",
$_->{test}, $_->{seed}, $_->{verdict}, $_->{errors}, $_->{naive_errors}
for @false;
print "the line that does it:\n";
open my $g, "<", "logs/arb_smoke.7.log" or die $!;
print " $_" for grep { /^UVM_ERROR/ } <$g>;
close $g;
# ---- 2. the log names the test twice and the names differ
print "\n==== the log carries two names ====\n";
my (%rntst, %testline);
for my $p (@logs) {
open my $fh, "<", $p or next;
while (my $l = <$fh>) {
$rntst{$1}++ if $l =~ /\[RNTST\] Running test (\S+?)\.\.\./;
$testline{$1}++ if $l =~ /^TEST:\s+(\S+)/;
}
close $fh;
}
printf "names on the RNTST line : %d %s\n", scalar keys %rntst,
join " ", sort keys %rntst;
printf "names on the TEST: line : %d\n", scalar keys %testline;
# the nine names wrap, so the block stays inside a narrow reading column
{
my @n = sort keys %testline;
while (@n) { printf " %s\n", join " ", splice @n, 0, 4 }
}
# ---- 3. one record per TEST loses the seeds
print "\n==== keying the hash by test name alone ====\n";
my %by_test;
$by_test{ $_->{test} } = $_ for grep { defined $_->{test} } @recs;
printf "records in %d, keys out %d, runs lost %d\n",
scalar(@recs), scalar(keys %by_test), @recs - keys %by_test;
for my $t (sort keys %by_test) {
my %v;
$v{ $_->{verdict} }++ for grep { ($_->{test} // "") eq $t } @recs;
my $mixed = keys(%v) > 1 ? " <- the four seeds DISAGREE" : "";
printf " %-18s kept %-8s | all seeds: %-22s%s\n",
$t, $by_test{$t}{verdict},
join(",", map { "$_=$v{$_}" } sort keys %v), $mixed;
}
# ---- 4. verdict against error count
print "\n==== is the verdict a function of the error count? ====\n";
my %map;
for my $r (@recs) {
my $k = sprintf "%-9s + %s", $r->{errors} ? "errors>0" : "errors=0",
$r->{complete} ? "summary present" : "no summary";
$map{$k}{ $r->{verdict} }++;
}
for my $k (sort keys %map) {
printf " %s -> %s\n", $k,
join ", ", map { "$_ x$map{$k}{$_}" } sort keys %{ $map{$k} };
}
my @odd = grep { $_->{verdict} eq "TIMEOUT" && $_->{errors} > 0 } @recs;
printf "\nTIMEOUT runs that had already found errors: %d (e.g. %s errors)\n",
scalar @odd, $odd[0] ? $odd[0]{errors} : 0;
print "so a timeout is not 'no result' -- it is a partial result with no verdict\n";logs read: 36
TEST SEED VERDICT ERRS WARN SIMTIME FIRST_ID NAIVE
arb_budget 1 TIMEOUT 777 0 12005 GNT_VEC 777
arb_budget 1234 TIMEOUT 781 0 12005 GNT_VEC 781
arb_budget 42 TIMEOUT 788 0 12005 GNT_VEC 788
arb_budget 7 TIMEOUT 782 0 12005 GNT_VEC 782
arb_light 1 PASS 0 0 325 - 1
arb_light 1234 PASS 0 0 325 - 1
arb_light 42 PASS 0 0 325 - 1
arb_light 7 FAIL 1 0 325 GNT_VEC 2
arb_random 1 FAIL 55 0 4025 GNT_VEC 56
arb_random 1234 FAIL 52 0 4025 GNT_VEC 53
arb_random 42 FAIL 62 0 4025 GNT_VEC 63
arb_random 7 FAIL 62 0 4025 GNT_VEC 63
arb_random_short 1 FAIL 17 0 1025 GNT_VEC 18
arb_random_short 1234 FAIL 12 0 1025 GNT_VEC 13
arb_random_short 42 FAIL 14 0 1025 GNT_VEC 15
arb_random_short 7 FAIL 12 0 1025 GNT_VEC 13
arb_single 1 PASS 0 0 20025 - 1
arb_single 1234 PASS 0 0 20025 - 1
arb_single 42 PASS 0 0 20025 - 1
arb_single 7 PASS 0 0 20025 - 1
arb_smoke 1 PASS 0 0 4025 - 1
arb_smoke 1234 PASS 0 0 4025 - 1
arb_smoke 42 PASS 0 0 4025 - 1
arb_smoke 7 PASS 0 0 4025 - 1
arb_soak 1 FAIL 162 0 4025 GNT_VEC 163
arb_soak 1234 FAIL 164 0 4025 GNT_VEC 165
arb_soak 42 FAIL 159 0 4025 GNT_VEC 160
arb_soak 7 FAIL 161 0 4025 GNT_VEC 162
arb_stress 1 FAIL 251 0 4025 GNT_VEC 252
arb_stress 1234 FAIL 263 0 4025 GNT_VEC 264
arb_stress 42 FAIL 264 0 4025 GNT_VEC 265
arb_stress 7 FAIL 260 0 4025 GNT_VEC 261
arb_trunc 1 FAIL 55 0 4025 GNT_VEC 56
arb_trunc 1234 UNKNOWN 8 0 - GNT_VEC 8
arb_trunc 42 UNKNOWN 8 0 - GNT_VEC 8
arb_trunc 7 UNKNOWN 8 0 - GNT_VEC 8
==== counting UVM_ERROR the obvious way ====
runs where the naive count differs: 29 of 36
PASSING runs the naive count gives a non-zero error count: 11
arb_light seed 1 verdict PASS errors 0, naive 1
arb_light seed 1234 verdict PASS errors 0, naive 1
arb_light seed 42 verdict PASS errors 0, naive 1
arb_single seed 1 verdict PASS errors 0, naive 1
arb_single seed 1234 verdict PASS errors 0, naive 1
arb_single seed 42 verdict PASS errors 0, naive 1
arb_single seed 7 verdict PASS errors 0, naive 1
arb_smoke seed 1 verdict PASS errors 0, naive 1
arb_smoke seed 1234 verdict PASS errors 0, naive 1
arb_smoke seed 42 verdict PASS errors 0, naive 1
arb_smoke seed 7 verdict PASS errors 0, naive 1
the line that does it:
UVM_ERROR : 0
==== the log carries two names ====
names on the RNTST line : 5 light random smoke soak stress
names on the TEST: line : 9
arb_budget arb_light arb_random arb_random_short
arb_single arb_smoke arb_soak arb_stress
arb_trunc
==== keying the hash by test name alone ====
records in 36, keys out 9, runs lost 27
arb_budget kept TIMEOUT | all seeds: TIMEOUT=4
arb_light kept FAIL | all seeds: FAIL=1,PASS=3 <- the four seeds DISAGREE
arb_random kept FAIL | all seeds: FAIL=4
arb_random_short kept FAIL | all seeds: FAIL=4
arb_single kept PASS | all seeds: PASS=4
arb_smoke kept PASS | all seeds: PASS=4
arb_soak kept FAIL | all seeds: FAIL=4
arb_stress kept FAIL | all seeds: FAIL=4
arb_trunc kept UNKNOWN | all seeds: FAIL=1,UNKNOWN=3 <- the four seeds DISAGREE
==== is the verdict a function of the error count? ====
errors=0 + summary present -> PASS x11
errors>0 + no summary -> TIMEOUT x4, UNKNOWN x3
errors>0 + summary present -> FAIL x18
TIMEOUT runs that had already found errors: 4 (e.g. 777 errors)
so a timeout is not 'no result' -- it is a partial result with no verdictFigure 24.1.1 — One log in, one record out, every report downstream
The log path is a field. A report row that says a test failed and does not say where to look is a row that generates a question instead of answering one.
2. The Obvious Error Counter Is Wrong
runs where the naive count differs: 29 of 36
PASSING runs the naive count gives a non-zero error count: 11
arb_smoke seed 7 verdict PASS errors 0, naive 1
the line that does it:
UVM_ERROR : 0/^UVM_ERROR/ matches the summary line. The report block at the end of every completed run prints UVM_ERROR : 0, and that line begins with UVM_ERROR just as a real error message does. So the obvious counter returns 1 for a run with no errors, measured on all eleven passing runs.
It is worth being precise about why this particular mistake survives review: the count is wrong by one, on exactly the runs nobody investigates. A failing test with 56 errors reported as 57 changes no decision. A passing test reported as having one error is the row that makes someone open a clean log.
Two fixes, and the second is better:
Match a message, not a count. A message line carries a file and a line number; the summary line does not.
$errors++ if $l =~ /^UVM_ERROR\s+\S+\(\d+\)/;Or read the total the tool already computed (21.7), which is authoritative because the simulator counted it:
$sum_errors = $1 if $l =~ /^UVM_ERROR\s*:\s*(\d+)/;The record uses the summary when the run reached it and falls back to counting messages when it did not — which is the only sensible rule, because an incomplete log has no summary to read and a complete one has no reason to be recounted. Chapter 18.4 met the same hazard with a one-line shell check that reported errors in 40 of 40 logs.
3. The Log Names The Test Twice
names on the RNTST line : 5 light random smoke soak stress
names on the TEST: line : 9 arb_budget arb_light arb_random arb_random_short
arb_single arb_smoke arb_soak arb_stress arb_truncNine tests, five names. The first line of each log says Running test smoke..., and that is the stimulus profile; several tests share one. The regression's own name for the run is on the TEST: line.
Take the name from the first line that looks like a name and the nine-row table becomes a five-row table, with four tests silently merged into their profile-mates. Nothing errors. The report is just wrong about what ran, and it is wrong in a way that looks tidier than the truth.
The rule is the one from Chapter 21.1: decide which line is authoritative for each field, and say so in the code. A comment naming the line you chose is worth more here than any amount of defensive matching.
4. Keying By Test Name Loses The Seeds
The registry's own description of this chapter says a hash keyed by test name — and with four seeds per test, that is exactly where the structure starts to hurt:
records in 36, keys out 9, runs lost 27
arb_light kept FAIL | all seeds: FAIL=1,PASS=3 <- the four seeds DISAGREE
arb_trunc kept UNKNOWN | all seeds: FAIL=1,UNKNOWN=3 <- the four seeds DISAGREETwenty-seven of thirty-six runs vanish, because $by_test{$t} = $rec overwrites. Seven of the nine tests survive that intact, since their four seeds agree. Two do not, and the worse of the two is arb_light: three of its four seeds passed, one failed, and the surviving record says FAIL. Had the sort order differed it would have said PASS with the same confidence. arb_trunc is the same shape — one run reached a verdict and three were cut short — and reports a verdict that one run in four contradicts.
This is not an argument against keying by test. It is an argument for being deliberate about what one key means:
One record per run — key "$test.$seed" — keeps everything and is what the raw layer should hold.
One record per test — a list of runs under each test name — is what a report wants, and it is Chapter 24.2's subject.
What you must not have is one record per test pretending to be one record per run. That structure answers "did arb_light pass" with a straight face and no indication that three quarters of the evidence was discarded.
5. The Verdict Is Not A Function Of The Counts
errors=0 + summary present -> PASS x11
errors>0 + summary present -> FAIL x18
errors>0 + no summary -> TIMEOUT x4, UNKNOWN x3The first two rows are a clean function. The third is not: the same combination of facts produces both TIMEOUT and UNKNOWN, so no amount of counting distinguishes them. What separates them is a different fact entirely — whether the log contains the budget message. That is Chapter 21.8's ladder, and it is why verdict is a stored field rather than something each report recomputes.
And one number is worth staring at:
TIMEOUT runs that had already found errors: 4 (777 of them in one)A timeout is not an absent result. That run found 777 real errors before it was stopped. Treating TIMEOUT as "no information" throws away a genuine failure; treating it as FAIL claims the test completed when it did not. It is its own state, with real counts attached, which is exactly why the record carries the verdict and the counts as separate fields.
6. What To Remember
- Decide the record once. Every report in this module reads the same five fields: verdict, error count, warning count, seed and simulated time, plus the log path.
- The log path is a field — a failing row that cannot be traced back to a run is a question, not an answer.
- Measured:
/^UVM_ERROR/matched the summary lineUVM_ERROR : 0, reporting 1 error on all 11 passing runs and differing from the truth on 29 of 36. - It is wrong on exactly the runs nobody investigates — a clean pass showing one error is the row that wastes someone's morning.
- Match a message, not a count:
^UVM_ERROR\s+\S+\(\d+\)— a message carries a file and line, the summary line does not. - Better: read the total the tool already counted (21.7), and fall back to counting messages only when the run never reached its summary.
- Measured: 9 tests but only 5 names on the RNTST line — that line carries the stimulus profile, not the test name.
- Decide which line is authoritative per field, and say so in a comment (21.1).
- Measured: keying by test name alone took 36 records to 9 keys and lost 27 runs, silently.
- Two tests' seeds disagreed, and
arb_lightcame out FAIL although three of its four seeds PASSED — the opposite answer was equally available. - Key by
"$test.$seed"for the raw layer; group by test for reports (24.2). - The verdict is not a function of the counts — "errors>0, no summary" covers both TIMEOUT and UNKNOWN, so verdict is a stored field (21.8).
- Measured: a TIMEOUT run had already found 777 errors. A timeout is a partial result, not an absent one.
Chapter 24.2 keeps all thirty-six runs. Once a test can have several results, two different questions appear — did this test ever fail, and how many of its seeds failed — and they have different answers.
Where this fits
Part of the Perl curriculum.