Beefy Boxes and Bandwidth Generously Provided by pair Networks
XP is just a number
 
PerlMonks  

dprofpp -- now what?

by water (Deacon)
on Mar 29, 2004 at 20:14 UTC ( [id://340732]=perlquestion: print w/replies, xml ) Need Help??

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

We have a large app using Class::DBI that runs too slowly for our needs on large files. To understand where the program is spending its time, we ran a small file through the system with profiling on and then ran dprofpp. Here's what dprofpp says:
Exporter::export_ok_tags has -1 unstacked calls in outer Exporter::Heavy::heavy_export has 26 unstacked calls in outer Class::MethodMaker::_make_get_set has 1 unstacked calls in outer Exporter::Heavy::heavy_export_tags has 1 unstacked calls in outer Exporter::export_tags has -1 unstacked calls in outer Class::MethodMaker::get_set has 1 unstacked calls in outer AutoLoader::AUTOLOAD has -2 unstacked calls in outer Exporter::Heavy::heavy_export_ok_tags has 1 unstacked calls in outer Exporter::export has -26 unstacked calls in outer Total Elapsed Time = 2.623325 Seconds User+System Time = 1.972325 Seconds Exclusive Times %Time ExclSec CumulS #Calls sec/call Csec/c Name 25.3 0.499 1.086 41957 0.0000 0.0000 Class::DBI::Column::name_ +lc 15.2 0.300 1.944 45850 0.0000 0.0000 Class::Accessor::__ANON__ 15.1 0.298 0.298 43063 0.0000 0.0000 Class::Accessor::get 14.1 0.279 1.060 286 0.0010 0.0037 Class::DBI::_require_clas +s 11.3 0.224 1.232 7695 0.0000 0.0002 Class::DBI::__ANON__ 10.9 0.216 1.261 40851 0.0000 0.0000 Class::DBI::Column::__ANO +N__ 9.58 0.189 0.430 11896 0.0000 0.0000 Class::DBI::_attr 9.48 0.187 0.186 22899 0.0000 0.0000 Class::Data::Inheritable: +:__ANON__ 7.00 0.138 0.200 6934 0.0000 0.0000 Class::DBI::primary_colum +n 6.34 0.125 0.380 118 0.0011 0.0032 Class::DBI::_mk_column_ac +cessors 5.53 0.109 0.349 89 0.0012 0.0039 base::import 5.48 0.108 0.416 5572 0.0000 0.0001 Class::DBI::_attribute_se +t 5.43 0.107 0.107 1334 0.0001 0.0001 UNIVERSAL::can 4.77 0.094 0.094 11 0.0085 0.0085 Template::Parser::BEGIN 4.06 0.080 0.203 7 0.0114 0.0290 Template::Config::load
To our understanding, this output says most of the time is spent on CDBI accessors. Not suprising.

We are comitted to using CDBI.... So what do we do next to gain speed? Perhaps we're using CDBI in a not-so-smart way... what else could we be asking dprofpp to know where to start tuning?

water

update

As per perrin's suggestion, used the -r flag:

dprofpp -r > out.txt
and get the following output
Total Elapsed Time = 2.585098 Seconds Real Time = 2.585098 Seconds Exclusive Times %Time ExclSec CumulS #Calls sec/call Csec/c Name 20.3 0.526 1.096 41957 0.0000 0.0000 Class::DBI::Column::name_ +lc 12.8 0.331 0.331 43063 0.0000 0.0000 Class::Accessor::get 11.9 0.309 0.309 635 0.0005 0.0005 DBI::db::ping 10.7 0.279 1.053 286 0.0010 0.0037 Class::DBI::_require_clas +s 10.1 0.261 0.501 557 0.0005 0.0009 DBI::st::execute 9.09 0.235 2.188 45850 0.0000 0.0000 Class::Accessor::__ANON__ 8.63 0.223 1.228 7695 0.0000 0.0002 Class::DBI::__ANON__ 7.97 0.206 0.461 11896 0.0000 0.0000 Class::DBI::_attr 7.85 0.203 0.201 22899 0.0000 0.0000 Class::Data::Inheritable: +:__ANON__ 7.27 0.188 0.188 79 0.0024 0.0024 DBI::db::commit 6.34 0.164 1.220 40851 0.0000 0.0000 Class::DBI::Column::__ANO +N__ 4.18 0.108 0.374 118 0.0009 0.0032 Class::DBI::_mk_column_ac +cessors 4.18 0.108 0.323 6211 0.0000 0.0001 Class::DBI::_attribute_ex +ists 4.18 0.108 0.348 89 0.0012 0.0039 base::import 4.06 0.105 0.184 6934 0.0000 0.0000 Class::DBI::primary_colum +n

Replies are listed 'Best First'.
Re: dprofpp -- now what?
by liz (Monsignor) on Mar 29, 2004 at 21:28 UTC
    These figures are consistent with another rather large Class::DBI project I'm involved with.

    One of the things you could do is to subclass the _mk_column_accessors method, e.g.:

    sub _mk_column_accessors { my $class = shift; my @new = grep {!exists &{$class."::$_"}} @_; # remember new ones $class->SUPER::_mk_column_accessors( @_ ); # accessors + mutators # Redefine accessors to be very lean no warnings 'redefine'; no strict 'refs'; foreach (@new) { my $method = $class."::$_"; my $old = \&$method; *$method = sub { # if not available yet, got fetch with normal accessor return $old->( @_ ) unless exists $_[0]->{$_}; $_[0]->{$_}; }; } } #_mk_column_accessors

    Further optimizations with the accessors could be made if you know 100% sure that when a subclss Class::DBI object is created, all the fields are fetched from the database (bij setting all of the fields to be "Essential"). Something like:

    sub _mk_column_accessors { my $class = shift; eval "sub ${class}::$_ { \$_[0]->{'$_'} }" foreach grep {!exists &{$class."::$_"}} @_; $class->SUPER::_mk_column_accessors( @_ ); } #_mk_column_accessors

    Please note that I've used a string eval here for a reason: benchmarks have shown that accessors created that way are the fastest accessors possible (just as if writing them manually). All other solutions use a closure, which are inherently slower. And since speed is what you're interested in here... ;-)

    Hope this helps.

    Liz

Re: dprofpp -- now what?
by perrin (Chancellor) on Mar 29, 2004 at 20:28 UTC
    That output looks wrong to me. Did you use the -r flag? Otherwise, you get CPU times, which are usually not what you want when profiling programs that do any significant I/O.
      Forgot the -r flag, yes. Posted an update to OP. Thanks.
        Maybe you should explain what your application does. These are certainly not typical numbers for a DBI app. For example, your ping is really high up there. Typically, the DBI execute method would be way up at the top. Are you not resuing your database connections?

        In general, Class::DBI (or any other O/R mapper) is going to have poor performance when used for bulk loading. To get really good performance on that stuff, you need to use your database's bulk loading tools.

Re: dprofpp -- now what?
by Ovid (Cardinal) on Mar 29, 2004 at 20:56 UTC

    You have a variety of strategies available to you. Probably one of the most significant is to look at your actual queries and determine if you can optmize them by pushing all of a query into the owning class instead of allowing Class::DBI to span classes. This is a common and acceptable strategy. However, it does look like the bulk of your time is not spent on database access.

    Right off the bat, we see that name_lc is taking a lot of time. That looks like a ridiculously large amount of time spent lower-casing a darned field name. Looking at the code, we see this:

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

    We have one too many method calls. Eliminating the overload would be great, but if we can't, how about:

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

    The only other place in the code that name_lc was being used was in Class/DBI.pm (and in only one spot). While it's nice to have a single point to lower-case the name, it's not as if we have exotic logic here, so if this solution seemed reasonable, perhaps submitting a patch to the Class::DBI list (assuming that you can demonstrate that this is a common case).

    Still, I'd be concerned about these figures. The database is usually the bottleneck and that doesn't appear to be the case in your code.

    Cheers,
    Ovid

    New address of my CGI Course.

Re: dprofpp -- now what?
by eXile (Priest) on Mar 30, 2004 at 01:41 UTC
    For a specific project I was working on I found it very useful to play around a little with the various flags of 'dprofpp' to get more insight into the figures it produces. For instance dprofpp -r -I will show you the real time spent in each subroutine + all subroutines called from this subroutine. This might provide you with more clues why specific subroutines are called this often, and if that can be avoided in somewhere in your own code. Another clue might be found in the dprofpp -t output. This will show you a call-tree of your subroutines. If you look for your top-10 of 'expensive' routines here you can see what routine called them. In general, the 'dprofpp' manpage is quite interesting literature. ;-)

    Although the database doesn't seem to be a bottleneck from the data you provide, you still can take a deeper look into the database side of this by using dbiprof(I think this comes standard with DBI). In short:
    • To profile (using bash): DBI_PROFILE=DBI::ProfileDumper perl <your program here>
    • To analyze: dbiprof
    This will give you some info on what query is executed how many times, and how mutch time it takes to do that. I used this with succes to see where I could speed things up by using extra indexes on much used columns in my tables.

Log In?
Username:
Password:

What's my password?
Create A New User
Domain Nodelet?
Node Status?
node history
Node Type: perlquestion [id://340732]
Approved by Limbic~Region
help
Chatterbox?
and the web crawler heard nothing...

How do I use this?Last hourOther CB clients
Other Users?
Others taking refuge in the Monastery: (6)
As of 2024-03-28 23:40 GMT
Sections?
Information?
Find Nodes?
Leftovers?
    Voting Booth?

    No recent polls found