Recipe 21.15 Benchmarking a mod_perl Application

21.15.1 Problem

You have an idea to speed up your application, but you're not sure whether your change will help.

21.15.2 Solution

Use Apache::Timeit to time how long your content handler takes to run:

PerlModule Apache::Timeit
PerlFixupHandler Apache::Timeit

For more detailed analysis, use the Apache::DProf module available from CPAN:

PerlModule Apache::DProf

21.15.3 Discussion

The Apache::Timeit module is available at http://perl.apache.org/dist/contrib/Timeit.pm.

This module records in the error log the amount of time that elapsed while the content handler ran. By scanning the logs and averaging these numbers, you can see which pages take longer to generate, and you can then start to figure out why.

To drill down into your code and figure out which parts of the content handler are taking the most time, use the Apache::DProf module. This module connects the standard (as of v5.8) Devel::DProf module to Apache and mod_perl.

The profiler records time spent in every subroutine the Perl module executes. The record of times is written to a file named dprof/$$/tmon.out ($$ is the process ID of the Apache child process), located under the ServerRoot directory. This file corresponds to every Perl subroutine encountered during the lifetime of the Apache child process. To profile just a single request, set the MaxRequestsPerChild directive in the httpd.conf file:

MaxRequestsPerChild 1

You must create and chmod this directory yourself:

cd $APACHE_SERVER_ROOT
mkdir logs/dprof
chmod 777 logs/dprof

To analyze the output, use the dprofpp program:

dprofpp -r dprof/13169/tmon.out
Total Elapsed Time = 89.93962 Seconds
         Real Time = 89.93962 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 0.01   0.010  0.010      1   0.0100 0.0100  Apache::Reload::handler
 0.00   0.000 -0.000      1   0.0000      -  Apache::DProf::handler
 0.00   0.000 -0.000      1   0.0000      -  MP002::trans
 0.00   0.000 -0.000      1   0.0000      -  MP002::fixup
 0.00   0.000 -0.000      1   0.0000      -  MP002::content

The -r option makes dprofpp display elapsed time instead of the default CPU time. The difference is important for mod_perl applications, where I/O and other non-CPU tasks are often significant causes of user-perceived delay.

There are a lot of options to dprofpp that refine and manipulate timing data. For example, -R gives separate timing data for each anonymous subroutine in a package, rather than lumping them together; -l sorts by the number of times the subroutine was called, rather than how long it took. See the dprofpp manpage for a complete list.

21.15.4 See Also

Recipe 9.12 in mod_perl Developer's Cookbook; documentation for the CPAN module Apache::DProf; documentation for the standard module Devel::DProf; the dprofpp(1) manpage; the section "The Perl Profiler" in Chapter 20 of Programming Perl