21.15. Benchmarking a mod_perl Application21.15.1. ProblemYou have an idea to speed up your application, but you're not sure whether your change will help. 21.15.2. SolutionUse 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. DiscussionThe 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 AlsoRecipe 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 Copyright © 2003 O'Reilly & Associates. All rights reserved. |
|