Perl Part II · Module 18 · Log Parsing and Text Processing

What a Tool Log Actually Looks Like

Parsing a tool log is the core skill of Part II, and almost everything built in the next eleven modules reads one. So it is worth spending a chapter on what is actually in the file, because a log is not a flat stream of messages — it has sections, each written by a different phase of the tool, and a pattern that is correct in one section is wrong in another. This chapter measures the specific consequence of ignoring that, and it is the measurement the whole module is built on: the single most common log-parsing command in this industry gives the wrong answer on a normal log, and it gives it quietly.

Foundation12 min readPerlPart IILog Parsing

Part II · Module 18 · Chapter 18.1 · What a Tool Log Actually Looks Like

1. Five Sections, Not One Stream

Figure 18.1.1 — The five sections of a tool log

A log is written by a tool in phases, and each phase produces a different shape of line. The banner and elaboration sections carry version and build information a parser mostly skips. The run section is the messages your parser is actually looking for. The summary and epilogue repeat the run's contents as counts — which is the problem, because those count lines begin with the same token as the messages they are counting.

A log of the kind this module parses, in the shape a real one has:

Azvya Education Pvt. Ltd.VLSI Mentor

sim.log (a sample, in the shape a real VCS/UVM log has)

Chronologic VCS simulator copyright 1991-2023
Compiler version V-2023.12; Runtime version V-2023.12
TimeScale is 1 ps / 1 ps
Elaboration: 412 modules, 1844 instances
UVM_INFO @ 0: reporter [RNTST] Running test alu_smoke_test...
UVM_ERROR tb/env/scoreboard.sv(151) @ 2400: [SB_MISMATCH] expected 0x0f got 0x0e
UVM_WARNING tb/env/driver.sv(88) @ 2401: [DRV] backpressure for 3 cycles
--- UVM Report Summary ---
UVM_INFO :    3
UVM_WARNING :    1
UVM_ERROR :    1
UVM_FATAL :    0
$finish at simulation time              9600 ps

Look at lines 6 and 10. One is a message reporting a mismatch; the other is a count saying how many such messages there were. Both begin with UVM_ERROR.

2. The Log Counts Itself

Azvya Education Pvt. Ltd.VLSI Mentor

self-counting.pl

use strict;
use warnings;
use File::Temp qw(tempdir);
use File::Spec;

# ---- the SAMPLE log above, written to a file
my $dir = tempdir(CLEANUP => 1);
my $log = File::Spec->catfile($dir, "sim.log");
open my $w, ">", $log or die "cannot write: $!\n";
print $w <<'LOG';
Chronologic VCS simulator copyright 1991-2023
Compiler version V-2023.12; Runtime version V-2023.12
TimeScale is 1 ps / 1 ps
Elaboration: 412 modules, 1844 instances
UVM_INFO @ 0: reporter [RNTST] Running test alu_smoke_test...
UVM_ERROR tb/env/scoreboard.sv(151) @ 2400: [SB_MISMATCH] expected 0x0f got 0x0e
UVM_WARNING tb/env/driver.sv(88) @ 2401: [DRV] backpressure for 3 cycles
--- UVM Report Summary ---
UVM_INFO :    3
UVM_WARNING :    1
UVM_ERROR :    1
UVM_FATAL :    0
$finish at simulation time              9600 ps
LOG
close $w;

# ---- the pattern everyone writes first
my $RUN = qr/^UVM_(?:INFO|WARNING|ERROR|FATAL)\b/;

open my $fh, "<", $log or die "cannot read: $!\n";
my (@matched, $ln);
while (my $l = <$fh>) {
    $ln++;
    chomp $l;
    push @matched, [$ln, $l] if $l =~ $RUN;
}
close $fh;

printf "lines matching %s : %d\n", 'qr/^UVM_(INFO|WARNING|ERROR|FATAL)\b/', scalar @matched;
printf "   %2d  %s\n", @$_ for @matched;

# a summary COUNT line is "UVM_WORD : <number>" and nothing else
my $COUNT = qr/^UVM_\w+\s*:\s*\d+\s*\z/;
my @genuine = grep { $_->[1] !~ $COUNT } @matched;
my @counts  = grep { $_->[1] =~ $COUNT } @matched;

printf "\n   genuine run messages                        : %d\n", scalar @genuine;
printf "   summary count lines misclassified as messages: %d\n", scalar @counts;

my $naive = grep { $_->[1] =~ /UVM_ERROR/ } @matched;
my $truth = grep { $_->[1] =~ /UVM_ERROR/ } @genuine;
printf "\n   a naive UVM_ERROR count reports %d; the truth is %d\n", $naive, $truth;
printf "   so the error count is overstated by %d, every time\n", $naive - $truth;

Azvya Education Pvt. Ltd.VLSI Mentor

Captured output

lines matching qr/^UVM_(INFO|WARNING|ERROR|FATAL)\b/ : 7
    5  UVM_INFO @ 0: reporter [RNTST] Running test alu_smoke_test...
    6  UVM_ERROR tb/env/scoreboard.sv(151) @ 2400: [SB_MISMATCH] expected 0x0f got 0x0e
    7  UVM_WARNING tb/env/driver.sv(88) @ 2401: [DRV] backpressure for 3 cycles
    9  UVM_INFO :    3
   10  UVM_WARNING :    1
   11  UVM_ERROR :    1
   12  UVM_FATAL :    0

   genuine run messages                        : 3
   summary count lines misclassified as messages: 4

   a naive UVM_ERROR count reports 2; the truth is 1
   so the error count is overstated by 1, every time

A naive error count reports 2 where the truth is 1.

That is not a contrived failure. grep -c UVM_ERROR sim.log is the most widely used log check in this industry, and on any log that ends with a UVM report summary it returns one more than the real number — because the summary's own UVM_ERROR : 1 line contains the string.

The consequences are both directions of wrong:

A clean run reports a failure. Zero errors, but the summary still prints UVM_ERROR : 0, which contains UVM_ERROR. So grep -c returns 1 on a passing test, and a regression keyed on "count greater than zero" fails every test it runs.

A failing run reports the wrong count. Three real errors become four, so a threshold of "fewer than four is acceptable" passes a run with three.

And the error is invisible, because the number is plausible. Chapter 14.1's third kind of failure, from the most ordinary command in the flow.

3. What Each Section Is For

The banner. Tool name, version, build date, copyright. A parser usually skips it — except to record the version, which Chapter 18.8 shows is the thing you need when the same parser has to handle two tool releases.

Elaboration. Module and instance counts, timescale, library resolution, and the compile warnings. Mostly skipped, with one exception: an elaboration error here means the run never started, which is a completely different outcome from a run that started and failed. Chapter 18.9 separates them.

The run. The messages. This is what a parser is for, and it is usually the largest section by a wide margin — Chapter 18.10 is about the case where it is larger than memory.

The summary. The tool's own counts. Useful as a cross-check on your parse rather than as the parse itself: if your count of run messages disagrees with the summary's count, one of you is wrong and you want to know. Treating the summary as the answer is tempting and fragile, because not every tool writes one and a truncated log has none.

The epilogue. $finish, simulation time, CPU time, memory. The presence of $finish is the cheapest available signal that the run reached its end rather than being killed — which Chapter 18.9 uses, and which matters because a killed run leaves a log that looks complete until you check.

4. Finding the Boundaries

Azvya Education Pvt. Ltd.VLSI Mentor

sections.pl

use strict;
use warnings;
use File::Temp qw(tempdir);
use File::Spec;

my $dir = tempdir(CLEANUP => 1);
my $log = File::Spec->catfile($dir, "sim.log");
open my $w, ">", $log or die "cannot write: $!\n";
print $w <<'LOG';
Chronologic VCS simulator copyright 1991-2023
Contains Synopsys proprietary information.
Compiler version V-2023.12; Runtime version V-2023.12
Top Level Modules:
       tb_top
TimeScale is 1 ps / 1 ps
Elaboration: 412 modules, 1844 instances
UVM_INFO @ 0: reporter [RNTST] Running test alu_smoke_test...
UVM_INFO tb/env/scoreboard.sv(142) @ 1200: [SB] compare ok pin=u_alu/A
UVM_ERROR tb/env/scoreboard.sv(151) @ 2400: [SB_MISMATCH] expected 0x0f got 0x0e
UVM_WARNING tb/env/driver.sv(88) @ 2401: [DRV] backpressure for 3 cycles
--- UVM Report Summary ---
** Report counts by severity
UVM_INFO :    3
UVM_WARNING :    1
UVM_ERROR :    1
UVM_FATAL :    0
$finish called from file "tb/tb_top.sv" line 91.
$finish at simulation time              9600 ps
CPU Time:      1.420 seconds
LOG
close $w;

# Boundaries are recognised by MARKERS, not by line numbers -- a log's
# section lengths change with every run, its markers do not.
my @boundary = (
  [ "banner",      qr/\A(?:Chronologic|Contains|Compiler version)/     ],
  [ "elaboration", qr/\A(?:Top Level Modules|\s+\w+\s*\z|TimeScale|Elaboration)/ ],
  [ "summary",     qr/\A(?:---\s*UVM Report Summary|\*\* Report counts)/ ],
  [ "epilogue",    qr/\A(?:\$finish|CPU Time:|Time:)/                   ],
);
my $RUN_MSG = qr/\AUVM_(?:INFO|WARNING|ERROR|FATAL)\s+\S|\AUVM_\w+\s+@/;

open my $fh, "<", $log or die "cannot read: $!\n";
my ($state, %lines, %first, $ln) = ("banner");
while (my $l = <$fh>) {
    $ln++;
    chomp $l;
    next unless $l =~ /\S/;
    # a marker moves the state; otherwise the state persists
    for my $b (@boundary) {
        if ($l =~ $b->[1]) { $state = $b->[0]; last }
    }
    $state = "run" if $l =~ $RUN_MSG && $state ne "summary" && $state ne "epilogue";
    $lines{$state}++;
    $first{$state} //= $ln;
}
close $fh;

printf "%-13s %6s %s\n", "SECTION", "lines", "first line";
for my $name (qw(banner elaboration run summary epilogue)) {
    printf "%-13s %6d %s\n", $name, $lines{$name} // 0, $first{$name} // "-";
}
printf "\ntotal non-blank lines: %d\n", eval { my $s = 0; $s += $_ for values %lines; $s };

Azvya Education Pvt. Ltd.VLSI Mentor

Captured output

SECTION        lines first line
banner             3 1
elaboration        4 4
run                4 8
summary            6 12
epilogue           3 18

total non-blank lines: 20

Three principles are doing the work there, and all three carry into the rest of the module.

Boundaries are markers, not line numbers. --- UVM Report Summary --- appears at a different line in every run. A parser that skips "the first seven lines" breaks the first time elaboration emits an extra warning.

The state persists between markers. A line that matches nothing belongs to the section it is in. That is a one-variable state machine, and Chapter 18.7 is what happens when one variable is not enough.

The run pattern is guarded by the state. $state ne "summary" is what stops the summary's count lines being classified as run messages — the same fix the measurement in section 2 was asking for, in its simplest form.

One practical note on reading an unfamiliar log before writing any pattern against it.

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

grep -n -m1 -E 'Report Summary|\$finish|^Elaboration' sim.log

That prints the line number of each boundary marker, which tells you the shape of the file in one command — how long the run section is, whether there is a summary at all, and whether the run reached $finish. It is worth doing before writing a parser, because it answers "is this log even complete" first. Chapter 18.9 turns that question into a check.

And on a log you have never seen, head -40 and tail -40 together show you both ends — which is where every marker lives. The middle is the part a parser scans and the part you do not need to read.

5. What To Remember

A log is five sections, not one stream: banner, elaboration, run, summary, epilogue.
The summary restates the run as counts, using the same leading token as the messages.
Measured: a naive UVM_ERROR count reported 2 where the truth was 1.
grep -c UVM_ERROR returns 1 on a passing test, because the summary prints UVM_ERROR : 0.
So a regression keyed on "count greater than zero" fails every test it runs — and the number always looks plausible.
The same substring match also catches NO_UVM_ERROR, a quoted mention, a test name, and UVM_ERROR_LIMIT (18.4).
Record the tool version from the banner — 18.8 needs it.
An elaboration error means the run never started, which is a different outcome from a run that failed (18.9).
The run section is usually the bulk, and sometimes larger than memory (18.10).
Use the summary as a cross-check on your parse, never as the parse — not every tool writes one, and a truncated log has none.
$finish is the cheapest signal that the run reached its end rather than being killed (18.9).
Recognise boundaries by markers, not line numbers — section lengths change every run.
Let the state persist between markers, so an unmatched line belongs to the section it is in.
Guard the run pattern with the state, which is what stops the summary being counted as messages.
Before writing a parser, grep -n -m1 the markers and read head and tail. The middle is what the parser is for.

Chapter 18.2 assembles the loop that every parser in the rest of the curriculum uses. It is seven steps long, it is rated Critical, and the reason is that six of the seven are easy to leave out and each omission produces a wrong answer rather than an error.

Where this fits

Part of the Perl curriculum.