Recipe 21.15 Benchmarking a mod_perl Application
PerlModule Apache::Timeit PerlFixupHandler Apache::Timeit
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:
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