Perl Part II · Module 29 · Practical VLSI Automation Projects
Project: Simulation Log Triage Tool
Every morning after a nightly regression, somebody has to turn a pile of failing logs into a short list of problems — which failures are the same bug, which are new, and where to start reading. Module 21 built every piece of that: the verdict, the first error, the signature and the excerpt. This project assembles them into the tool a verification lead runs first, runs it on eighty real simulation logs, and deals with the failures that a log-based tool cannot see on its own — a run that never wrote a log at all.
Advanced22 min readPerlPart IIProjectsSimulation Logs
Part II · Module 29 · Chapter 29.5 · Project: Simulation Log Triage Tool
1. The Brief
| Command | triage.pl LOG... [--group-by MODE] [--top N] [--examples N] [--expect LIST], where MODE is signature (the default) or id |
| Reads | one simulation log per run; a run is named by the directory above logs/ |
| Writes | STDOUT: verdict counts, then the failure groups — biggest first — each with its size, example runs and an excerpt around the first error of its first run |
| Exit 0 | every run passed |
| Exit 1 | failing runs were triaged |
| Exit 2 | an input problem: a log path that does not exist (often an unmatched glob), or two logs for one run |
| Exit 3 | usage error |
The tool assembles Module 21 and adds what an assembly needs:
- Deciding PASS, FAIL, TIMEOUT or UNKNOWN — verdict rules as an ordered table (21.8).
- Classifying failures by signature — normalise the values, keep the shape and the ID (21.9).
- First-error excerpt and triage context — a bounded excerpt with line numbers (21.10).
- Did the test even finish? — no report summary means the run did not finish (21.2).
- Collecting results when some jobs never return — every planned run gets a verdict, including the ones that left no log (25.7).
2. Eighty Real Logs
UVM cannot run on this toolchain, so — exactly as Module 21 did — the testbench prints UVM-shaped report lines itself. The logs are real Icarus output. Which failures a run shows depends on its seed, and the values inside each message — addresses, data, cycle numbers — change with the seed, which is what makes raw error texts useless for grouping.
// tb_regress.v -- a testbench that prints UVM-SHAPED report lines, so the
// logs this chapter triages are real simulator output. It is NOT UVM (UVM
// cannot run on this toolchain); the line layout follows the usual
// uvm_report_server shape, which is what a log parser sees.
//
// +TEST=name +SEED=n which failures appear depends on k, which is the
// seed for alu_smoke and the seed plus 3 for alu_burst:
// k % 5 == 0 SCBD data mismatch (values vary with the seed)
// k % 7 == 0 PROTO request while busy
// k % 11 == 0 SCBD response timeout (same ID as the mismatch,
// a different problem)
// k % 13 == 0 AXI 4KB boundary, then UVM_FATAL
// k % 17 == 0 the run dies: no report summary is printed
`timescale 1ns/1ps
module tb_regress;
integer seed, k, n_info, n_warn, n_err, n_fatal;
reg [8*24-1:0] test;
task summary;
begin
$display("--- UVM Report Summary ---");
$display("");
$display("** Report counts by severity");
$display("UVM_INFO :%5d", n_info);
$display("UVM_WARNING :%5d", n_warn);
$display("UVM_ERROR :%5d", n_err);
$display("UVM_FATAL :%5d", n_fatal);
$display("$finish called from file \"tb/tb_regress.v\" line 0.");
end
endtask
initial begin
n_info = 0; n_warn = 0; n_err = 0; n_fatal = 0;
if (!$value$plusargs("TEST=%s", test)) test = "alu_smoke";
if (!$value$plusargs("SEED=%d", seed)) seed = 1;
k = (test == "alu_burst") ? seed + 3 : seed;
$display("UVM_INFO @ 0: reporter [RNTST] Running test %0s...", test);
#10 $display("UVM_INFO tb/tb_regress.v(40) @ %0t: uvm_test_top.env [CFG] seed=%0d", $time, seed);
n_info = n_info + 1;
#10 $display("UVM_INFO tb/tb_regress.v(42) @ %0t: uvm_test_top.env [PHASE] main_phase begin", $time);
n_info = n_info + 1;
if (k % 5 == 0) begin
#10 $display("UVM_ERROR tb/tb_regress.v(46) @ %0t: uvm_test_top.env.scbd [SCBD] data mismatch exp=%08x got=%08x addr=0x%08x",
$time, seed * 2654435, seed * 40503, seed * 64);
n_err = n_err + 1;
end
if (k % 7 == 0) begin
#10 $display("UVM_ERROR tb/tb_regress.v(51) @ %0t: uvm_test_top.env.drv [PROTO] req asserted while busy at cycle %0d",
$time, seed * 3 + 17);
n_err = n_err + 1;
end
if (k % 11 == 0) begin
#10 $display("UVM_ERROR tb/tb_regress.v(56) @ %0t: uvm_test_top.env.scbd [SCBD] no response for tag %0d after %0d cycles",
$time, seed % 16, 1000);
n_err = n_err + 1;
end
if (k % 17 == 0) begin
#10 $display("UVM_INFO tb/tb_regress.v(61) @ %0t: uvm_test_top.env [PHASE] main_phase executing", $time);
$finish; // dies: no summary, no report counts
end
if (k % 13 == 0) begin
#10 $display("UVM_ERROR tb/tb_regress.v(65) @ %0t: uvm_test_top.env.axi [AXI] burst crossed a 4KB boundary at addr=0x%08x",
$time, seed * 4096 - 4);
n_err = n_err + 1;
#10 $display("UVM_FATAL tb/tb_regress.v(68) @ %0t: uvm_test_top.env.axi [AXI] cannot continue after illegal burst", $time);
n_fatal = n_fatal + 1;
summary;
$finish;
end
#10 $display("UVM_INFO tb/tb_regress.v(74) @ %0t: uvm_test_top.env [PHASE] main_phase end", $time);
n_info = n_info + 1;
summary;
$finish;
end
endmoduleTwo failure types share the ID SCBD on purpose: a data mismatch and a response timeout. They are different problems with different fixes, and section 6 uses them to show what grouping by ID alone gets wrong. Crash mode stops without printing the report summary, standing in for a simulator that died mid-run. Icarus still prints its own $finish called line, which is precisely why the tool takes the summary, not that line, as evidence of a clean end.
run_regression.sh simulates two tests over forty seeds each and keeps the logs where a regression would.
#!/bin/bash
# run_regression.sh DIR -- simulate two tests x 40 seeds, one log per run,
# laid out the way a regression keeps them: DIR/<test>_s<seed>/logs/sim.log
set -u
out=${1:?usage: run_regression.sh DIR}
iverilog -o regress.vvp tb/tb_regress.v || exit 1
for test in alu_smoke alu_burst; do
for seed in $(seq 1 40); do
mkdir -p "$out/${test}_s$seed/logs"
vvp -n regress.vvp +TEST=$test +SEED=$seed > "$out/${test}_s$seed/logs/sim.log"
done
done
rm -f regress.vvpA note on checking the result by hand. My first quick count of failing runs used grep -c '^UVM_ERROR' and reported 70 failures and 0 passes. Every log ends with the summary line UVM_ERROR : 0, which that pattern matches. It is the trap Chapter 18.4 described and Chapter 21.1 measured, caught in a one-liner written while preparing this chapter. The tool avoids it because a message must carry an [ID].
3. The Design
Figure 29.5.1 — From eighty logs to five causes
Each log is read once. One pass collects the counts, whether the summary appeared, the first error with two lines of context on each side, and — for a run that never errored — its last two lines. A verification lead's regression can hold thousands of logs, and reading each one twice is the first thing that makes a triage tool slow.
The group key is the verdict and the signature together. A FATAL and a FAIL with the same first error are different situations — one stopped the test — so they are kept apart.
4. The Tool
#!/usr/bin/perl
# triage.pl -- turn a directory of failing simulation logs into a short list
# of failure signatures: how many runs each, which runs, and the first error
# of the first run in context.
use strict;
use warnings;
use Getopt::Long qw(GetOptions);
use File::Basename qw(dirname basename);
use constant { ALL_PASS => 0, FAILURES => 1, INPUT => 2, USAGE => 3 };
my %opt = ("group-by" => "signature", top => 10, examples => 3);
GetOptions(\%opt, "group-by=s", "top=i", "examples=i", "expect=s", "help")
or usage("bad option");
usage() if $opt{help};
usage("--group-by must be signature or id") unless $opt{"group-by"} =~ /^(?:signature|id)\z/;
usage("--top and --examples must be at least 1") if $opt{top} < 1 || $opt{examples} < 1;
fail(INPUT, "no log files given") unless @ARGV;
# A run is named by the directory above logs/: runs/alu_smoke_s5/logs/sim.log
sub run_name { my $d = dirname($_[0]); $d = dirname($d) if basename($d) eq "logs"; return basename($d) }
# Natural order: alu_smoke_s2 before alu_smoke_s10.
sub natural { my @x = split /(\d+)/, $a; my @y = split /(\d+)/, $b;
while (@x && @y) { my ($p, $q) = (shift @x, shift @y);
my $c = ($p =~ /^\d+\z/ && $q =~ /^\d+\z/) ? $p <=> $q : $p cmp $q;
return $c if $c }
return @x <=> @y }
# The verdict rules, IN ORDER: the first that matches decides.
my @RULES = (
[ NO_LOG => sub { !$_[0]{exists} } ],
[ EMPTY => sub { $_[0]{size} == 0 } ],
[ FATAL => sub { $_[0]{fatals} > 0 } ],
[ CRASH => sub { !$_[0]{summary} } ],
[ FAIL => sub { $_[0]{errors} > 0 } ],
[ PASS => sub { 1 } ],
);
# ---- which runs: every log given, plus every expected run with no log
my (%log_of, @problems);
for my $log (@ARGV) {
unless (-e $log) { # an unmatched shell glob arrives here as literal text
push @problems, $log =~ /[*?\[]/ ? "no file matches $log (an unmatched glob?)"
: "no such log: $log";
next;
}
my $run = run_name($log);
push @problems, "two logs for run $run: $log_of{$run} and $log" if $log_of{$run};
$log_of{$run} = $log;
}
if (defined $opt{expect}) {
open my $fh, "<", $opt{expect} or fail(INPUT, "cannot read --expect $opt{expect}: $!");
while (<$fh>) { s/\s+\z//; next unless length; $log_of{$_} //= undef }
}
if (@problems) { print STDERR "triage.pl: $_\n" for @problems; fail(INPUT, "nothing triaged") }
# ---- read each log once: counts, completion, the first error and its context
my %run;
for my $name (sort natural keys %log_of) {
my $log = $log_of{$name};
my %r = (name => $name, log => $log, exists => defined $log && -e $log,
errors => 0, fatals => 0, summary => 0, size => 0);
if ($r{exists}) {
$r{size} = -s $log;
open my $fh, "<", $log or fail(INPUT, "cannot read $log: $!");
my (@before, $after);
while (my $line = <$fh>) {
chomp $line;
$r{summary} = 1 if $line =~ /^--- UVM Report Summary ---/;
# a message needs an [ID]: that is what keeps the summary's own
# "UVM_ERROR : 0" count lines from being counted as errors
if ($line =~ /^(UVM_ERROR|UVM_FATAL)\b.*?\[(\w+)\]\s*(.*)$/) {
$1 eq "UVM_ERROR" ? $r{errors}++ : $r{fatals}++;
if (!defined $r{first}) {
@r{qw(first id msg line)} = ($line, $2, $3, $.);
$r{excerpt} = [ @before, [ $., $line, 1 ] ];
$after = 2;
next;
}
}
if (defined $after && $after > 0) { push @{ $r{excerpt} }, [ $., $line, 0 ]; $after-- }
push @before, [ $., $line, 0 ];
shift @before if @before > 2; # a ring of the last two lines
$r{tail} = [ @before ];
}
close $fh;
$r{excerpt} //= $r{tail}; # no error: show where it stopped
}
($r{verdict}) = map { $_->[0] } grep { $_->[1]->(\%r) } @RULES;
$run{$name} = \%r;
}
# ---- signature: the shape of the first error, with its values taken out
sub signature {
my ($r) = @_;
return "log never written" if $r->{verdict} eq "NO_LOG";
return "log is empty" if $r->{verdict} eq "EMPTY";
return "ended without a report summary, no error before it" unless defined $r->{id};
return $r->{id} if $opt{"group-by"} eq "id";
(my $m = $r->{msg}) =~ s/0x[0-9a-fA-F]+/0xHEX/g;
$m =~ s/\b(?=[0-9a-fA-F]*\d)[0-9a-fA-F]{6,}\b/HEX/g;
$m =~ s/\b\d+\b/N/g;
return "$r->{id}: $m";
}
my %group;
for my $r (grep { $_->{verdict} ne "PASS" } map { $run{$_} } sort natural keys %run) {
push @{ $group{"$r->{verdict} " . signature($r)} }, $r;
}
# ---- the report: biggest group first, ties by name, so the order is fixed
my %n;
$n{ $_->{verdict} }++ for values %run;
printf "triaged %d run(s): %s\n", scalar keys %run,
join(", ", map { "$_ " . ($n{$_} // 0) } map { $_->[0] } @RULES);
print " missing runs cannot be detected without --expect\n" unless defined $opt{expect};
my @keys = sort { @{ $group{$b} } <=> @{ $group{$a} } or $a cmp $b } keys %group;
my $failing = 0;
$failing += @{ $group{$_} } for @keys;
my %texts = map { (defined $_->{msg} ? "[$_->{id}] $_->{msg}" : $_->{verdict}) => 1 }
grep { $_->{verdict} ne "PASS" } values %run;
printf "failing runs: %d, in %d group(s) by %s (%d distinct first-error texts before normalising)\n",
$failing, scalar @keys, $opt{"group-by"}, scalar keys %texts;
my $shown = @keys < $opt{top} ? @keys : $opt{top};
for my $i (0 .. $shown - 1) {
my @runs = @{ $group{ $keys[$i] } };
my @ex = map { $_->{name} } @runs[0 .. ($#runs < $opt{examples} - 1 ? $#runs : $opt{examples} - 1)];
printf "\n#%d %d run(s) %s\n", $i + 1, scalar @runs, $keys[$i];
printf " runs: %s%s\n", join(", ", @ex), @runs > @ex ? sprintf(" (+%d more)", @runs - @ex) : "";
my $first = $runs[0];
next unless $first->{excerpt} && @{ $first->{excerpt} };
printf " %s:\n", $first->{log};
printf " %s %3d | %s\n", ($_->[2] ? ">" : " "), $_->[0], $_->[1] for @{ $first->{excerpt} };
}
if (@keys > $shown) {
my $rest = 0;
$rest += @{ $group{ $keys[$_] } } for $shown .. $#keys;
printf "\n(%d more group(s) with %d run(s); use --top)\n", @keys - $shown, $rest;
}
exit($failing ? FAILURES : ALL_PASS);
sub usage {
my ($why) = @_;
print STDERR "triage.pl: $why\n" if $why;
print STDERR <<'END';
usage: triage.pl LOG... [--group-by signature|id] [--top N] [--examples N] [--expect LIST]
--expect LIST a file naming every run that should exist; a run with no
log is then reported as NO_LOG instead of being invisible
exit: 0 every run passed; 1 failing runs triaged; 2 input problem; 3 usage
END
exit($why ? USAGE : ALL_PASS);
}
sub fail { my ($code, $msg) = @_; print STDERR "triage.pl: $msg\n"; exit $code }The verdict is an ordered table
my @RULES = (
[ NO_LOG => sub { !$_[0]{exists} } ],
[ EMPTY => sub { $_[0]{size} == 0 } ],
[ FATAL => sub { $_[0]{fatals} > 0 } ],
[ CRASH => sub { !$_[0]{summary} } ],
[ FAIL => sub { $_[0]{errors} > 0 } ],
[ PASS => sub { 1 } ],
);This is Chapter 21.8's design: rules as data, the first match decides, and the order is the rule. FATAL before FAIL matters on every fatal run here, because each one logged an error before its fatal. CRASH before FAIL means that a run which errored and then died is reported as a crash — its error count is incomplete, so it cannot be judged by it.
A message needs an ID
# a message needs an [ID]: that is what keeps the summary's own
# "UVM_ERROR : 0" count lines from being counted as errors
if ($line =~ /^(UVM_ERROR|UVM_FATAL)\b.*?\[(\w+)\]\s*(.*)$/) {An earlier version of the tool also had a line that skipped the summary's count lines explicitly. It was removed: the [ID] in the pattern already excludes them, so the extra line could never change the result, and a line that cannot change the result cannot be tested.
The signature takes out values and keeps the shape
(my $m = $r->{msg}) =~ s/0x[0-9a-fA-F]+/0xHEX/g;
$m =~ s/\b(?=[0-9a-fA-F]*\d)[0-9a-fA-F]{6,}\b/HEX/g;
$m =~ s/\b\d+\b/N/g;Three substitutions, in order: prefixed hex, then long bare hex words that contain a digit (the lookahead keeps an ordinary word like accede intact), then decimal numbers. The price of the lookahead is real: a bare value made only of the letters a to f, such as deadbeef, also has no digit and is kept as text. Prefixed with 0x it is normalised by the first rule. The ID stays at the front, so two different IDs can never share a signature — Chapter 21.9's rule.
The order of groups and of examples is fixed
my @keys = sort { @{ $group{$b} } <=> @{ $group{$a} } or $a cmp $b } keys %group;Groups are ordered by size, and groups of equal size by name — two groups of six appear here, and without the tie-break their order would follow the hash order of the process. Inside a group, runs are listed in natural order, which the next block shows is not what sort does.
#!/bin/bash
# order.sh -- the same five run names, sorted two ways.
perl -e '
my @runs = qw(alu_burst_s2 alu_burst_s12 alu_burst_s7 alu_burst_s30 alu_burst_s19);
sub natural { my @x = split /(\d+)/, $a; my @y = split /(\d+)/, $b;
while (@x && @y) { my ($p, $q) = (shift @x, shift @y);
my $c = ($p =~ /^\d+\z/ && $q =~ /^\d+\z/) ? $p <=> $q : $p cmp $q;
return $c if $c }
return @x <=> @y }
print "sort: ", join(" ", sort @runs), "\n";
print "sort natural: ", join(" ", sort natural @runs), "\n";
'sort: alu_burst_s12 alu_burst_s19 alu_burst_s2 alu_burst_s30 alu_burst_s7
sort natural: alu_burst_s2 alu_burst_s7 alu_burst_s12 alu_burst_s19 alu_burst_s30sort compares characters, so s12 comes before s2. An engineer scanning a list of seeds reads numbers, and the natural sort splits each name into text and number pieces and compares the numbers as numbers.
5. Running It
#!/bin/bash
# demo.sh -- simulate the regression, then triage every log it left.
bash run_regression.sh runs || exit 1
echo "$(ls runs | wc -l | tr -d ' ') run directories, e.g. $(ls runs | head -3 | tr '\n' ' ')"
echo
perl triage.pl runs/*/logs/sim.log --group-by signature --top 10
echo "exit $?"
echo
echo "== the same logs, grouped by message ID only"
perl triage.pl runs/*/logs/sim.log --group-by id | grep -E '^(failing|#)'80 run directories, e.g. alu_burst_s1 alu_burst_s10 alu_burst_s11
triaged 80 run(s): NO_LOG 0, EMPTY 0, FATAL 6, CRASH 4, FAIL 31, PASS 39
missing runs cannot be detected without --expect
failing runs: 41, in 5 group(s) by signature (38 distinct first-error texts before normalising)
#1 16 run(s) FAIL SCBD: data mismatch exp=HEX got=HEX addr=0xHEX
runs: alu_burst_s2, alu_burst_s7, alu_burst_s12 (+13 more)
runs/alu_burst_s2/logs/sim.log:
2 | UVM_INFO tb/tb_regress.v(40) @ 10000: uvm_test_top.env [CFG] seed=2
3 | UVM_INFO tb/tb_regress.v(42) @ 20000: uvm_test_top.env [PHASE] main_phase begin
> 4 | UVM_ERROR tb/tb_regress.v(46) @ 30000: uvm_test_top.env.scbd [SCBD] data mismatch exp=005101c6 got=00013c6e addr=0x00000080
5 | UVM_INFO tb/tb_regress.v(74) @ 40000: uvm_test_top.env [PHASE] main_phase end
6 | --- UVM Report Summary ---
#2 9 run(s) FAIL PROTO: req asserted while busy at cycle N
runs: alu_burst_s4, alu_burst_s11, alu_burst_s18 (+6 more)
runs/alu_burst_s4/logs/sim.log:
2 | UVM_INFO tb/tb_regress.v(40) @ 10000: uvm_test_top.env [CFG] seed=4
3 | UVM_INFO tb/tb_regress.v(42) @ 20000: uvm_test_top.env [PHASE] main_phase begin
> 4 | UVM_ERROR tb/tb_regress.v(51) @ 30000: uvm_test_top.env.drv [PROTO] req asserted while busy at cycle 29
5 | UVM_INFO tb/tb_regress.v(74) @ 40000: uvm_test_top.env [PHASE] main_phase end
6 | --- UVM Report Summary ---
#3 6 run(s) FAIL SCBD: no response for tag N after N cycles
runs: alu_burst_s8, alu_burst_s19, alu_burst_s30 (+3 more)
runs/alu_burst_s8/logs/sim.log:
2 | UVM_INFO tb/tb_regress.v(40) @ 10000: uvm_test_top.env [CFG] seed=8
3 | UVM_INFO tb/tb_regress.v(42) @ 20000: uvm_test_top.env [PHASE] main_phase begin
> 4 | UVM_ERROR tb/tb_regress.v(56) @ 30000: uvm_test_top.env.scbd [SCBD] no response for tag 8 after 1000 cycles
5 | UVM_INFO tb/tb_regress.v(74) @ 40000: uvm_test_top.env [PHASE] main_phase end
6 | --- UVM Report Summary ---
#4 6 run(s) FATAL AXI: burst crossed a 4KB boundary at addr=0xHEX
runs: alu_burst_s10, alu_burst_s23, alu_burst_s36 (+3 more)
runs/alu_burst_s10/logs/sim.log:
2 | UVM_INFO tb/tb_regress.v(40) @ 10000: uvm_test_top.env [CFG] seed=10
3 | UVM_INFO tb/tb_regress.v(42) @ 20000: uvm_test_top.env [PHASE] main_phase begin
> 4 | UVM_ERROR tb/tb_regress.v(65) @ 30000: uvm_test_top.env.axi [AXI] burst crossed a 4KB boundary at addr=0x00009ffc
5 | UVM_FATAL tb/tb_regress.v(68) @ 40000: uvm_test_top.env.axi [AXI] cannot continue after illegal burst
6 | --- UVM Report Summary ---
#5 4 run(s) CRASH ended without a report summary, no error before it
runs: alu_burst_s14, alu_burst_s31, alu_smoke_s17 (+1 more)
runs/alu_burst_s14/logs/sim.log:
4 | UVM_INFO tb/tb_regress.v(61) @ 30000: uvm_test_top.env [PHASE] main_phase executing
5 | tb/tb_regress.v:61: $finish called at 30000 (1ps)
exit 1
== the same logs, grouped by message ID only
failing runs: 41, in 4 group(s) by id (38 distinct first-error texts before normalising)
#1 22 run(s) FAIL SCBD
#2 9 run(s) FAIL PROTO
#3 6 run(s) FATAL AXI
#4 4 run(s) CRASH ended without a report summary, no error before itForty-one failing runs, thirty-eight different first-error texts, five causes. The raw texts are nearly all distinct because each carries its own addresses and values; normalising them leaves five shapes. Each group gives what a lead needs to assign it: how many runs, which runs (the first three, in natural order), and the first error of the first run with two lines of context and its line number.
The crash group is the one a pure error-counting tool would miss entirely. Its four logs contain no error at all. They are failures because they stop without a report summary, and the excerpt shows where each one stopped.
The ls line at the top shows the directory listing in plain sorted order — alu_burst_s1, alu_burst_s10, alu_burst_s11 — which is the order the tool deliberately does not use for its examples.
6. Grouping By ID Merges Different Problems
The last block of the demo groups the same logs by message ID only. Four groups instead of five: the data mismatch (16 runs) and the response timeout (6 runs) both carry [SCBD], and grouping by ID merges them into one group of 22. They are different bugs — one is wrong data, the other is no data — and a lead who assigns "the SCBD failures" to one engineer has assigned two problems while seeing one.
--group-by id is still useful. It is the right first view when a new testbench produces hundreds of distinct messages and you want to know which component is complaining. But the signature view is the one that matches failures to causes.
7. The Runs A Glob Cannot See
#!/bin/bash
# edges.sh -- the runs a glob cannot see, and the inputs triage must refuse.
bash run_regression.sh runs || exit 1
for t in alu_smoke alu_burst; do for s in $(seq 1 40); do echo "${t}_s$s"; done; done > expected.txt
rm runs/alu_smoke_s3/logs/sim.log # a job that never started
: > runs/alu_smoke_s6/logs/sim.log # a job killed before it wrote anything
show() { "$@" > out.txt 2> err.txt; local rc=$?
grep -E '^(triaged| missing|failing|#)' out.txt; grep -v -E '^(usage:|exit:| )' err.txt | sed 's/^/ stderr: /'
echo " exit $rc"; }
echo "== the glob, without --expect"
show perl triage.pl runs/*/logs/sim.log
echo "== the glob, with --expect expected.txt"
show perl triage.pl runs/*/logs/sim.log --expect expected.txt
echo "== three passing runs"
show perl triage.pl runs/alu_smoke_s1/logs/sim.log runs/alu_smoke_s2/logs/sim.log runs/alu_smoke_s4/logs/sim.log
echo "== a glob that matches nothing"
show perl triage.pl nightly/*/logs/sim.log
echo "== two logs for one run"
cp runs/alu_smoke_s5/logs/sim.log runs/alu_smoke_s5/sim.log
show perl triage.pl runs/alu_smoke_s5/logs/sim.log runs/alu_smoke_s5/sim.log
echo "== --group-by test"
show perl triage.pl runs/*/logs/sim.log --group-by test== the glob, without --expect
triaged 79 run(s): NO_LOG 0, EMPTY 1, FATAL 6, CRASH 4, FAIL 31, PASS 37
missing runs cannot be detected without --expect
failing runs: 42, in 6 group(s) by signature (39 distinct first-error texts before normalising)
#1 16 run(s) FAIL SCBD: data mismatch exp=HEX got=HEX addr=0xHEX
#2 9 run(s) FAIL PROTO: req asserted while busy at cycle N
#3 6 run(s) FAIL SCBD: no response for tag N after N cycles
#4 6 run(s) FATAL AXI: burst crossed a 4KB boundary at addr=0xHEX
#5 4 run(s) CRASH ended without a report summary, no error before it
#6 1 run(s) EMPTY log is empty
exit 1
== the glob, with --expect expected.txt
triaged 80 run(s): NO_LOG 1, EMPTY 1, FATAL 6, CRASH 4, FAIL 31, PASS 37
failing runs: 43, in 7 group(s) by signature (40 distinct first-error texts before normalising)
#1 16 run(s) FAIL SCBD: data mismatch exp=HEX got=HEX addr=0xHEX
#2 9 run(s) FAIL PROTO: req asserted while busy at cycle N
#3 6 run(s) FAIL SCBD: no response for tag N after N cycles
#4 6 run(s) FATAL AXI: burst crossed a 4KB boundary at addr=0xHEX
#5 4 run(s) CRASH ended without a report summary, no error before it
#6 1 run(s) EMPTY log is empty
#7 1 run(s) NO_LOG log never written
exit 1
== three passing runs
triaged 3 run(s): NO_LOG 0, EMPTY 0, FATAL 0, CRASH 0, FAIL 0, PASS 3
missing runs cannot be detected without --expect
failing runs: 0, in 0 group(s) by signature (0 distinct first-error texts before normalising)
exit 0
== a glob that matches nothing
stderr: triage.pl: no file matches nightly/*/logs/sim.log (an unmatched glob?)
stderr: triage.pl: nothing triaged
exit 2
== two logs for one run
stderr: triage.pl: two logs for run alu_smoke_s5: runs/alu_smoke_s5/logs/sim.log and runs/alu_smoke_s5/sim.log
stderr: triage.pl: nothing triaged
exit 2
== --group-by test
stderr: triage.pl: --group-by must be signature or id
exit 3The first case is the most important finding of this chapter. One run's log was deleted — a job that never started. The shell's glob lists only files that exist, so the tool is given 79 logs, triages 79 runs, and nothing anywhere says a run is missing. The output is complete-looking and one run short.
With --expect — the list of runs the regression was supposed to produce, which the regression runner always has — the tool reports 80 runs, and the missing one appears as its own group, NO_LOG. Without --expect, the tool prints the one thing it can honestly say: missing runs cannot be detected.
The other cases are refusals and edge states. An empty log is its own verdict, EMPTY. A glob that matches nothing arrives at the program as the literal text nightly/*/logs/sim.log — the shell passes an unmatched pattern through unchanged — and the tool refuses it with exit 2 and names the likely cause, rather than inventing a run named *. Two logs that claim the same run are refused, because one of them would otherwise be silently overwritten.
8. A Test Suite For The Tool
#!/usr/bin/perl
# t/triage.t -- black-box tests for triage.pl over 80 real simulation logs.
use strict;
use warnings;
use Test::More;
use File::Temp qw(tempdir);
use File::Copy qw(copy);
use FindBin qw($Bin);
my $TOOL = "$Bin/../triage.pl";
my $base = tempdir(CLEANUP => 1);
chdir "$Bin/.." or die;
system("bash", "run_regression.sh", "$base/runs") == 0 or die "run_regression.sh failed\n";
my @LOGS = sort glob("$base/runs/*/logs/sim.log");
sub slurp { open my $fh, "<", $_[0] or return undef; local $/; return scalar <$fh> }
sub run_tool { # (status, stdout, stderr); %$env is added to the environment
my ($env, @args) = @_;
my $pid = fork // die "fork: $!";
if ($pid == 0) {
@ENV{ keys %$env } = values %$env;
open STDOUT, ">", "$base/stdout" or die;
open STDERR, ">", "$base/stderr" or die;
exec $^X, $TOOL, @args;
die "exec: $!";
}
waitpid $pid, 0;
return ($? >> 8, slurp("$base/stdout") // "", slurp("$base/stderr") // "");
}
# (size, label) of every group, in order. The captures come back as one flat
# list -- size, label, size, label -- so they are paired by position; $1 and
# $2 inside a map would hold the LAST match's values every time.
sub groups {
my @flat = $_[0] =~ /^#\d+ (\d+) run\(s\) (.+)$/mg;
return map { [ @flat[ 2 * $_, 2 * $_ + 1 ] ] } 0 .. @flat / 2 - 1;
}
# Runs whose output is compared are pinned to one hash seed, so a test about
# order sees only the thing it is about; test 8 varies the seed on purpose.
my %PIN = (PERL_HASH_SEED => 7, PERL_PERTURB_KEYS => 2);
# ---- the eighty runs
my ($rc, $out) = run_tool(\%PIN, @LOGS);
is($rc, 1, "failing runs exist: exit 1");
like($out, qr/^triaged 80 run\(s\): NO_LOG 0, EMPTY 0, FATAL 6, CRASH 4, FAIL 31, PASS 39$/m,
"verdicts: 6 fatal, 4 crashed, 31 failed, 39 passed");
# the failing count, established here without the tool: a log with an error or
# fatal MESSAGE (one that has an [ID]), or with no report summary at all
my $failing = grep { my $t = slurp($_);
$t =~ /^UVM_(?:ERROR|FATAL)\b.*\[\w+\]/m || $t !~ /^--- UVM Report Summary ---/m } @LOGS;
my $grouped = 0;
$grouped += $_->[0] for groups($out);
ok($failing == 41 && $grouped == 41, "every one of the 41 failing runs is in exactly one group");
is_deeply([ map { $_->[0] } groups($out) ], [ 16, 9, 6, 6, 4 ], "five groups, biggest first");
like($out, qr/^\#3 6 run\(s\) FAIL SCBD: no response.*\n.*\n.*\n.*\n.*\n.*\n.*\n.*\n\n\#4 6 run\(s\) FATAL AXI/m,
"two groups of 6 appear in a fixed order (FAIL before FATAL, by name)");
like($out, qr/^ runs: alu_burst_s2, alu_burst_s7, alu_burst_s12 \(\+13 more\)$/m,
"example runs in natural order: s2, s7, s12 (not s12, s17, s2)");
like($out, qr/^ > 4 \| UVM_ERROR .*\[SCBD\] data mismatch exp=005101c6/m,
"the excerpt marks the first error, with its line number");
my %outs;
for my $seed (1 .. 5) {
my (undef, $o) = run_tool({ PERL_HASH_SEED => $seed, PERL_PERTURB_KEYS => 2 }, @LOGS);
$outs{$o}++;
}
is(scalar keys %outs, 1, "five hash seeds give one identical report");
(undef, $out) = run_tool(\%PIN, @LOGS, "--group-by", "id");
is_deeply([ groups($out) ], [ [ 22, "FAIL SCBD" ], [ 9, "FAIL PROTO" ], [ 6, "FATAL AXI" ],
[ 4, "CRASH ended without a report summary, no error before it" ] ],
"--group-by id: the two SCBD problems merge into one group of 22");
(undef, $out) = run_tool(\%PIN, @LOGS, "--top", 2);
like($out, qr/^\(3 more group\(s\) with 16 run\(s\); use --top\)$/m, "--top 2 says what it left out");
# ---- the runs a glob cannot see
my @kept = grep { !m{/alu_smoke_s3/} } @LOGS;
my $empty = "$base/empty/alu_smoke_s6/logs";
system("mkdir", "-p", $empty) == 0 or die;
open my $e, ">", "$empty/sim.log" or die; close $e;
@kept = map { m{/alu_smoke_s6/} ? "$empty/sim.log" : $_ } @kept;
open my $x, ">", "$base/expected.txt" or die;
print {$x} "$_\n" for map { m{/([^/]+)/logs/sim\.log$} } @LOGS;
close $x;
(undef, $out) = run_tool({}, @kept);
like($out, qr/^triaged 79 run\(s\)/m, "without --expect, a run with no log simply is not there");
(undef, $out) = run_tool({}, @kept, "--expect", "$base/expected.txt");
ok($out =~ /^triaged 80 run\(s\): NO_LOG 1, EMPTY 1,/m && $out =~ /NO_LOG log never written/,
"with --expect, the missing run is NO_LOG and the empty one EMPTY");
# ---- exit status and refusals
my @pass = grep { m{/alu_smoke_s(?:1|2|4)/} } @LOGS;
($rc) = run_tool({}, @pass);
is($rc, 0, "three passing runs: exit 0");
my ($grc, undef, $gerr) = run_tool({}, "$base/nightly/*/logs/sim.log");
ok($grc == 2 && $gerr =~ /an unmatched glob/, "an unmatched glob: exit 2, and it says so");
copy($LOGS[0], "$base/runs/alu_burst_s1/sim.log") or die;
($rc) = run_tool({}, $LOGS[0], "$base/runs/alu_burst_s1/sim.log");
is($rc, 2, "two logs for one run: exit 2");
($rc) = run_tool({}, @LOGS, "--group-by", "test");
is($rc, 3, "an unknown --group-by: exit 3");
done_testing();Test 3 counts the failing runs without the tool. It reads the logs with its own pattern and requires that the tool's groups add up to the same 41. A tool that drops a run from every group, or puts one in two, fails it.
The helper groups() has a comment because it was wrong first. It was written as map { [ $1, $2 ] } over a list-context match, and three tests failed on the first run: every group came back as the crash group, five times. That is the $1 trap Chapter 29.1 found in its own tool — after a list-context match, $1 holds the last match's capture on every pass. The fixed helper pairs the flat capture list by position.
Every run that is compared with another is pinned to one hash seed, and test 8 varies the seed on purpose — the rule Chapter 29.3 arrived at. Tests 11 and 12 are the glob finding: the same 79 logs, without and with --expect.
#!/bin/bash
# tests.sh -- run the suite through prove, keeping prove's own exit status.
prove -v t/ > prove.log 2>&1
status=$?
grep -v 'wallclock' prove.log
echo "prove exit $status"t/triage.t ..
ok 1 - failing runs exist: exit 1
ok 2 - verdicts: 6 fatal, 4 crashed, 31 failed, 39 passed
ok 3 - every one of the 41 failing runs is in exactly one group
ok 4 - five groups, biggest first
ok 5 - two groups of 6 appear in a fixed order (FAIL before FATAL, by name)
ok 6 - example runs in natural order: s2, s7, s12 (not s12, s17, s2)
ok 7 - the excerpt marks the first error, with its line number
ok 8 - five hash seeds give one identical report
ok 9 - --group-by id: the two SCBD problems merge into one group of 22
ok 10 - --top 2 says what it left out
ok 11 - without --expect, a run with no log simply is not there
ok 12 - with --expect, the missing run is NO_LOG and the empty one EMPTY
ok 13 - three passing runs: exit 0
ok 14 - an unmatched glob: exit 2, and it says so
ok 15 - two logs for one run: exit 2
ok 16 - an unknown --group-by: exit 3
1..16
ok
All tests successful.
Result: PASS
prove exit 09. Proving The Suite Can Fail
#!/bin/bash
# mutate.sh -- plant one defect at a time in a COPY of the tool; does the
# suite notice?
mutant() { # LABEL PERL-SUBSTITUTION (applied to the whole file)
local label=$1 edit=$2 d failed
d=$(mktemp -d)
mkdir "$d/t"
cp -r run_regression.sh tb "$d/"
cp t/triage.t "$d/t/"
perl -0pe "$edit" triage.pl > "$d/triage.pl"
if cmp -s triage.pl "$d/triage.pl"; then
printf '%-44s NOT PLANTED (edit matched nothing)\n' "$label"
elif ! perl -c "$d/triage.pl" > /dev/null 2>&1; then
printf '%-44s INVALID (the mutant does not compile)\n' "$label"
else
failed=$(perl "$d/t/triage.t" 2>/dev/null | grep -c '^not ok')
printf '%-44s %s (%s failing test(s))\n' "$label" \
"$([ "$failed" -gt 0 ] && echo CAUGHT || echo SURVIVED)" "$failed"
fi
rm -rf "$d"
}
mutant "1 FAIL ranked above FATAL" 's/( \[ FATAL => [^\n]*\n)( \[ CRASH => [^\n]*\n)( \[ FAIL => [^\n]*\n)/$3$1$2/'
mutant "2 no completion check" 's/\[ CRASH => sub \{ !\$_\[0\]\{summary\} \} \]/[ CRASH => sub { 0 } ]/'
mutant "3 leave hex values in the signature" 's/\n \$m =~ s\/\\b\(\?=\[0-9a-fA-F\]\*\\d\)\[0-9a-fA-F\]\{6,\}\\b\/HEX\/g;//'
mutant "4 plain sort for the examples" 's/sort natural keys %run/sort keys %run/'
mutant "5 no tie-break between groups" 's/ or \$a cmp \$b \} keys %group;/ } keys %group;/'
mutant "6 ignore --expect" 's/\$log_of\{\$_\} \/\/= undef/1/'
mutant "7 take a missing file as a run" 's/unless \(-e \$log\) \{/if (0) {/'
mutant "8 last error, not first" 's/if \(!defined \$r\{first\}\) \{/if (1) {/'1 FAIL ranked above FATAL CAUGHT (3 failing test(s))
2 no completion check CAUGHT (5 failing test(s))
3 leave hex values in the signature CAUGHT (6 failing test(s))
4 plain sort for the examples CAUGHT (2 failing test(s))
5 no tie-break between groups CAUGHT (2 failing test(s))
6 ignore --expect CAUGHT (1 failing test(s))
7 take a missing file as a run CAUGHT (1 failing test(s))
8 last error, not first CAUGHT (3 failing test(s))All eight are caught. Mutant 1 reorders the rule table so that FAIL is tested before FATAL, and three tests notice: every fatal run becomes an ordinary failure. Mutant 5 removes the tie-break between groups, and its result was the reason the seeds are pinned. Before pinning, that mutant was caught by one test on some runs and two on others, because the unpinned run's hash order was random — a mutation result that changes between runs cannot be published, and a test result that changes between runs cannot be trusted.
10. What The Tool Does Not Do
- It does not know the history. Whether a signature is new today or has failed for a week needs yesterday's result; that comparison is the next project's job.
- It reads one log layout, the UVM-shaped lines of Module 21. Questa's
#prefix (Chapter 21.1) would need the patterns to accept it. - Its signature is a heuristic. A message whose meaningful content is a number —
retry count 3 exceeded limit 2— loses that content, and two genuinely different failures can share a shape. Read the excerpts before trusting a group. - It cannot detect a missing run without
--expect. It says so on every run without it. - It does not judge timeouts from wall-clock time. Chapter 21.8's TIMEOUT verdict needs a runtime record from outside the log; here a UVM timeout appears as a fatal.
11. Exercises
1. Every run, not three. Add --list GROUP to print every run in one group, one per line, so the output can be fed to a rerun script.
2. A stricter signature. Find a pair of messages in your own logs that this signature merges and should not. Change the normalisation so they separate, and add a test with both messages.
3. The Questa prefix. Make the tool accept a leading # on every line without changing any result on the current logs. What test proves it?
4. Expected runs from the directory. Some flows create a run directory before starting the job. Add --runs DIR, which treats every subdirectory as an expected run. Which edge case from section 7 does it catch, and which does it still miss?
5. A crash with an error. Make one seed log an error and then die. Which verdict does it get, which signature, and do you agree with both?
12. What To Remember
- Assemble the pieces in a fixed order: verdict by ordered rules, first error, signature, group, ordered output.
- Group by verdict and signature. Measured: 38 distinct error texts became 5 causes; grouping by ID alone merged two different
SCBDproblems into one group of 22. - A crash has no error in it. Its evidence is a missing report summary, and it needs its own group.
- A glob only lists files that exist. Measured: a missing log made the tool triage 79 runs with no message. Give the tool the list of expected runs.
- An unmatched glob reaches the program as literal text. Refuse it, and say so.
- Natural order for run names; a tie-break for groups of equal size.
- Read each log once, keeping a two-line ring for context.
- A message needs an
[ID]— the summary's own count lines are not errors. My own first quick count got this wrong. - Pin the hash seed in any test that compares two runs, and vary it only in the test about it.
Where this fits
Part of the Perl curriculum.