Trace your Perl programs

You can write your own mini (or micro) debuggers to watch your program run. You might want to do this when the other Perl debuggers are too heavyweight (or even too interactive) for your immediate problem.

The Devel::Trace module is a simple debugging tool that lets you watch the flow of control as your program runs. It’s not a debugger and you don’t get to interact with it, but it can be useful in some operations.

If you were a shell programmer in a former life, you probably used the -x switch to watch your shell script execute. Here’s simple script:

#!/bin/sh

echo $HOME
cd ~/Dev/effective-perl-programming
du -s

When you run it with the -x, it prints each line of the script before it executes it:

% sh -x trace.sh
+ echo /Users/brian
/Users/brian
+ cd /Users/brian/Dev/effective-perl-programming
+ du -s
200320  .

You can do the same thing with a Perl program. Here’s a small program to find factorials:

use v5.10;
use strict;
use warnings;

my $n = $ARGV[0];

my $product = 1;

foreach ( 1 .. $n ) {
	$product *= $_;
	}
	
say $product;

The output shows each line as perl executes it:

% perl -d:Trace factorial.pl
>> factorial.pl:5: my $n = $ARGV[0];
>> factorial.pl:7: my $product = 1;
>> factorial.pl:9: foreach ( 1 .. $n ) {
>> factorial.pl:10: 	$product *= $_;
>> factorial.pl:10: 	$product *= $_;
>> factorial.pl:10: 	$product *= $_;
>> factorial.pl:13: say $product;
6

Devel::Trace doesn’t limit itself to your program though. If you use the bignum module, the multiplication happens on objects instead of Perl numbers:

use v5.10;
use strict;
use warnings;
use bignum;

my $n = $ARGV[0];

my $product = 1;

foreach ( 1 .. $n ) {
	$product *= $_;
	}
	
say $product;

Try it with a number that requires bignum, there’s quite a bit of output:

% perl -d:Trace fact.pl 200
>> fact.pl:6: my $n = $ARGV[0];
>> fact.pl:8: my $product = 1;
>> fact.pl:10: foreach ( 1 .. $n ) {
>> /usr/local/perls/perl-5.14.1/lib/5.14.1/Math/BigInt.pm:152: '0+' => sub { $_[0]->numify(); }
>> /usr/local/perls/perl-5.14.1/lib/5.14.1/Math/BigInt.pm:839:   my $x = shift; $x = $class->new($x) unless ref $x;
>> /usr/local/perls/perl-5.14.1/lib/5.14.1/Math/BigInt.pm:839:   my $x = shift; $x = $class->new($x) unless ref $x;
>> /usr/local/perls/perl-5.14.1/lib/5.14.1/Math/BigInt.pm:841:   return $x->bstr() if $x->{sign} !~ /^[+-]$/;
>> /usr/local/perls/perl-5.14.1/lib/5.14.1/Math/BigInt.pm:842:   my $num = $CALC->_num($x->{value});
>> /usr/local/perls/perl-5.14.1/lib/5.14.1/Math/BigInt/Calc.pm:276:     my $x = $_[1];
>> /usr/local/perls/perl-5.14.1/lib/5.14.1/Math/BigInt/Calc.pm:278:     return 0 + $x->[0] if scalar @$x == 1;      # below $BASE
>> /usr/local/perls/perl-5.14.1/lib/5.14.1/Math/BigInt.pm:843:   return -$num if $x->{sign} eq '-';
.... # about 23,800 more lines
>> /usr/local/perls/perl-5.14.1/lib/5.14.1/Math/BigInt/Calc.pm:268:     $l--;
>> /usr/local/perls/perl-5.14.1/lib/5.14.1/Math/BigInt/Calc.pm:267:     $ret .= substr($z.$ar->[$l],-$BASE_LEN); # fastest way I could think of
>> /usr/local/perls/perl-5.14.1/lib/5.14.1/Math/BigInt/Calc.pm:268:     $l--;
>> /usr/local/perls/perl-5.14.1/lib/5.14.1/Math/BigInt/Calc.pm:270:   $ret;
788657867364790503552363213932185062295135977687173263294742533244359449963403342920304284011984623904177212138919638830257642790242637105061926624952829931113462857270763317237396988943922445621451664240254033291864131227428294853277524242407573903240321257405579568660226031904170324062351700858796178922222789623703897374720000000000000000000000000000000000000000000000000

That’s pretty ugly, and the Devel::Trace module doesn’t give you any way to change it. That’s not surprising consider the source code, which is

package Devel::Trace;
$VERSION = '0.11';
$TRACE = 1;

# This is the important part.  The rest is just fluff.
sub DB::DB {
  return unless $TRACE;
  my ($p, $f, $l) = caller;
  my $code = \@{"::_<$f"};
  print STDERR ">> $f:$l: $code->[$l]";
}


sub import {
  my $package = shift;
  foreach (@_) {
    if ($_ eq 'trace') {
      my $caller = caller;
      *{$caller . '::trace'} = \&{$package . '::trace'};
    } else {
      use Carp;
      croak "Package $package does not export `$_'; aborting";
    }
  }
}

my %tracearg = ('on' => 1, 'off' => 0);
sub trace {
  my $arg = shift;
  $arg = $tracearg{$arg} while exists $tracearg{$arg};
  $TRACE = $arg;
}

1;

The magic happens in DB::DB, which, when perl calls before every statement. This module is Devel::Trace, but its defining its meat in the package DB. The debugger stashes lots of information about the program in various package variables. The @{"::_<$f"} is a symbolic reference, using the filename in $f to translate the filename and line number from caller to a line of code.

You don't need the module, really. The import and trace subroutines are there just to turn things on and off. To do that, you'd have to modify your code to litter calls to trace throughout the code. You usually don't want to modify the code.

You can reduce that module to a command line. When you run the debugger, perl inserts the value in the PERL5BD environment variable before the source in your program. The reduces Devel::Trace to:

PERL5DB='sub DB::DB {my @c=caller;print STDERR qq|@c[1,2] ${"::_<$c[1]"}[$c[2]]|}' perl5.14.1 -d fact.pl 4

That's a bit hard to use, especially on a command line that tries to interpret those sigils characters. You don't need to worry about that now that you know how simple it is. You can create your own throw-away module to trace exactly what you want. Since the current directory is usually already in @INC, you can create a Devel/MyTrace.pm. This one saves to the file you specify:

use v5.10;
use autodie;

BEGIN {

my $trace_file = $ENV{TRACE_FILE} // "mytrace.$$";
print STDERR "Saving trace to $trace_file\n";
open my $fh, '>>', $trace_file;

sub DB::DB {
	my( $package, $file, $line ) = caller;
	my $code = \@{"::_<$file"};
	print $fh "[@{[time]}] $file $line $code->[$line]";
	}
}

1;

That is only slightly improved on Devel::Trace because it lets you specify the file in which to save your trace. You can improve that a bit to also handle the special - or STDERR virtual filenames:

use v5.10;
use autodie;

BEGIN {

my $trace_file = $ENV{TRACE_FILE} // "mytrace.$$";
print STDERR "Saving trace to $trace_file\n";

my $fh = do {
	   if( $trace_file eq '-'      ) { \*STDOUT }
	elsif( $trace_file eq 'STDERR' ) { \*STDERR }
	else { 
		open my $fh, '>>', $trace_file;
		$fh;
		}
	};

sub DB::DB {
	my( $package, $file, $line ) = caller;
	my $code = \@{"::_<$file"};
	print $fh "[@{[time]}] $file $line $code->[$line]";
	}
}

1;

You can go one step further to exclude all code except for the primary file:

use v5.10;
use autodie;

BEGIN {

my $trace_file = $ENV{TRACE_FILE} // "mytrace.$$";
print STDERR "Saving trace to $trace_file\n";

my $fh = do {
	   if( $trace_file eq '-'      ) { \*STDOUT }
	elsif( $trace_file eq 'STDERR' ) { \*STDERR }
	else { 
		open my $fh, '>>', $trace_file;
		$fh;
		}
	};

sub DB::DB {
	my( $package, $file, $line ) = caller;
	return unless $file eq $0;
	my $code = \@{"::_<$file"};
	print $fh "[@{[time]}] $file $line $code->[$line]";
	}
}

1;

From there, what your tracer does is up to you and what problem you are trying to track down. It doesn't have to be fancy and you don't have to spend a lot of time making it perfect or "pure".

Things to remember

  • You can trace your Perl program just like a shell program
  • Under the -d switch, perl calls &DB::DB before each statement
  • You can write your own throw-away tracer