Item 37: Use debugging and profiling modules.

In addition to the use strict pragmas mentioned above, there are a variety of modules that are especially helpful in debugging and tuning software. Some of these modules are shipped with the basic distribution of Perl. Others you'll have to get from the CPAN.

Get verbose messages with diagnostics

Do you think that Perl's warnings and error messages tend to be a little obscure? If so, try using the diagnostics pragma module. The diagnos tics module produces verbose output for warnings and errors:

use diagnostics; $^W = 1;	Turn on blabbermouth mode. Turn on warnings.
print $not_defined; print 1/$not_defined;	Uninitialized var warning. Division by zero error.
% tryme Use of uninitialized value at tryme line 7 (#1) (W) An undefined value was used as if it were already defined. It was interpreted as a "" or a 0, but maybe it was a mistake. To suppress this warning assign an initial value to your variables. Use of uninitialized value at tryme line 8 (#1) Illegal division by zero at tryme line 8 (#2) (F) You tried to divide a number by 0. Either something was wrong in your logic, or you need to put a conditional in to guard against meaningless input. Uncaught exception from user code: Illegal division by zero at tryme line 8.

There you go! More than you ever wanted to know.

Because diagnostics reports errors in a way that is more useful to developers than to end users, it probably should not be turned on in released code, and particularly not in modules.

Benchmark with Benchmark

Benchmark is an easy-to-use module that allows you to compare the relative speed of pieces of Perl code. As an example, let's use Benchmark to compare the relative speeds of several methods of iterating over an array:

 use Benchmark;  @a = (1..10000);  timethese (100, {    for => q{      my $i;      my $n = @a;      for ($i = 0; $i < $n; $i++) { $a[$i]++ }    },    foreach => q{      foreach $a (@a) { $a++ }    },  } )  %  tryme  Benchmark: timing 100 iterations of for, foreach...         for: 27 secs (27.18 usr  0.00 sys = 27.18 cpu)     foreach: 11 secs (10.54 usr  0.00 sys = 10.54 cpu) 

I'm sold on the foreach loop. How about you?

Note the use of q{ } single-quoted strings in the example above. This style of quoting is especially appropriate for strings containing Perl code.

Dump data with Data::Dumper

Data::Dumper is a versatile module that allows you to dump the contents of one or more variables or data structures as a text stream. This in itself is handy, but the text stream written by Data::Dumper is actually Perl and can be eval -ed to reconstruct the original data.

Data::Dumper readily handles simple constructs:

 use Data::Dumper;  $a = { H => 1, He => 2, Li => 3, Be => 4 };  print Dumper $a;  %  tryme  $VAR1 = {            H => 1,            Li => 3,            He => 2,            Be => 4           }; 

You can associate names with data by calling the Dump method:

 use Data::Dumper;  $a = { H => 1, He => 2, Li => 3, Be => 4 };  $b = { B => 5, C => 6, N => 7, O => 8 };  print Data::Dumper->Dump([$a, $b], [qw(a b)]);  $a = {         H => 1,         Li => 3,         He => 2,         Be => 4       };  $b = {         B => 5,         C => 6,         N => 7,         O => 8       }; 

Data::Dumper can also handle self-referential structures:

 use Data::Dumper;  $c = { name => "C" };  $b = { name => "B", next => $c };  $a = { name => "A", next => $b };  $c->{next} = $a;  print Data::Dumper->Dump([$a, $b, $c], [qw(a b c)]);  %  tryme  $a = {         name => 'A',         next => {                   name => 'B',                   next => {                             name => 'C',                             next => $a                           }                 }       };  $b = $a->{next};  $c = $a->{next}{next}; 

Data::Dumper has many other capabilities and a lengthy man page that describes them. Be sure to check it out.

Dump in detail with Devel ::Peek

If the output from Data::Dumper isn't giving you the kind of detail you want, Devel::Peek should satisfy your curiosity . Devel::Peek dumps the contents of variables or data structures in a low-level format that is most appropriate for developers working on Perl XSUBs (see Item 47) and programs that call Perl.

Here's Devel::Peek operating on a simple scalar:

 use Devel::Peek qw(Dump);  $a = 1234;  Dump $a;  %  tryme  SV = IV(0xa6460)    REFCNT = 1    FLAGS = (IOK,pIOK)    IV = 1234 

Decoded, this gobbledygook says that the value is an SV (scalar value) of the IV (integer value) type, with a reference count of one, and a valid ( IOK ) integer value of 1234 . Suppose that we also use $a as a string:

 use Devel::Peek qw(Dump);  $a = 1234;  "$a";  Dump $a;  %  tryme  SV = PVIV(0xa5108)    REFCNT = 1    FLAGS = (IOK,POK,pIOK,pPOK)    IV = 1234    PV = 0xff528 "1234"    CUR = 4    LEN = 11 

Now, $a has both integer ( IV ) and string ( PV ) values. As a final example, consider a "magic" variable like $! :

 use Devel::Peek qw(Dump);  open F, "bogus-file";  Dump $!;  $a = $!;  Dump $a; 

This gives us:

 SV = PVMG(0xa5ec8)    REFCNT = 1    FLAGS = (GMG,SMG)    IV = 0    NV = 0    PV = 0    MAGIC = 0xa5188  SV = PVMG(0xa5d48)    REFCNT = 1    FLAGS = (NOK,POK,pNOK,pPOK)    IV = 0    NV = 2    PV = 0xb6148 "No such file or directory"    CUR = 25    LEN = 26 

The first variable dumped is $! , which uses a larger "magic" structure. Magic variables can get their values via functionsthe MAGIC field shows the value of the function pointer.

The second variable is $a , which you will notice contains both string ( PV ) and floating-point ( NV ) values. Both were set when $a was assigned the value of $! . Note also that although $a also winds up with the larger PVMG structure, it isn't itself magic, because none of the magic flags are set.

Profile with Devel::DProf

To profile a Perl program as it runs, use Devel::DProf .

Assuming that DProf is installed on your system, you apply it to your program by using the -d option on the command line:

 %  perl -d:DProf my_script  

When the script has completed running, a file named tmon.out , containing raw profiling data, will be left in the current directory. The dprofpp program (installed as part of the DProf distribution) can be used to analyze this data.

Here is some sample profiling output from dprofpp :

 %  dprofpp  Total Elapsed Time =  103.31 Seconds    User+System Time =   70.35 Seconds  Exclusive Times  %Time Seconds     #Calls sec/call Name   55.9   39.39        376   0.1048 News::NNTPClient::fetch   10.2   7.190         62   0.1160 main::decode_uu   3.92   2.760         70   0.0394 main::save_data   3.71   2.610         13   0.2008 MIME::Base64::decode_base64   1.35   0.950        379   0.0025 News::NNTPClient::response   1.01   0.710        378   0.0019 News::NNTPClient::cmd   0.87   0.610         13   0.0469 main::decode_mime_multi   0.44   0.310        378   0.0008 News::NNTPClient::command   0.34   0.240        379   0.0006 News::NNTPClient::returnval   0.27   0.190        259   0.0007 News::NNTPClient::head   0.23   0.160        516   0.0003 main::CODE(0xa6a78)   0.21   0.150        516   0.0003 main::CODE(0x130ac0)   0.21   0.150        516   0.0003 main::CODE(0x1f748c)   0.20   0.140        129   0.0011 main::skip_article   0.20   0.140        379   0.0004 News::NNTPClient::okprint 

The dprofpp program can produce many other types of outputtake a look at the man page for more information.