Run it with the profiler enabled, and then create the profiling
stastics with the help of dprofpp:
% perl -d:DProf diagnostics.pl % dprofpp Total Elapsed Time = 0.342236 Seconds User+System Time = 0.335420 Seconds Exclusive Times %Time ExclSec CumulS #Calls sec/call Csec/c Name 92.1 0.309 0.358 1 0.3089 0.3578 main::BEGIN 14.9 0.050 0.039 3161 0.0000 0.0000 diagnostics::unescape 2.98 0.010 0.010 2 0.0050 0.0050 diagnostics::BEGIN 0.00 0.000 -0.000 2 0.0000 - Exporter::import 0.00 0.000 -0.000 2 0.0000 - Exporter::export
0.00 0.000 -0.000 1 0.0000 - Config::BEGIN 0.00 0.000 -0.000 1 0.0000 - Config::TIEHASH 0.00 0.000 -0.000 2 0.0000 - Config::FETCH 0.00 0.000 -0.000 1 0.0000 - diagnostics::import 0.00 0.000 -0.000 1 0.0000 - main::test_code 0.00 0.000 -0.000 2 0.0000 - diagnostics::warn_trap 0.00 0.000 -0.000 2 0.0000 - diagnostics::splainthis 0.00 0.000 -0.000 2 0.0000 - diagnostics::transmo 0.00 0.000 -0.000 2 0.0000 - diagnostics::shorten 0.00 0.000 -0.000 2 0.0000 - diagnostics::autodescribe
It’s not easy to see what is responsible for this enormous overhead,
even if main::BEGIN
seems to be running most of the time. To get
the full picture we must see the OPs tree, which shows us who calls
whom, so we run:
% dprofpp -T
and the output is:
main::BEGIN diagnostics::BEGIN Exporter::import Exporter::export diagnostics::BEGIN Config::BEGIN Config::TIEHASH Exporter::import Exporter::export Config::FETCH Config::FETCH diagnostics::unescape ..................... 3159 times [diagnostics::unescape] snipped ..................... diagnostics::unescape diagnostics::import diagnostics::warn_trap diagnostics::splainthis diagnostics::transmo diagnostics::shorten diagnostics::autodescribe main::test_code diagnostics::warn_trap diagnostics::splainthis diagnostics::transmo diagnostics::shorten diagnostics::autodescribe diagnostics::warn_trap diagnostics::splainthis diagnostics::transmo diagnostics::shorten diagnostics::autodescribe
So we see that two executions of diagnostics::BEGIN
and 3161 of
diagnostics::unescape
are responsible for most of the running
overhead.
If we comment out the diagnostics
module, we get:
Total Elapsed Time = 0.079974 Seconds User+System Time = 0.059974 Seconds Exclusive Times %Time ExclSec CumulS #Calls sec/call Csec/c Name 0.00 0.000 -0.000 1 0.0000 - main::test_code
It is possible to profile code running under mod_perl with the
Devel::DProf
module, available on CPAN. However, you must have
apache version 1.3b3 or higher and the PerlChildExitHandler
enabled
during the httpd build process. When the server is started,
Devel::DProf
installs an END
block to write the tmon.out
file. This block will be called at server shutdown. Here is how to
start and stop a server with the profiler enabled:
% setenv PERL5OPT -d:DProf % httpd -X -d 'pwd' & ... make some requests to the server here ... % kill 'cat logs/httpd.pid' % unsetenv PERL5OPT % dprofpp
The Devel::DProf
package is a Perl code profiler. It will collect
information on the execution time of a Perl script and of the subs in
that script (remember that print()
and map()
are just like any
other subroutines you write, but they come bundled with Perl!)