Measuring mod_perl with Apache::DProf

redhotpenguin has asked for the wisdom of the Perl Monks concerning the following question:

I've been using Apache::DProf to figure out where my code in mod_perl is running slow. There are some socket calls out to other services, so I used '-r' to measure real time as opposed to cpu time. My::Apache::Handler::handler calls several subroutines, but I haven't been able to get dprofpp to tell me how much time it is spending in those subs.

I've gone over the docs, and the writeup at perl.com, but have come up empty. I've started to use dtrace, but I'd really like to be able to figure out what I need to know with dprofpp. I've tried SmallProf but it didn't play nice with my application.

Any suggestions?

Total Elapsed Time = 292.7386 Seconds
         Real Time = 292.7386 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 0.32   0.928 -0.226      3   0.3093 0.0753  My::Handler::handler
 0.01   0.039  0.038      2   0.0194 0.0190  DBD::Pg::dr::connect
 0.01   0.033  0.074      1   0.0325 0.0743  Apache::DBI::childinit
 0.01   0.020  0.020      1   0.0199 0.0199  utf8::AUTOLOAD
 0.00   0.005  0.005     38   0.0001 0.0001  DBI::common::DESTROY
 0.00   0.000  0.000      1   0.0000 0.0000  Socket::__ANON__
 0.00   0.000  0.000      1   0.0000 0.0000  HTTP::Message::__ANON__
 0.00       - -0.000      1        -      -  Compress::Raw::Zlib::infl
+ateStream
                                     0.0001  ::DESTROY
 0.00       - -0.000      1        -      -  My::Model::Foo::BEGIN
 0.00       - -0.000      1        -      -  warnings::import
 0.00       - -0.000      2        -      -  utf8::SWASHNEW
 0.00       - -0.000      1        -      -  APR::Pool::DESTROY
 0.00       - -0.000      1        -      -  vars::import
 0.00       - -0.000      1        -      -  warnings::unimport
 0.00       - -0.000      2        -      -  Template::Context::stash
[download]

p.s. - I'm using Apache::DProf, not Devel::Profiler::Apache because I'm using mod_perl2.

SOLVED - I was doing 'use Apache::DProf' in my startup.pl instead of PerlModule Apache::DProf in my httpd.conf. I added a PerlSection also, here is the total code now:

LoadModule perl_module        modules/mod_perl.so
<Perl>
    require Apache::DB;
    Apache::DB->init;
</Perl>
PerlModule Apache::DProf
[download]

I had this stuff loading conditionally in startup.pl if My::Config->profile was set to true. Sucks to be me, but I'm glad it is working now. Thanks for your help again Monks.

Comment on Measuring mod_perl with Apache::DProf Select or Download Code

Replies are listed 'Best First'.
Re: Measuring mod_perl with Apache::DProf by perrin (Chancellor) on Dec 07, 2007 at 06:24 UTC
Make sure you really call Apache::DB->init before loading any of the code you want to profile. From the article: Note that you must call Apache::DB->init(); prior to whatever code you are attempting to debug. To be safe, I always just put it as the very first thing in my startup.pl.	[reply]
Re^2: Measuring mod_perl with Apache::DProf by redhotpenguin (Deacon) on Dec 07, 2007 at 06:57 UTC
Thanks for the spot, I missed that one. I remember something about needing to call ->init but when I reviewed the docs this seemed to indicate I didn't need to do anything more than load the module. I'll give that a shot. I've also been starting to use dtrace so it should be interesting to compare the results of the two. `The Apache::DProf module also requires apache version 1.3b3 or higher +and PerlChildInitHandler enabled. It is configured simply by adding t +his line to your httpd.conf file: PerlModule Apache::DProf` [download] UPDATE - ->init didn't change anything, so it looks like that wasn't the issue. To convince myself that I was looking at valid results I created a subroutine: `sub sleepy { sleep 10; }` [download] and I call sleepy() from My::Handler::handler. The ExclSec for My::Handler::handler is 10.47 seconds, and My::Handler::sleep is nowhere to be seen in the profile.	[reply] [d/l] [select]
Re^3: Measuring mod_perl with Apache::DProf by tachyon-II (Chaplain) on Dec 07, 2007 at 08:00 UTC
Apache::DProf works under mod_perl, but only show one method called (APR::Pool)	[reply]
Re: Measuring mod_perl with Apache::DProf by tachyon-II (Chaplain) on Dec 07, 2007 at 06:00 UTC
Apache::DProf dumps out a file for every Apache child process. Say you have 5 Apache kids and only send one request you may be looking at the file for one of the kids that did nothing, thus no sub calls. Have you grepped the raw data (rather than using dprofpp) as a sanity check to see if there are any references to your sub calls? Devel::Profiler::Apache might be worth a shot.	[reply]