Did the Test Even Finish?

Part II · Module 21 · Chapter 21.2 · Did the Test Even Finish?

1. Five Logs, Two Verdict Rules

Four of these logs are real runs of the same testbench on this machine; the crash log is one of those runs truncated mid-flight on purpose, which is exactly what a killed simulator leaves behind.

use strict;
use warnings;

# Five logs. Four are real Icarus runs of tb/uvm_style_tb.v (pass, errors,
# fatal, and crash -- the crash log is a real run truncated mid-flight on
# purpose). timeout.log is a real partial run plus a runinfo file, because a
# TIMEOUT cannot be established from the log alone -- see section 4.
my @LOGS = qw(pass errors fatal crash timeout);

my $SUMMARY_COUNT = qr/^(?:#\s*)?UVM_\w+\s*:\s*\d+\s*$/;   # 18.4
my @FINISH = (
  qr/^(?:#\s*)?\$finish\b/,
  qr/^\$finish at simulation time/,
  qr/^Simulation complete via \$finish/,
  qr/^#\s*\*\* Note: \$finish/,
);

sub read_log {
    my ($name) = @_;
    my $file = "logs/$name.log";
    return (missing => 1) unless -e $file;
    return (empty   => 1) if     -z $file;
    open my $fh, "<", $file or return (unreadable => 1);
    my %r = (lines => 0, err => 0, fatal => 0, warn => 0, finish => 0, summary => 0);
    while (my $l = <$fh>) {
        $r{lines}++;
        $r{summary} = 1 if $l =~ /^(?:#\s*)?--- UVM Report Summary ---/;
        next if $l =~ $SUMMARY_COUNT;
        $r{err}++   if $l =~ /^(?:#\s*)?UVM_ERROR\b/;
        $r{fatal}++ if $l =~ /^(?:#\s*)?UVM_FATAL\b/;
        $r{warn}++  if $l =~ /^(?:#\s*)?UVM_WARNING\b/;
        for my $f (@FINISH) { $r{finish} = 1 if $l =~ $f }
    }
    close $fh;
    return %r;
}

# ---- A: the verdict almost everybody writes first
sub verdict_naive {
    my (%r) = @_;
    return "PASS" if ($r{err} // 0) == 0 && ($r{fatal} // 0) == 0;
    return "FAIL";
}

# ---- B: ask whether the run finished BEFORE counting anything
sub verdict_finish_first {
    my (%r) = @_;
    return "NO_LOG"     if $r{missing};
    return "EMPTY_LOG"  if $r{empty};
    return "UNREADABLE" if $r{unreadable};
    return "NO_FINISH"  unless $r{finish};
    return "FAIL"       if ($r{fatal} // 0) > 0 || ($r{err} // 0) > 0;
    return "PASS";
}

printf "%-10s %-7s %-7s %-7s %-9s %-9s %-11s %s\n",
    "LOG", "lines", "errors", "fatals", "summary?", "finish?", "A verdict", "B verdict";
my (%A, %B);
for my $n (@LOGS) {
    my %r = read_log($n);
    $A{$n} = verdict_naive(%r);
    $B{$n} = verdict_finish_first(%r);
    printf "%-10s %-7s %-7s %-7s %-9s %-9s %-11s %s\n", $n,
        ($r{lines} // "-"), ($r{err} // "-"), ($r{fatal} // "-"),
        ($r{summary} ? "yes" : "no"), ($r{finish} ? "yes" : "NO"),
        $A{$n}, $B{$n};
}

print "\nwhat the truth is for each log:\n";
my %TRUTH = (pass => "PASS", errors => "FAIL", fatal => "FAIL",
             crash => "did not finish", timeout => "did not finish");
printf "  %-10s truth=%-16s A says %-6s %s\n", $_, $TRUTH{$_}, $A{$_},
    ($A{$_} eq "PASS" && $TRUTH{$_} ne "PASS" ? "<-- FALSE PASS" : "")
    for @LOGS;

my $false = grep { $A{$_} eq "PASS" && $TRUTH{$_} ne "PASS" } @LOGS;
printf "\npattern A produced %d FALSE PASSES out of %d logs\n", $false, scalar @LOGS;
print "both are runs that never reached the end, and neither contains a\n";
print "single UVM_ERROR -- which is exactly why counting errors says PASS.\n";

LOG        lines   errors  fatals  summary?  finish?   A verdict   B verdict
pass       16      0       0       yes       yes       PASS        PASS
errors     20      3       0       yes       yes       FAIL        FAIL
fatal      20      3       1       yes       yes       FAIL        FAIL
crash      6       0       0       no        NO        PASS        NO_FINISH
timeout    6       0       0       no        NO        PASS        NO_FINISH

what the truth is for each log:
  pass       truth=PASS             A says PASS   
  errors     truth=FAIL             A says FAIL   
  fatal      truth=FAIL             A says FAIL   
  crash      truth=did not finish   A says PASS   <-- FALSE PASS
  timeout    truth=did not finish   A says PASS   <-- FALSE PASS

pattern A produced 2 FALSE PASSES out of 5 logs
both are runs that never reached the end, and neither contains a
single UVM_ERROR -- which is exactly why counting errors says PASS.

Two false passes out of five. And they are not marginal cases — they are the two logs anybody would most want flagged.

2. Why A Crashed Run Contains No Errors

Read the crash and timeout rows: errors 0, fatals 0, summary? no, finish? NO.

The reason counting errors fails here is not that it counts badly. It is that there is nothing to count. A simulator that is killed — by the queue, by a segmentation fault, by a licence timeout, by somebody's kill — stops printing. It does not print an error on the way out. It does not get to the report summary. The log simply ends.

So the evidence for a crashed run is the absence of a line, and no amount of looking for the presence of one will find it. That is the whole chapter, and it is the same argument Chapter 18.9 made about a truncated tool log, moved from a synthesis report to a simulation transcript.

Three absences, each meaning something slightly different:

No finish marker — the run did not reach the end of the testbench. Crash, kill, timeout.

No report summary — UVM's end-of-test reporting never ran. Usually the same cause, and worth tracking separately because a run can finish without the summary if the testbench calls $finish outside the UVM phasing.

No log at all, or a zero-byte log — the job never started. A licence failure, a bad path, a full disk.

Chapter 18.9 measured that last pair and it holds here unchanged: test -e before -z, because -z is false for a file that does not exist.

3. The Order Of The Tests Is Not Style

The corrected verdict asks its questions in one specific order:

return "NO_LOG"     if $r{missing};
return "EMPTY_LOG"  if $r{empty};
return "UNREADABLE" if $r{unreadable};
return "NO_FINISH"  unless $r{finish};
return "FAIL"       if ($r{fatal} // 0) > 0 || ($r{err} // 0) > 0;
return "PASS";

Each line depends on every line above it having already returned:

Existence before emptiness, because -z on a missing file is false and would send it down the "has content" path.

Readability before reading, because the counts are meaningless if the file could not be opened — and Chapter 13.5's or die is the wrong response in a batch job that has four hundred other logs to process.

Completion before counting. This is the one that matters. FAIL and PASS are both statements about a run that happened; asking them of a run that did not happen produces a confident answer to the wrong question.

PASS last, and only by elimination. Not a condition that can be met — a conclusion reached when nothing else applied. Written the other way round, as return "PASS" if $err == 0, it becomes a condition that a crashed log satisfies.

4. What The Log Cannot Tell You

crash and timeout get the same verdict from the parser — NO_FINISH — and they are different problems with different owners. The log cannot separate them, and it is worth being precise about why.

Both logs end mid-run with no marker. Byte for byte, a log cut off by a segmentation fault and one cut off by a queue limit have the same shape. Chapter 18.9 measured the identical situation for a tool log and reached the identical conclusion: the difference is not in the file.

What separates them is evidence from outside the log, which is why this module's fixture carries a runinfo file beside each one:

wall_seconds=7201
limit_seconds=7200
killed_by=queue

Three facts the log does not have: how long the job ran, what it was allowed, and what killed it. With them, NO_FINISH splits into TIMEOUT (ran to its limit) and CRASH (died early), which is Chapter 21.8's four-way verdict.

Where that information comes from in practice:

The queue. bjobs -l, sacct, qstat -f — whatever the site uses — knows the wall time and the exit reason, and it is the authoritative source.

The job wrapper. If the flow script that launched the simulator records a start and end timestamp and the exit status, you have it without querying anything. This is the cheapest option and the one most worth building.

The file's own mtime, as a last resort — Chapter 17.9's -M, with its two measured surprises: it is relative to $^T rather than to now, and it is a named unary operator whose precedence silently breaks int(-M $f + 0.5).

Say which source you used. TIMEOUT (wall 7201s of 7200s, per the queue) is a sentence somebody can act on; TIMEOUT alone invites the question you have already answered.

5. What To Remember

• Ask whether the run finished before counting anything.
• Measured, five logs: counting errors gives 2 false passes — on the crash and the timeout.
• A crashed run contains zero errors, so there is nothing for an error count to find.
• The evidence is the absence of a line, not the presence of one.
• Three distinct absences: no finish marker, no report summary, no log at all.
• A run can finish without a summary if $finish is called outside UVM phasing — track them separately.
• -e before -z (18.9): -z is false for a file that does not exist.
• The error-counting rule is correct on every healthy log, which is why it survives and why it has never been tested.
• A rule that is right whenever the input is healthy is untested, not verified — feed it a broken input on purpose.
• The order of the tests is load-bearing: existence, emptiness, readability, completion, then severity.
• PASS is a conclusion by elimination, never a condition — written as if $err == 0 it is satisfied by a crashed log.
• Guard the counts with // 0 (3.8), or a missing log prints an uninitialized warning to stderr that nobody reads (20.3).
• A crash and a timeout are byte-identical in the log — the difference is not in the file (18.9).
• Separating them needs outside evidence: the queue, a job wrapper's own timing record, or -M as a last resort (17.9).
• Record wall time and exit reason in the job wrapper — the cheapest reliable source.
• Name the source in the verdict: "TIMEOUT (wall 7201s of 7200s, per the queue)".

Chapter 21.3 starts on the UVM content itself, with the severity that makes up almost all of a log's volume and almost none of its information — and the problem of finding the handful of UVM_INFO lines that actually matter.