Debugging Perl - Program Tracing
(Page 4 of 5 )
The Carp module also provides the cluck and confess subroutines to dump stack traces. cluck is akin to warn (or carp) in that it prints its message but lets the program continue. confess does the same thing, but like die, stops the program once it prints its mess.#
Both cluck and confess print stack traces, which show the list of subroutine calls and their arguments. Each subroutine call puts a frame with all of its information onto the stack. When the subroutine finishes, Perl removes the frame for that subroutine, and then Perl looks on the stack for the next frame to process. Alternately, if a subroutine calls another subroutine, that puts another frame on the stack.
Here’s a short program that has a chain of subroutine calls. I call the do_it function, which calls multiply_and_divide, which in turn calls the divide. Now, in this situation, I’m not getting the right answer for dividing 4 by 5. In this short example, you can probably spot the error right away, but imagine this is a huge mess of arguments, subroutine calls, and other madness:
#!/usr/bin/perl
use warnings;
use Carp qw(cluck);
print join " ", do_it( 4, 5 ), "\n";
sub do_it
{
my( $n, $m ) = @_;
my $sum = $n + $m;
my( $product, $quotient ) =
multiply_and_divide( [ $n, $m ], 6, { cat => 'buster' } );
return ( $sum, $product, $quotient );
}
sub multiply_and_divide
{
my( $n, $m ) = @{$_[0]};
my $product = $n * $m;
my $quotient = divide( $n, $n );
return ( $product, $quotient );
}
sub divide
{
my( $n, $m ) = @_;
my $quotient = $n / $m;
}
I suspect that something is not right in the divide subroutine, but I also know that it’s at the end of a chain of subroutine calls. I want to examine the path that got me to divide, so I want a stack trace. I modify divide to use cluck, the warn version of Carp’s stack tracing, and I put a line of hyphens before and after the cluck() to set apart its output to make it easier to read:
sub divide
{
print "-" x 73, "\n";
cluck();
print "-" x 73, "\n";
my( $n, $m ) = @_;
my $quotient = $n / $m;
}
The output shows me the list of subroutine calls, with the most recent subroutine call first (so, the list shows the stack order). The stack trace shows me the package name, subroutine name, and the arguments. Looking at the arguments to divide, I see a repeated 4. One of those arguments should be 5. It’s not divide’s fault after all:
---------------------------------------
at confess.pl line 68
---------------------------------------
main::divide(4, 4) called at confess.pl line 60
main::multiply_and_divide('ARRAY(0x180064c)') called at confess.pl line 49
main::do_it(4, 5) called at confess.pl line 41
9 20 1
It’s not a problem with divide, but with the information I sent to it. That’s from multiply_and_divide, and looking at its call to divide I see that I passed the same argument twice. If I’d been wearing my glasses, I might have been able to notice that $n might look like $m, but really isn’t:
my $quotient = divide( $n, $n ); # WRONG
my $quotient = divide( $n, $m ); # SHOULD BE LIKE THIS
This was a simple example, and still Carp had some problems with it. In the argument list for multiply_and_divide, I just get 'ARRAY(0x180064c)'. That’s not very helpful. Luckily for me, I know how to customize modules (Chapters 9 and 10), and by looking at Carp, I find that the argument formatter is in Carp::Heavy. The relevant part of the subroutine has a branch for dealing with references:
package Carp;
# This is in Carp/Heavy.pm
sub format_arg {
my $arg = shift;
...
elsif (ref($arg)) {
$arg = defined($overload::VERSION) ? overload::StrVal($arg) : "$arg";
}
...
return $arg;
}
If format_arg sees a reference, it checks for the overload module, which lets me define my own actions for Perl operations, including stringification. If Carp sees that I’ve somehow loaded overload, it tries to use the overload::StrVal subroutine to turn the reference into something I can read. If I haven’t loaded overload, it simply interpolates the reference in double quotes, yielding something like the
ARRAY(0x180064c) I saw before.
The format_arg function is a bit simple-minded, though. I might have used the overload module in one package, but that doesn’t mean I used it in another. Simply checking that I’ve used it once somewhere in the program doesn’t mean it applies to every reference. Additionally, I might not have even used it to stringify references. Lastly, I can’t really retroactively use overload for all the objects and references in a long stack trace, especially when I didn’t create most of those modules. I need a better way.
I can override Carp’s format_arg to do what I need. I copy the existing code into a BEGIN block so I can bend it to my will. First, I load its original source file, Carp::Heavy, so I get the original definition loaded first. I replace the subroutine definition by assigning to its typeglob. If the subroutine argument is a reference, I pull in Data::Dumper, set some Dumper parameters to fiddle with the output format, then get its stringified version of the argument:
BEGIN {
use Carp::Heavy;
no warnings 'redefine';
*Carp::format_arg = sub {
package Carp;
my $arg = shift;
if( not defined $arg )
{ $arg = 'undef' }
elsif( ref $arg )
{
use Data::Dumper;
local $Data::Dumper::Indent = 0; # salt to taste
local $Data::Dumper::Terse = 0;
$arg = Dumper( $arg );
$arg =~ s/^\$VAR\d+\s*=\s*//;
$arg =~ s/;\s*$//;
}
else
{
$arg =~ s/'/\'/g;
$arg = str_len_trim($arg, $MaxArgLen);
$arg = "'$arg'" unless
$arg =~ /^-?[\d.]+\z/;
}
$arg =~ s/([[:cntrl:]]|[[:^ascii:]])/sprintf("\\x{%x}",ord($1))/eg;
return $arg;
};
}
I do a little bit of extra work on the Dumper output. It normally gives me something I can use in eval, so it’s a Perl expression with an assignment to a scalar and a trailing semicolon. I use a couple of substitutions to get rid of these extras. I want to get rid of the Data::Dumper artifacts on the ends:
$VAR = ... ; # leave just the ...
Now, when I run the same program I had earlier, I get better output. I can see in elements of the anonymous array that I passed to multiply_and_divide:
--------------------------------------
at confess.pl line 65
main::divide(4, 4) called at confess.pl line 57
main::multiply_and_divide([4,5]) called at confess.pl line 46
main::do_it(4, 5) called at confess.pl line 38
9 20 1
The best part of all of this, of course, is that I only had to add cluck in one subroutine to get all of this information. I’ve used this for very complex situations with lots of arguments and complex data structures, giving me a Perl-style stack dump. It may be tricky to go through, but it’s almost painless to get (and to disable, too).
Next: Safely Changing Modules >>
More Perl Articles
More By O'Reilly Media
|
 This article is excerpted from chapter four of Mastering Perl, written by Brian D Foy (O'Reilly; ISBN: 0596527241). Check it out today at your favorite bookstore. Buy this book now.
|
|
