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

Streaming a Multi-Gigabyte Log

Gate-level simulation logs, full-chip timing reports and long regression transcripts reach sizes where the parser's memory use stops being an implementation detail and becomes the reason the job dies. The usual advice is 'stream, do not slurp', and it is right but incomplete: this chapter measures eight strategies against the same log, and one of the four that blows up is reading the file strictly one line at a time. The constraint is not how you read the file. It is what you are still holding when you reach the end of it.

Advanced19 min readPerlPart IILog Parsing

Part II · Module 18 · Chapter 18.10 · Streaming a Multi-Gigabyte Log

1. Eight Strategies, One Log

Every strategy below reads the whole log and reaches the same answer about it. They differ only in what they keep while doing it. Each one runs in its own child process, for a reason section 5 measures.

Azvya Education Pvt. Ltd.VLSI Mentor

streaming.pl

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

my ($mode, $log) = @ARGV;
my $LINES = 150_000;

sub rss_mb { my $k = `ps -o rss= -p $$`; $k =~ s/\D//g; return $k / 1024 }

# ---------------- child: run ONE strategy, report its own peak RSS
if (defined $mode) {
    my $n = 0;
    if ($mode eq "baseline") { open my $fh, "<", $log or die $!; close $fh }
    elsif ($mode eq "stream") {
        open my $fh, "<", $log or die $!;
        while (my $l = <$fh>) { $n++ if $l =~ /^UVM_ERROR\b/ }
        close $fh;
    }
    elsif ($mode eq "ring") {
        open my $fh, "<", $log or die $!;
        my @last;
        while (my $l = <$fh>) {
            push @last, $l;
            shift @last if @last > 20;          # never holds more than 20
            $n++ if $l =~ /^UVM_ERROR\b/;
        }
        close $fh;
    }
    elsif ($mode eq "hash_bounded") {
        open my $fh, "<", $log or die $!;
        my %count;
        while (my $l = <$fh>) { $count{$1}++ if $l =~ /^UVM_(\w+)\b/ }
        close $fh;
        $n = scalar keys %count;                # a handful of severities
    }
    elsif ($mode eq "hash_unbounded") {
        open my $fh, "<", $log or die $!;
        my %seen;
        while (my $l = <$fh>) { $seen{$1}++ if $l =~ /\bid=(\d+)/ }
        close $fh;
        $n = scalar keys %seen;                 # ONE KEY PER LINE
    }
    elsif ($mode eq "slurp") {
        open my $fh, "<", $log or die $!;
        my @lines = <$fh>;
        close $fh;
        $n = grep { /^UVM_ERROR\b/ } @lines;
    }
    elsif ($mode eq "forloop") {
        open my $fh, "<", $log or die $!;
        for my $l (<$fh>) { $n++ if $l =~ /^UVM_ERROR\b/ }   # a slurp in disguise
        close $fh;
    }
    elsif ($mode eq "collect") {
        open my $fh, "<", $log or die $!;
        my @hits;
        while (my $l = <$fh>) { push @hits, $l if $l =~ /^UVM_INFO\b/ }
        close $fh;
        $n = scalar @hits;
    }
    printf "%.1f %d\n", rss_mb(), $n;
    exit 0;
}

# ---------------- parent: build the log once, one child per strategy
my $dir = tempdir(CLEANUP => 1);
my $big = "$dir/big.log";
open my $o, ">", $big or die $!;
for my $i (1 .. $LINES) {
    print $o "UVM_INFO /proj/tb/driver.sv($i) \@ ${i}000: sent packet id=$i len=64\n";
    print $o "UVM_ERROR /proj/tb/scoreboard.sv(214) \@ ${i}000: mismatch exp=3f\n"
        if $i % 500 == 0;
}
close $o;
my $size = (-s $big) / 1048576;
printf "log: %d MB, %d lines -- every strategy below reads ALL of it\n\n",
    int($size), $LINES + $LINES/500;

my @MODES = qw(baseline stream ring hash_bounded hash_unbounded slurp forloop collect);
my %HOLDS = (baseline => "nothing", stream => "one line", ring => "20 lines",
             hash_bounded => "a few keys", hash_unbounded => "one key per line",
             slurp => "every line", forloop => "every line", collect => "every match");
my (%rss, %found);
for my $m (@MODES) {
    chomp(my $out = `perl $0 $m $big`);
    ($rss{$m}, $found{$m}) = split ' ', $out;
}
my $base = $rss{baseline};

printf "%-15s %-17s %-9s %s\n", "STRATEGY", "holds", "found", "memory vs baseline";
for my $m (@MODES) {
    my $d = $rss{$m} - $base;
    printf "%-15s %-17s %-9s %s\n", $m, $HOLDS{$m}, $found{$m},
        $d < $size/4 ? "FLAT" : "GREW";
}

print "\nverdicts (each strategy in its OWN process; 'grew' means by more\n";
print "than a quarter of the log size, 'flat' means less):\n";
for my $m (qw(stream ring hash_bounded)) {
    printf "  %-16s stays FLAT?                        %s\n", $m,
        (($rss{$m} - $base) < $size/4 ? "YES" : "no");
}
for my $m (qw(hash_unbounded slurp forloop collect)) {
    printf "  %-16s GREW?                              %s\n", $m,
        (($rss{$m} - $base) > $size/4 ? "YES" : "no");
}
printf "  streaming and slurping agree on the count?         %s (%d vs %d)\n",
    ($found{stream} == $found{slurp} ? "YES" : "NO"), $found{stream}, $found{slurp};

Azvya Education Pvt. Ltd.VLSI Mentor

Captured output

log: 10 MB, 150300 lines -- every strategy below reads ALL of it

STRATEGY        holds             found     memory vs baseline
baseline        nothing           0         FLAT
stream          one line          300       FLAT
ring            20 lines          300       FLAT
hash_bounded    a few keys        2         FLAT
hash_unbounded  one key per line  150000    GREW
slurp           every line        300       GREW
forloop         every line        300       GREW
collect         every match       150000    GREW

verdicts (each strategy in its OWN process; 'grew' means by more
than a quarter of the log size, 'flat' means less):
  stream           stays FLAT?                        YES
  ring             stays FLAT?                        YES
  hash_bounded     stays FLAT?                        YES
  hash_unbounded   GREW?                              YES
  slurp            GREW?                              YES
  forloop          GREW?                              YES
  collect          GREW?                              YES
  streaming and slurping agree on the count?         YES (300 vs 300)

Four stay flat and four grow, and the grouping is not the one the usual advice predicts.

2. What You Hold, Not How You Read

Line up the two columns that matter — holds and memory — and the rule falls out:

holds	memory
nothing, one line, 20 lines, a few keys	flat
every line, every match, one key per line	grows

Memory tracks what is live at the end of the loop, not what passes through it. All eight strategies touch all 150,300 lines. The four that grow are the four still holding something proportional to the input when the loop finishes.

Two of those four are surprising, and they are the two worth knowing.

A for loop over a filehandle is a slurp. The diamond in list context builds the complete list of lines before the loop body runs once. It reads like a stream, it is indented like a stream, and it costs what my @lines = <$fh> costs. That is why Chapter 18.2's reference scan uses while, and why Chapter 13.2 insists on it; the measurement above is what the other keyword costs. Chapter 13.3 is the chapter on slurping, and this is the third way to do it by accident.

hash_bounded and hash_unbounded differ only in the key. Both read strictly one line at a time, never build a list, and never push onto an array. One stays flat on two keys; the other grows as much as the slurp, on 150,000. A hash of counts is flat only when its key set is bounded:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

$count{$severity}++;          # four or five keys, ever        -> flat
$count{$packet_id}++;         # one key per line               -> grows

So "stream, do not slurp" is not the rule. The rule is: nothing you keep may be proportional to the input. Streaming avoids one way of breaking that rule. It is not a guarantee you have not broken it another way.

The two accumulators that look innocent in review:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

push @all_errors, $line  if /^UVM_ERROR/;      # bounded only if errors are rare
$seen{$transaction_id}++;                      # one key per transaction

The first is fine on a log with twelve errors and fatal on a log with two million — and the log with two million errors is exactly the one you are debugging when it matters. If you need the errors, keep the first N and a count of the rest:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

if (/^UVM_ERROR/) {
    $errs++;
    push @sample, $_ if @sample < 50;          # a bounded sample
}
...
printf "%d errors; first %d shown\n", $errs, scalar @sample;

That reports the true total and shows enough to start work, in constant memory. A count plus a bounded sample is almost always what the reader of the report actually wanted, and it is the only version that survives the pathological log.

3. The Last N Lines, Without Keeping All Of Them

The ring row holds twenty lines and stays flat. The trick is two lines long:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

push @last, $line;
shift @last if @last > 20;

Every iteration appends and, once the window is full, drops the oldest. @last never exceeds twenty elements regardless of input size, and when the scan ends it holds the final twenty lines of the log — which is where a crashed tool's last words are.

This is the pattern for every "context around the interesting thing" problem:

The tail of a log. A window of the last N lines, printed when the scan ends.

Lines before an error. Keep a window; when an error line matches, print the window as its preceding context, then clear it.

Lines after an error. A countdown: set $after = 5 on a match, then print and decrement while it is positive.

All three are constant memory, and all three are what grep -B and grep -A do. Reach for them instead of collecting every line and slicing at the end — the slice is precisely the part that cannot run on a log larger than memory.

4. Compiling The Pattern Once

The advice is to hoist the pattern out of the loop with qr// (Chapter 11.18). The advice is right. The reason usually given for it is mostly wrong on a modern Perl.

Azvya Education Pvt. Ltd.VLSI Mentor

compiled.pl

use strict;
use warnings;
use Time::HiRes qw(time);

my @lines;
for my $i (1 .. 50_000) {
    push @lines, ($i % 125 == 0)
        ? "UVM_ERROR /proj/tb/scoreboard.sv(214) \@ ${i}000: mismatch\n"
        : "UVM_INFO /proj/tb/driver.sv($i) \@ ${i}000: sent id=$i\n";
}
my $ERRS = grep { /^UVM_ERROR/ } @lines;
printf "matching over %d lines, %d of them errors\n\n", scalar @lines, $ERRS;

my $SEV = "ERROR|FATAL";
my $RE  = qr/^UVM_($SEV)\b/;

# ---- case 1: ONE pattern, constant text
my ($win_c, $rounds, $tc_i, $tc_c) = (0, 5, 0, 0);
for (1 .. $rounds) {
    my ($t0, $n) = (time, 0);
    for my $l (@lines) { $n++ if $l =~ /^UVM_($SEV)\b/ }
    my $t_i = time - $t0;
    ($t0, $n) = (time, 0);
    for my $l (@lines) { $n++ if $l =~ $RE }
    my $t_c = time - $t0;
    $win_c++ if $t_c < $t_i;
    $tc_i += $t_i; $tc_c += $t_c;
}
my $cratio = $tc_c > 0 ? $tc_i / $tc_c : 0;
printf "ONE constant pattern:\n";
printf "  qr// faster by 2x or more?                     %s\n", ($cratio >= 2 ? "YES" : "no");
printf "  qr// faster by 1.5x or more?                   %s\n", ($cratio >= 1.5 ? "YES" : "no");
printf "  (which form wins a single round varies between runs,\n";
printf "   so the per-round count is noise and is not reported)\n";

# ---- case 2: the pattern text CHANGES every line
my @NEEDLES = ("ERROR", "FATAL", "WARNING", "INFO");
my %COMPILED = map { $_ => qr/^UVM_$_\b/ } @NEEDLES;

my ($win_v, $tv_i, $tv_c) = (0, 0, 0);
for (1 .. $rounds) {
    my ($t0, $n) = (time, 0);
    for my $l (@lines) {
        for my $needle (@NEEDLES) { $n++ if $l =~ /^UVM_$needle\b/ }   # recompiled: text differs
    }
    my $t_i = time - $t0;
    ($t0, $n) = (time, 0);
    for my $l (@lines) {
        for my $needle (@NEEDLES) { $n++ if $l =~ $COMPILED{$needle} } # compiled once, looked up
    }
    my $t_c = time - $t0;
    $win_v++ if $t_c < $t_i;
    $tv_i += $t_i; $tv_c += $t_c;
}
my $ratio = $tv_c > 0 ? $tv_i / $tv_c : 0;
printf "\nFOUR patterns, the text changing every match:\n";
printf "  pre-compiled faster in all %d rounds?           %s\n", $rounds,
    ($win_v == $rounds ? "YES" : "no");
printf "  faster by 1.5x or more?                        %s\n", ($ratio >= 1.5 ? "YES" : "no");
printf "  faster by 1.1x or more?                        %s\n", ($ratio >= 1.1 ? "YES" : "no");
printf "\nis the qr// win BIGGER when the text varies?      %s\n",
    ($ratio > $cratio ? "YES" : "no");
printf "  -> for a constant pattern Perl already caches the\n";
printf "     compiled form, so qr// mostly buys readability.\n";

Azvya Education Pvt. Ltd.VLSI Mentor

Captured output

matching over 50000 lines, 400 of them errors

ONE constant pattern:
  qr// faster by 2x or more?                     no
  qr// faster by 1.5x or more?                   no
  (which form wins a single round varies between runs,
   so the per-round count is noise and is not reported)

FOUR patterns, the text changing every match:
  pre-compiled faster in all 5 rounds?           YES
  faster by 1.5x or more?                        YES
  faster by 1.1x or more?                        YES

is the qr// win BIGGER when the text varies?      YES
  -> for a constant pattern Perl already caches the
     compiled form, so qr// mostly buys readability.

For one constant pattern, there is no meaningful win — not 2x, and not even 1.5x. Perl caches the compiled form of an interpolated pattern and reuses it as long as the interpolated text has not changed, so /^UVM_($SEV)\b/ with $SEV fixed is compiled once, not 50,000 times. Which of the two forms wins any single round is noise, which is why the script says so instead of printing a count.

For a pattern whose text varies, the win is real — faster in all five rounds and by at least 1.5x. There the cache is defeated on every match: each iteration interpolates a different needle, so each one is a new pattern to compile.

Three practical consequences:

Hoist patterns anyway. It costs nothing, and a named my $RE = qr/.../; at the top of the file is where the next person will look for it. Just do not expect the speed-up folklore promises.

Precompile a set of patterns into a hash, as %COMPILED does above, whenever you match several alternatives per line. That is where the measurement says the time actually is — and it is the same table-of-patterns structure Chapter 18.8 used for tool versions and Chapter 18.7 for fields.

Never interpolate a variable that changes inside a hot loop. If the needle varies, compile the needles once outside the loop and look them up.

Three more things that cost real time on a very large log, none of them regex:

grep in list context inside the loop builds a list in order to count it. grep { ... } @big is fine once (Chapter 5.10); the same call once per line is quadratic. Count with a scalar.

Growing one string with .= to hold the whole log, then matching against it, is the slurp again with extra steps — and it throws away every line-oriented tool you have.

Printing progress per line. One progress line per input line turns a two-minute scan into an I/O-bound crawl. Print progress every 100,000 lines, or not at all.

And if the log is compressed, read it through a pipe rather than expanding it to disk:

Azvya Education Pvt. Ltd.VLSI Mentor

Snippet

open my $fh, "-|", "gzip", "-dc", $log or die "gzip: $!\n";

The scan loop is unchanged, memory stays flat, and the expanded file never exists. Chapter 13.12 covers the encoding layers to set on a handle like this when the log is not plain ASCII.

5. Measuring Memory Honestly

The harness in section 1 runs each strategy in a separate child process. That is not tidiness. It is the only way the numbers mean anything, and I learned that by getting it wrong.

My first version measured every strategy in one process, and reported that slurping the log did not grow memory. It plainly does. Two facts combine to produce that lie:

Azvya Education Pvt. Ltd.VLSI Mentor

heaphold.pl

use strict;
use warnings;

sub rss_mb { my $k = `ps -o rss= -p $$`; $k =~ s/\D//g; return $k / 1024 }

my $base = rss_mb();

my @lines;
push @lines, "UVM_INFO /proj/tb/driver.sv($_) \@ ${_}000: sent packet id=$_\n"
    for 1 .. 150_000;
my $held = rss_mb();

@lines = ();                       # free every one of them
my $freed = rss_mb();

printf "holding %d lines grew the process?                  %s\n",
    150_000, ($held - $base > 5 ? "YES" : "no");
printf "freeing them returned the memory to the OS?         %s\n",
    ($freed < $base + ($held - $base) / 2 ? "YES" : "NO");
printf "RSS after freeing is still within 10%% of its peak?  %s\n",
    (abs($freed - $held) < $held * 0.10 ? "YES" : "no");

# so a SECOND allocation of the same size reuses that heap
my @again;
push @again, "UVM_INFO /proj/tb/driver.sv($_) \@ ${_}000: sent packet id=$_\n"
    for 1 .. 150_000;
my $second = rss_mb();
printf "\na SECOND %d-line slurp in the same process grew RSS? %s\n",
    150_000, ($second - $freed > 5 ? "YES" : "NO -- it reused the heap");
print "  ^ which is why each strategy must be measured in its own process:\n";
print "    measured here, the second allocation looks free when it is not.\n";

Azvya Education Pvt. Ltd.VLSI Mentor

Captured output

holding 150000 lines grew the process?                  YES
freeing them returned the memory to the OS?         NO
RSS after freeing is still within 10% of its peak?  YES

a SECOND 150000-line slurp in the same process grew RSS? NO -- it reused the heap
  ^ which is why each strategy must be measured in its own process:
    measured here, the second allocation looks free when it is not.

Perl does not return freed memory to the operating system. Freeing all 150,000 lines returned nothing; RSS stayed within 10% of its peak. The memory is free to Perl, which will reuse it, but the process never shrinks.

So every measurement after the first is taken against an inflated baseline. Measured above: a second slurp of the same size grew RSS by nothing at all. It is not cheap — it is reusing the heap the first one grew, and a reading taken that way reports it as free.

The fix is one process per strategy, which is what the defined $mode branch at the top of streaming.pl is for: the parent builds the log once, then re-runs the same script once per strategy, and each child reports its own peak against the baseline child.

The general version of this is worth more than the specific bug.

A measurement that agrees with what you expected is not evidence until you have checked it could have come out otherwise. My broken harness happened to print no where I expected YES, and that disagreement is the only reason I went looking. Had the broken harness agreed with me, I would have published it.

That is why the measured table includes baseline, which holds nothing and must come out flat, and why section 4 includes a case where the two forms are indistinguishable. A harness that reports "flat" for everything, or "faster" for everything, cannot be told apart from a broken one unless at least one row comes out the other way.

Timing and memory also need the reproducibility discipline the whole track uses: publish counts and bucketed verdicts, never raw figures. Four of this chapter's timing statements had to be coarsened before they held still across five consecutive runs — a band that flipped, a win count that read 5, 5 then 4, a threshold sitting exactly on the true value, and a line that was unstable because what it measured was noise.

6. What To Remember

The constraint is what you hold at the end of the loop, not how you read the file.
Measured, 8 strategies on a 10 MB / 150,300-line log, each in its own process: 4 flat, 4 grew.
Flat: holding nothing, one line, a 20-line window, or a hash with a few keys.
Grows: every line, every match, or one hash key per line.
A for loop over a filehandle is a slurp — the list is built in full before the body runs once. Use while.
Streaming does not save you if you accumulate. hash_unbounded reads one line at a time and grows like the slurp.
A hash of counts is flat only when its key set is bounded — severities yes, packet ids no.
Keep a count plus a bounded sample, not every match: push @sample, $_ if @sample < 50.
Ring buffer for the last N lines: push, then shift ... if @last > N. Constant memory, and it is how you get context before and after a match.
Hoist patterns with qr// — but the measured reason is not the usual one.
A constant interpolated pattern is already cached by Perl: measured, not a 1.5x win, let alone 2x.
The real win (1.5x or more, all 5 rounds) is when the pattern text varies — so precompile a hash of patterns.
Avoid per-line grep in list context, whole-log string building, and per-line progress printing.
Read a compressed log through open "-|", "gzip", "-dc" — flat memory, nothing expanded to disk.
Perl does not return freed memory to the OS — measured: freeing 150,000 lines left RSS within 10% of its peak.
So measure one strategy per process, or every reading after the first sits on an inflated baseline.
A measurement that agrees with your expectation is not evidence until you know it could have disagreed.
Publish counts and bucketed verdicts, never raw timings or megabytes.

Chapter 18.11 closes the module by marking its limits. Everything here has assumed that what you want is a known field on a recognisable line — and the last chapter is about the questions where that assumption fails, and pattern matching is simply the wrong instrument.

Where this fits

Part of the Perl curriculum.