The Perl Debugger: perl -d

Part I · Module 14 · Chapter 14.10 · The Perl Debugger: perl -d

1. Starting It, And The Six Commands

perl -d analyse.pl            # debug a script
perl -d analyse.pl report.rpt # arguments work exactly as normal
perl -d -e 'print 1+1'        # debug a one-liner

No module to install, no flag in the script, no recompilation. The -d switch is all of it. You land at a prompt that looks like DB<1> with the first executable line shown but not yet run.

The commands worth memorising:

Four more that save time once the first seven are habit:

• l lists the source around where you are; v shows a wider window.
• T prints a stack trace from here — who called this, and with what.
• r runs until the current subroutine returns, and shows the return value.
• c 20 continues to line 20 once, without setting a permanent breakpoint.

The one to understand properly is n against s. n treats a subroutine call as a single step: it runs the whole call and stops on the line after. s goes inside it. Use n while you are narrowing down which line misbehaves, then s on that line to go in.

2. A Real Session

The debugger is interactive, so to put a session in a tutorial honestly it has to be captured rather than typed out from memory. The script below writes a small program, writes a list of debugger commands, runs perl -d against both, and prints what came back.

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

my $dir  = tempdir(CLEANUP => 1);
my $prog = File::Spec->catfile($dir, "analyse.pl");
my $cmds = File::Spec->catfile($dir, "session.txt");

open my $w, ">", $prog or die "cannot write: $!\n";
print $w <<'PROG';
use strict;
use warnings;
$| = 1;

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

sub worst {
    my (%s) = @_;
    my $worst_pin = "";
    my $worst_val;
    for my $pin (sort keys %s) {
        if (!defined $worst_val || $s{$pin} < $worst_val) {
            $worst_val = $s{$pin};
            $worst_pin = $pin;
        }
    }
    return ($worst_pin, $worst_val);
}

my ($pin, $val) = worst(%slack);
printf "worst: %s at %.3f\n", $pin, $val;
PROG
close $w;

my @session = (
    'b worst',                                         # break on the subroutine
    'c',                                               # run to it
    'n',                                               # execute my (%s) = @_
    'p join(",", sort keys %s)',                       # which pins arrived
    'p join(", ", map { "$_=$s{$_}" } sort keys %s)',  # sorted: reproducible
    'b 17',                                            # break on a LINE number
    'c',                                               # run to it
    'p "pin=$worst_pin val=$worst_val"',               # the computed answer
    'c',                                               # let it finish
    'q',
);
open my $c, ">", $cmds or die "cannot write: $!\n";
print $c join("\n", @session), "\n";
close $c;

my $out = `cd '$dir' && perl -d analyse.pl < session.txt 2>&1`;

# mask the three things that change between runs
$out =~ s/HASH\(0x[0-9a-f]+\)/HASH(0xADDR)/g;
$out =~ s/\Q$dir\E\/?//g;
$out =~ s/perl5db\.pl version [\d._]+/perl5db.pl version V/;

# the debugger's final prompt has NO trailing newline; without this the next
# thing printed lands on the same line as "DB<6>"
$out .= "\n" unless $out =~ /\n\z/;
print $out;

Loading DB routines from perl5db.pl version V
Editor support available.

Enter h or 'h h' for help, or 'man perldebug' for more help.

main::(analyse.pl:3):	$| = 1;
  DB<1>   DB<2> main::worst(analyse.pl:8):	    my (%s) = @_;
  DB<2> main::worst(analyse.pl:9):	    my $worst_pin = "";
  DB<2> U1/Q,U2/D,U3/CK
  DB<3> U1/Q=0.44, U2/D=-0.03, U3/CK=0.12
  DB<4>   DB<5> main::worst(analyse.pl:17):	    return ($worst_pin, $worst_val);
  DB<5> pin=U2/D val=-0.03
  DB<6> worst: U2/D at -0.030
Debugged program terminated.  Use q to quit or R to restart,
use o inhibit_exit to avoid stopping after program termination,
h q, h R or h o to get additional info.
  DB<6>

Walking through what the transcript shows:

b worst then c stopped at analyse.pl:8, the first line inside the subroutine. Note that it stopped before that line ran.

n executed my (%s) = @_ and moved to line 9. This is the step people miss: at a subroutine breakpoint the arguments have not been unpacked yet, so inspecting %s immediately shows an empty hash and looks like the caller passed nothing.

The two p commands then show the data: the keys, and the keys with their values. Both are sorted deliberately — see the warning below.

b 17 then c ran the whole loop and stopped on the return line, where the answer exists. A line-number breakpoint is often more useful than stepping, because you can skip over a hundred iterations you do not care about.

p "pin=$worst_pin val=$worst_val" gives pin=U2/D val=-0.03. That is the computed result, visible before it is returned.

c let the program finish, and its own output worst: U2/D at -0.030 appears.

3. Using It Without Sitting There

A batch job has nobody at a terminal, and a plain perl -d would stop at the first line and wait forever. PERLDB_OPTS fixes that.

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

my $dir  = tempdir(CLEANUP => 1);
my $prog = File::Spec->catfile($dir, "crash.pl");

open my $w, ">", $prog or die "cannot write: $!\n";
print $w <<'PROG';
use strict;
use warnings;
sub level3 { my $d = shift; return 42 / $d }
sub level2 { return level3(@_) }
sub level1 { return level2(@_) }
print "result: ", level1(0), "\n";
PROG
close $w;

print "--- plain run: one line, no context\n";
my $plain = `cd '$dir' && perl crash.pl 2>&1`;
my $plain_rc = $? >> 8;
$plain =~ s/\s+\z//;
print "    $plain\n    exit $plain_rc\n";

print "\n--- with PERLDB_OPTS=\"NonStop AutoTrace\"\n";
my $traced = `cd '$dir' && PERLDB_OPTS="NonStop AutoTrace" perl -d crash.pl 2>&1`;
my $traced_rc = $? >> 8;
# keep only the frames, dropping the per-line trace through warnings.pm
for my $line (split /\n/, $traced) {
    next unless $line =~ /crash\.pl/;
    next if $line =~ /CODE\(0x/;          # compile-time frames: no information
    print "    $line\n";
}
print "    exit $traced_rc\n";

--- plain run: one line, no context
    Illegal division by zero at crash.pl line 3.
    exit 255

--- with PERLDB_OPTS="NonStop AutoTrace"
    main::(crash.pl:6):	print "result: ", level1(0), "\n";
    main::level1(crash.pl:5):	sub level1 { return level2(@_) }
    main::level2(crash.pl:4):	sub level2 { return level3(@_) }
    main::level3(crash.pl:3):	sub level3 { my $d = shift; return 42 / $d }
    main::level3(crash.pl:3):	sub level3 { my $d = shift; return 42 / $d }
    Illegal division by zero at crash.pl line 3.
     at crash.pl line 3.
    	main::level3(0) called at crash.pl line 4
    	main::level2(0) called at crash.pl line 5
    	main::level1(0) called at crash.pl line 6
    exit 255

The plain run gave one line: Illegal division by zero at crash.pl line 3. True, and it does not tell you which of the three callers passed the zero.

With NonStop AutoTrace, the same failure produced every line as it executed and then a full stack trace naming each frame with its arguments — main::level1(0) called at crash.pl line 6. The zero is visible entering at the top. Exit status is 255 either way, so this changes the diagnostics and nothing else.

The options worth knowing:

• NonStop=1 — never stop for input. Essential for anything unattended.
• AutoTrace=1 — print each line as it runs. Verbose, and the point.
• LineInfo=file — send all of that to a file instead of the terminal.
• frame=2 — show subroutine entry and exit instead of every line, which is far more readable on a long run.

So the form to remember for a real job:

PERLDB_OPTS="NonStop frame=2 LineInfo=/tmp/trace.txt" perl -d analyse.pl

That runs normally, writes a call-by-call trace to a file, and costs you nothing but speed.

4. A Stack Trace With No Debugger At All

Often you do not want a trace of everything — you want a trace at the moment of death, out of a script running somewhere you cannot attach to. Chapter 14.9's confess does it, wired into the __DIE__ handler.

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

my $dir  = tempdir(CLEANUP => 1);
my $prog = File::Spec->catfile($dir, "traced.pl");

open my $w, ">", $prog or die "cannot write: $!\n";
print $w <<'PROG';
use strict;
use warnings;
use Carp qw(confess);

# turn any uncaught death into a death WITH a stack trace.
# $^S is false only for a die that is NOT inside an eval, so a
# caught exception is left completely alone.
local $SIG{__DIE__} = sub { confess @_ unless $^S };

sub level3 { my $d = shift; return 42 / $d }
sub level2 { return level3(@_) }
sub level1 { return level2(@_) }
print "result: ", level1(0), "\n";
PROG
close $w;

# redirect to files so the exit status is the SCRIPT's, not a pipe's
my $log = File::Spec->catfile($dir, "err.txt");
system("cd '$dir' && perl traced.pl >/dev/null 2>'$log'");
my $rc = $? >> 8;

open my $r, "<", $log or die "cannot read: $!\n";
for my $line (<$r>) {
    $line =~ s/\s+\z//;
    $line =~ s/\\x\{a\}//g;
    print "    $line\n";
}
close $r;
printf "    exit %d\n", $rc;

    Illegal division by zero at traced.pl line 10.
     at traced.pl line 8.
    	main::__ANON__("Illegal division by zero at traced.pl line 10.") called at traced.pl line 10
    	main::level3(0) called at traced.pl line 11
    	main::level2(0) called at traced.pl line 12
    	main::level1(0) called at traced.pl line 13
    exit 255

Three frames, each with the argument that was passed, and the 0 is visible travelling from level1 all the way down. No debugger, no change to how the script runs, and it works in a cron job.

Two details that matter:

unless $^S is the important part. $^S is true while Perl is inside an eval, so this handler adds a trace only to a death that nobody caught. Without that guard, every eval in the program — including ones inside modules you did not write — gets a stack trace bolted onto its error message, and Chapter 14.4's careful error handling turns into noise.

The exit status is 255, and getting that number right took a second measurement. The first time, the script's output was read through a pipe into another command and the status came back as 0 — because a pipeline reports the status of the last command in it, not the first. This is the same hazard Chapter 14.3 measured in system("a; true"). Redirecting to a file, as the script above does, gives you the real status.

5. What To Remember

• perl -d script.pl is all the setup there is. Nothing to install, no change to the script.
• You stop before the shown line runs, both at the start and at a breakpoint.
• Six commands cover most work: n, s, c, b, p, q — plus l, T, r and c 20.
• n steps over a call, s steps into it. Narrow down with n, then s the suspect line.
• At a subroutine breakpoint the arguments are not unpacked yet — step once with n before inspecting them, or they look empty.
• A line-number breakpoint often beats stepping, because it skips iterations you do not care about.
• Sort before you dump. Measured: x %s gave three different outputs in three runs, because hash order is randomised per process.
• Put $| = 1; in a script you are debugging, or its own output arrives after the debugger says it finished.
• PERLDB_OPTS="NonStop ..." makes it usable unattended — AutoTrace for every line, frame=2 for calls only, LineInfo= to a file.
• Measured: a plain crash gave one line; NonStop AutoTrace gave the full chain with each frame's arguments, same exit 255.
• $SIG{__DIE__} with Carp::confess gives a trace on death with no debugger at all.
• Guard it with unless $^S so caught exceptions inside eval are left alone.
• Measured: that script exits 255 — and reading its status through a pipe reported 0, because a pipeline gives you the last command's status.
• Debugger when you have no hypothesis; a print when you do.

Chapter 14.11 closes the module. A script that runs unattended needs a record of what it did, with a timestamp and a severity on every line, written to a file as well as the screen — because a failure overnight that left no trace cannot be explained the next morning.