We've expanded our Perl news coverage and improved our search! Search for all things Perl across O'Reilly!

Debugging and Profiling mod_perl Applications
by Frank Wiles | Pages: 1, 2, 3

As an example, here's a small application to profile. This code, while not all that useful, will help illustrate the major differences between these two profiling modules:

package PerlTest;

sub handler {
    my $r = shift;
  
    $r->content_type( 'text/plain' );
  
    handle_request($r);

    return( Apache2::Const::OK );
}

sub handle_request {
    my $r = shift;

    $r->print( "Handling request....\n" );

    cleanup_request($r);

}

sub cleanup_request {
    my $r = shift;

    $r->print( "Cleaning up request....\n" );

    sleep(5);     # Take some time in this section
}

1;

When you profile a module with Apache::Dprof, it will create a directory named dprof/ in your server's logs/ directory. Under this directory will be subdirectories named after the PID of each Apache child your server has. This allows you to profile code over a long period of time on a production system to see where your real bottlenecks are. Often, faking a typical user session does not truly represent how your users interact with your application and having the real data is beneficial.

After your server has run for a while, you need to stop it and revert your configuration, removing the PerlModule Apache::DProf you just inserted. This is due to the fact that Apache::DProf does not write its data to disk until the server child ends.

Viewing the profiling data is exactly the same as with Devel::DProf. Choose a particular Apache child directory in $SERVER_ROOT/logs/dprof/ and run dprofpp on the corresponding tmon.out file.

After beating on the code sample above for awhile with ab, here are the results Apache::DProf gave me:

Total Elapsed Time = 1082.402 Seconds
  User+System Time =        0 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 0.00   0.004  0.001    687   0.0000 0.0000  RevSys::PerlTest::cleanup_request
 0.00       - -0.000      1        -      -  warnings::import
 0.00       - -0.000      1        -      -  APR::Pool::DESTROY
 0.00       - -0.000      1        -      -  strict::import
 0.00       - -0.000      1        -      -  Apache2::XSLoader::load
 0.00       - -0.000      3        -      -  Apache2::RequestIO::BEGIN
 0.00       - -0.000      2        -      -  RevSys::PerlTest::BEGIN
 0.00       - -0.003    687        -      -  Apache2::RequestRec::content_type
 0.00       - -0.006   1374        -      -  Apache2::RequestRec::print
 0.00       - -0.012    687        -      -  RevSys::PerlTest::handle_request
 0.00       - -0.024    687        -      -  RevSys::PerlTest::handler

As expected, cleanup_request() shows the most time used per call. The report also shows stats for the other function calls you would expect as well as the ones that happen behind the scenes.

Code Profiling with Apache::SmallProf

While Apache::DProf will show you which subroutines use the most system resources, sometimes that is not enough information. Apache::SmallProf gives you fine-grained details in a line-by-line profile of your code.

Setup is similar to both of two previous modules. Add into a <Perl> section or your startup.pl file the code:

use APR::Pool ();
use Apache::DB ();
Apache::DB->init();

You also need to add PerlFixupHandler Apache::SmallProf into the <Directory> or <Location> block that refers to your mod_perl code.

Like Apache::DProf, Apache::SmallProf writes all of the profiling data into $SERVER_ROOT/logs/smallprof/. One interesting difference between Apache::DProf and Apache::SmallProf is that the latter writes a profile for each module in use. This is helpful because you already know which subroutines are slow and which packages they are in, from your first round of profiling with Apache::DProf. By focusing on those modules you can find your troubled code much faster.

Viewing Apache::SmallProf data is, however, a little different from Apache::DProf. A module profile looks like this:

<number>

<wall time>

<cpu time>

<line number>

<source line>

<number> is the number of times this particular line was executed, <wall time> is the actual time passed, and <cpu time> is the amount of time the CPU spent working on that line. The remaining two pieces of data are the line number in the file and the actual source on that line.

You can just open up the profiles generated by Apache::SmallProf and look at the results. However, this doesn't get to the heart of the matter very quickly. Sorting the profile by the amount of time spent on each line gets you where you want to go:

$ sort -nrk 2 logs/smallprof/MyHandler.pm | more

This command sorts the profile for MyHandler.pm by the wall time of each line. If you use this same sort on the output from Apache::SmallProf on the example code, you will see something similar to this:

# sort -nrk 2 PerlTest.pm.prof | more
    1 5.000785 0.000000         29:    sleep( 5 );
    1 0.008177 0.000000         13:    return( Apache2::Const::OK );
    1 0.007431 0.010000         21:    cleanup_request( $r );
    3 0.001343 0.000000          4:use Apache2::RequestIO;
    1 0.000176 0.000000         33:1;
    3 0.000164 0.000000          3:use Apache2::RequestRec;
    1 0.000093 0.000000         19:    $r->print( "Handling request......\n" );
    1 0.000067 0.000000         11:    handle_request( $r );
    1 0.000058 0.000000          9:    $r->content_type( 'text/plain' );
    1 0.000058 0.000000         28:    $r->print( "Cleaning up request......\n" );

As you can see, Apache::SmallProf has zeroed right in on our sleep() call as the source of our performance problems.

Conclusion

Hopefully, this article has given you enough of an introduction to these modules that you can begin using them in your development efforts. The next time you face a seemingly unsolvable bug or performance issue, you have a few more weapons in your arsenal.

If you have trouble getting any of these three modules to work, please don't hesitate to contact me directly. If you need mod_perl help in general, I strongly suggest you join the mod_perl mailing list. You can often get an answer to your mod_perl question in a few hours, if not minutes.