print-Debugging Done Properly

Part I · Module 14 · Chapter 14.8 · print-Debugging Done Properly

1. Use STDERR — And Know Why The Order Changes

The first rule is easy: debug output goes to standard error, not standard output.

print STDERR "slack for $pin = $value\n";

Two reasons, one obvious and one that catches people out.

The obvious one is separation. Chapter 14.2 established that stdout and stderr are different streams. Your script's real output — the report, the data, the list of failing pins — belongs on stdout, where > report.txt captures it cleanly. A debug line printed to stdout ends up inside the report, and in a script whose output feeds another tool, that is a corrupted input rather than a helpful note.

The second reason is the one worth measuring.

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

my $dir = tempdir(CLEANUP => 1);

my %variants = (
    "buffered.pl"  => qq{print "1: stdout\\n";\nprint STDERR "2: stderr\\n";\n}
                    . qq{print "3: stdout\\n";\nprint STDERR "4: stderr\\n";\n},
    "autoflush.pl" => qq{\$| = 1;\nprint "1: stdout\\n";\nprint STDERR "2: stderr\\n";\n}
                    . qq{print "3: stdout\\n";\nprint STDERR "4: stderr\\n";\n},
);

for my $name (sort keys %variants) {
    my $script = File::Spec->catfile($dir, $name);
    my $log    = File::Spec->catfile($dir, "$name.log");
    open my $w, ">", $script or die "cannot write: $!\n";
    print $w $variants{$name};
    close $w;

    # both streams into ONE file -- the batch-job case
    system("perl '$script' > '$log' 2>&1");

    open my $r, "<", $log or die "cannot read: $!\n";
    my @lines = <$r>;
    close $r;
    chomp @lines;

    my @order = map { /^(\d)/ ? $1 : "?" } @lines;
    printf "%-13s script printed 1,2,3,4 -> file holds %s\n", $name, join(",", @order);
}

autoflush.pl  script printed 1,2,3,4 -> file holds 1,2,3,4
buffered.pl   script printed 1,2,3,4 -> file holds 2,4,1,3

Read that carefully, because it is not a typo. Both scripts printed in the order 1, 2, 3, 4. The first one's log file holds 2, 4, 1, 3.

The cause is buffering. When standard output is not a terminal — when it is a file, or a pipe, or a Vercel build log — Perl block-buffers it and only writes when the buffer fills or the program ends. Standard error is never buffered that way. So every stderr line hits the file immediately while every stdout line waits until the end, and the two streams arrive in completely different groups.

The practical consequence is nasty. You add a debug line before a block of real output, run the script into a log, and the debug line appears after the output it was supposed to precede. The natural conclusion — that the code ran in a different order than you thought — is wrong. Only the file was written in a different order.

The fix is one line, and the second variant measures it working:

$| = 1;        # autoflush STDOUT; now the two streams interleave correctly

$| set to a true value makes Perl flush standard output after every write. The order in the log then matches the order the script printed, as measured. It costs a little speed on a script that prints heavily, which is irrelevant while you are debugging.

2. Bracket The Value

The second rule: never print a value bare. Put something around it.

use strict;
use warnings;

my @values = ("0.44", "0.44 ", " 0.44", "0.44\t", "0.44\n", "");

for my $v (@values) {
    (my $escaped = $v) =~ s/\t/\\t/g;
    $escaped =~ s/\n/\\n/g;

    # how a bare print shows it, with real control characters removed
    (my $bare = $v) =~ s/[\t\n]//g;

    printf "bare: %-8s bracketed: %-10s length %d\n", $bare, "[$escaped]", length $v;
}

bare: 0.44     bracketed: [0.44]     length 4
bare: 0.44     bracketed: [0.44 ]    length 5
bare:  0.44    bracketed: [ 0.44]    length 5
bare: 0.44     bracketed: [0.44\t]   length 5
bare: 0.44     bracketed: [0.44\n]   length 5
bare:          bracketed: []         length 0

Five of those six values print as 0.44. They are not the same value — the lengths are 4, 5, 5, 5 and 5 — and the differences are exactly the ones that break a comparison:

• "0.44 " with a trailing space fails eq "0.44" and fails a numeric match anchored with \z.
• " 0.44" with a leading space does the same.
• "0.44\t" is what you get from splitting on the wrong delimiter.
• "0.44\n" is what you get when you forget chomp, which Chapter 13.2 covered.

And the sixth value is the worst. An empty string prints as nothing at all, so a debug line printing a bare empty value is indistinguishable from a debug line that never ran. You stare at the absent output and conclude the branch was not taken, when actually it was taken and the value was empty.

So the habit is:

print STDERR "pin=[$pin] slack=[$slack]\n";

Brackets, and a name for each value. The name matters as much as the brackets once you have more than one debug line, because [0.44] [3] tells you nothing about which is which.

For the whitespace-is-invisible problem specifically, make it visible:

(my $show = $value) =~ s/([\t\n\r])/{ "\t"=>'\t', "\n"=>'\n', "\r"=>'\r' }->{$1}/ge;
print STDERR "value=[$show] length=${\ length $value }\n";

Printing the length alongside the value is the cheapest version of this and often enough on its own. A length that disagrees with what you can see is the whole answer.

3. Structures Need Data::Dumper

Printing a reference gives you its type and address, which is almost never what you wanted.

use strict;
use warnings;
use Data::Dumper;

my %report = (
    "U1/Q" => { slack => 0.44, check => "setup" },
    "U2/D" => { slack => -0.03, check => "hold"  },
);

print "a bare print of the hash ref:\n";
my $ref = \%report;
print "  ", ($ref =~ s/0x[0-9a-f]+/0xADDR/r), "\n";

# make the output stable and compact enough to read
$Data::Dumper::Sortkeys = 1;     # without this, key order varies run to run
$Data::Dumper::Indent   = 1;     # 2 is the default and very tall
$Data::Dumper::Terse    = 1;     # drop the "$VAR1 = " prefix

print "\nwith Data::Dumper:\n";
print Dumper(\%report);

a bare print of the hash ref:
  HASH(0xADDR)

with Data::Dumper:
{
  'U1/Q' => {
    'check' => 'setup',
    'slack' => '0.44'
  },
  'U2/D' => {
    'check' => 'hold',
    'slack' => '-0.03'
  }
}

The bare print gave HASH(0xADDR) — the script had to mask the address, because it changes on every run. That is the other reason not to print references raw: the output is not reproducible, so you cannot diff two runs.

The three settings are worth knowing because the defaults are awkward:

• Sortkeys = 1 puts the keys in a fixed order. Without it, Perl's hash ordering varies between runs, so two dumps of identical data can differ — and comparing two dumps is the main reason to make one. This is Chapter 6.6's point about hash order changing between runs, with a practical consequence.
• Indent = 1 is compact. The default, 2, aligns everything into a very tall column.
• Terse = 1 drops the $VAR1 = wrapper, which is noise unless you intend to eval the output back.

Data::Dumper is in core, so it is always available — Chapter 12.9 listed it among the modules you can rely on without a thought.

4. Leave It In, Switched Off

A debug line that gets deleted the moment it works has to be retyped the next time. The alternative is to leave it in and gate it.

use strict;
use warnings;

# one knob, from the environment, defaulting to quiet
my $DEBUG = $ENV{SLACK_DEBUG} // 0;

sub debug {
    my ($level, @message) = @_;
    return if $level > $DEBUG;
    print STDERR "[debug$level] ", @message, "\n";
}

sub analyse {
    my (%slack) = @_;
    debug(1, "analysing ", scalar(keys %slack), " pins");

    my @failing;
    for my $pin (sort keys %slack) {
        debug(2, "  pin=[$pin] slack=[", $slack{$pin}, "]");
        push @failing, $pin if $slack{$pin} < 0;
    }
    debug(1, "found ", scalar @failing, " failing");
    return @failing;
}

my %slack = ("U1/Q" => 0.44, "U2/D" => -0.03, "U3/CK" => 0.12);

for my $level (0, 1, 2) {
    $DEBUG = $level;
    print "--- SLACK_DEBUG=$level\n";
    my @bad = analyse(%slack);
    print "    result: ", join(", ", @bad), "\n";
}

--- SLACK_DEBUG=0
    result: U2/D
--- SLACK_DEBUG=1
    result: U2/D
--- SLACK_DEBUG=2
    result: U2/D

Only the result: lines are on standard output. Everything in brackets went to standard error, so the three debug levels produced no change at all in what the script returns — which is the property that makes it safe to leave in.

Four things that make this worth copying:

One knob, read from the environment. SLACK_DEBUG=2 ./analyse.pl with nothing recompiled and no flag parsing. Reading one environment variable is all this needs.

Levels, not a boolean. Level 1 is a handful of lines about what the script is doing. Level 2 is per-item detail that would be unreadable on a real report of ten thousand pins. A single on/off switch forces you to choose between useless and overwhelming.

The return if comes first. The cost of a switched-off debug(2, ...) call is one comparison. Note, though, that the arguments are still evaluated before the call, so a debug line that calls an expensive function pays for it even when switched off. Where that matters, guard the call itself: debug(2, expensive()) if $DEBUG >= 2;

Everything goes to STDERR. So the gate changes the diagnostics and nothing else.

5. What To Remember

• Debug output goes to STDERR, so it never lands inside your real output.
• Measured: the order in a log file is not the order you printed. 1, 2, 3, 4 became 2, 4, 1, 3 once stdout was redirected, because stdout is block-buffered and stderr is not.
• That scrambling makes a debug line look like it came from the wrong place. The script ran in order; the file was written out of order.
• $| = 1; fixes it, measured — or STDOUT->autoflush(1);, which is readable.
• Never print a value bare. Measured: five distinguishable values all appear as 0.44.
• An empty value prints as nothing, which is indistinguishable from a line that never ran.
• Bracket it and name it — pin=[$pin] slack=[$slack] — and print the length when whitespace is in question.
• Printing a reference gives HASH(0x...), and the address changes every run, so it cannot be diffed.
• Use Data::Dumper with Sortkeys = 1 so two runs are comparable, plus Indent = 1 and Terse = 1.
• Gate debug output behind one environment variable and leave it in the script.
• Use levels, not a boolean, so you can have a summary without per-item noise.
• Arguments are evaluated even when the level is off — guard the call where the arguments are expensive.
• Keep the helper dumb. Anything with state belongs in a logger, which is Chapter 14.11.

Chapter 14.9 solves a problem that printing cannot. When a helper subroutine rejects its input, the error points at the helper — which is the one place you already know is fine. Carp makes it point at the line that called it instead.