The Perl Profiler (Perl in a Nutshell, 2nd Edition)

6.5. The Perl Profiler

You can supply an alternative debugger for Perl to run by invoking your script with the -d:module switch. One of the most popular alternative debuggers for Perl is DProf, the Perl profiler. As of this writing, DProf is not included with the standard Perl distribution, but it is expected to be included soon.

Meanwhile, you can fetch the Devel::DProf module from CPAN. Once it has been properly installed on your system, you can use it to profile the Perl program in testpgm by typing:

perl -d:DProf testpgm

As your script runs, DProf gathers profile information. When the script terminates, the profiler dumps the gathered information to a file called tmon.out. A tool such as dprofpp, which is supplied with the Devel::DProf package, can be run to interpret the profile. If you run dprofpp against the tmon.out file created by DProf in the example above, you'll see something like the following:

% dprofpp tmon.out
Total Elapsed Time =    0.15 Seconds
  User+System Time =     0.1 Seconds
Exclusive Times
%Time Seconds     # Calls sec/call Name
 30.0   0.030          1   0.0300 Text::Wrap::CODE(0x175f08)
 20.0   0.020          1   0.0200 main::CODE(0xc7880)
 20.0   0.020          1   0.0200 main::CODE(0xfe480)
 10.0   0.010          1   0.0100 Text::Wrap::CODE(0x17151c)
 10.0   0.010         10   0.0010 Text::Tabs::expand
 0.00   0.000          1   0.0000 lib::CODE(0xfe5b8)
 0.00   0.000          3   0.0000 Exporter::export
 0.00   0.000          1   0.0000 Config::FETCH
 0.00   0.000          1   0.0000 lib::import
 0.00   0.000          1   0.0000 Text::Wrap::CODE(0x171438)
 0.00   0.000          3   0.0000 vars::import
 0.00   0.000          3   0.0000 Exporter::import
 0.00   0.000          2   0.0000 strict::import
 0.00   0.000          1   0.0000 Text::Wrap::CODE(0x171684)
 0.00   0.000          1   0.0000 lib::CODE(0xfe4d4)

The output shows the 15 subroutines that use the most time; you can then focus your efforts on those subroutines where tuning the code will have the greatest effect. This output is an example of running the dprofpp command with the default option set. The following are the options that are available:

-a: Sorts output alphabetically by subroutine name.
-E: Default. Displays all subroutine times exclusive of child subroutine times.
-F: Forces generation of fake exit timestamps if dprofpp reports that the profile is garbled. Useful only if dprofpp determines that the profile is garbled due to missing exit timestamps.
-I: Displays all subroutine times inclusive of child subroutine times.
-l: Sorts by number of calls to the subroutines.
-O cnt: Shows only cnt subroutines. The default is 15.
-p script: Profiles the given script and interprets its profile data, combining the usual two steps into one.
-Q: Used with -p, profiles the script and quits without interpreting the data.
-q: Does not display column headers.
-r: Displays elapsed real times.
-s: Displays system times only.
-T: Displays subroutine calls, but not subroutine statistics .
-t: Displays subroutine call tree, but not subroutine statistics. A subroutine called multiple times is shown only once, with a repeat count.
-U: Displays unsorted output.
-u: Displays user times only.
-V: Prints the dprofpp version number.
-v: Sorts by average time spent in subroutines during each call.
-z: Default. Sorts by amount of user and system time used, so that the first few lines should show which subroutines are using the most time.