Profilers and profiling

jplindstrom on 2004-07-19T08:29:26

So, at least two profilers worked fine. Which is nice, I haven't had great success in that department historically.

Devel::Profile is a debugger-based sub-routine level profiler which gives you total execution time spent in each sub as well as the call count. The overhead of instrumentation is about 10%. Very handy, but it would be useful to be able to disable reporting for certain modules/subs.

For example, in the application I profiled (an Apache-based OLTP application based on Class::DBI on e.g. MySQL, and CGI::Session for session state persistence) more than a third of the execution time was spent in DBI::db::commit, DBI::db::ping and DBI::st::execute, which means they mostly obscure the things that actually can be tuned outside the database, i.e. my application. This is interesting, because since the database is on a different machine, the mod_perl application itself is CPU bound and game for profiling and optimization.

I'm not sure whether Devel::Profile can be used to profile code running under mod_perl since it's supposed to be invoked lik so

perl -d:Profile script.pl

but for me that wasn't a problem. TDD tends to result in a nice design and the call dispatch is completely decoupled from Apache. That's where I drive the performance run.

This is the output of Devel::Profile

%Time Sec. #calls sec/call F name 22.97 1.3708 23 0.059601 DBI::db::commit 5.89 0.3514 317 0.001108 DBI::db::ping 5.49 0.3277 7195 0.000046 :...e/lib/Class/DBI/Column.pm:41 4.75 0.2836 251 0.001130 DBI::st::execute 3.62 0.2159 7263 0.000030 Class::DBI::Column::name_lc 2.94 0.1752 207 0.000846 Class::DBI::_init 2.29 0.1364 8844 0.000015 Class::Accessor::get 1.35 0.0807 20 0.004035 GS::Server::Dispatcher::Foo::Bar::dispatch_baz ...

Interesting runner up: Stringification of the Class::DBI::Column objects. All three lines with #calls around 8000 are a result of the Class::DBI::Column

  use overload
      '""'     => sub { shift->name_lc },
      fallback => 1;

  shift->name_lc    --unrolls-to-->    lc($_[0]->{name})

shift->name_lc

       22 0.000142 0.000000    52:   my $method = $rhRequest->{"method"};
       22 0.000128 0.000000    53:   my $methodDispatch = "dispatch_$method";
       22 0.000139 0.010000    54:   $rhClassKey->{$domain} or die("Invalid
       22 0.000120 0.000000    55:   $rhClassKey->{$domain}->{$method} or
        0 0.000000 0.000000    56:
           ================ SmallProf version 1.15 ================
                   Profile of ../lib/GS/Server/Dispatcher.pm           Page 157
       =================================================================
    count wall tm  cpu time line
       22 0.000117 0.000000    57:   my $class =
       22 0.000234 0.000000    58:   $rhResponse = $class-
        0 0.000000 0.000000    59:
        0 0.000000 0.000000    60:
        0 0.000000 0.000000    61:  #Commit
       22 0.000162 0.000000    62:  GS->dbi_commit("Main");
        0 0.000000 0.000000    63: };
       22 0.000097 0.010000    64: if($@) {
        0 0.000000 0.000000    65:  my $err = $@;
        0 0.000000 0.000000    66:  eval { GS->dbi_rollback("Main"); };
        0 0.000000 0.000000    67:  $rhResponse = { statusMessage => "Internal
        0 0.000000 0.000000    68:  ##todo: log error
        0 0.000000 0.000000    69: }