ServersImproving mod_perl Driven Site's Performance -- Part III: Code Profiling and Memory...

Improving mod_perl Driven Site’s Performance — Part III: Code Profiling and Memory Measurement Techniques Page 2

ServerWatch content and product recommendations are editorially independent. We may make money when you click on links to our partners. Learn More.




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!)

Get the Free Newsletter!

Subscribe to Daily Tech Insider for top news, trends & analysis

Latest Posts

Related Stories