[Dbix-class] profiling Cat/DBIx app

[jason konrad]

I was doing some profiling of our Cat/DBIx application which is  
running in a mod_perl environment. I'm currently using DBIx::Class  
0.07005. I was surprised to see DBIx::Class::Row::get_columns at the  
top of the list for taking the most time. The server was under a very  
high load during these tests. I'm thinking that the fact that the  
server was under a very high load it was causing the response from  
mysql running on the same machine to be a bit slow. WHich would make  
sense but then I noticed from the calling tree that for every call to  
get_columns a Data::Dumper object was being created and that seems a  
bit strange.

  Here is some output from dprofpp

# dprofpp -r /tmp/dprof/27422/tmon.out
Storable::_freeze has 1 unstacked calls in outer
Catalyst::__ANON__ has -95 unstacked calls in outer
AutoLoader::AUTOLOAD has -1 unstacked calls in outer
DBIx::Class::Row::get_column has 94 unstacked calls in outer
bytes::length has 1 unstacked calls in outer
Total Elapsed Time = 108.3457 Seconds
          Real Time = 108.3457 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
34.3   37.21 37.289    190   0.1959 0.1963   
DBIx::Class::Row::get_columns
9.35   10.13  2.759     95   0.1066 0.0290  Catalyst::__ANON__
7.58   8.212 11.061    665   0.0123 0.0166  Tree::Simple::_insertChildAt
6.16   6.670  0.149    665   0.0100 0.0002  DBIx::Class::Row::get_column
2.39   2.592  2.806    570   0.0045 0.0049   
kRad::Util::Helpers::placeholder

# dprofpp /tmp/dprof/27422/tmon.out
Storable::_freeze has 1 unstacked calls in outer
Catalyst::__ANON__ has -95 unstacked calls in outer
AutoLoader::AUTOLOAD has -1 unstacked calls in outer
DBIx::Class::Row::get_column has 94 unstacked calls in outer
bytes::length has 1 unstacked calls in outer
Total Elapsed Time = 108.5012 Seconds
   User+System Time = 6.871273 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
46.5   3.195  4.574    665   0.0048 0.0069  Tree::Simple::_insertChildAt
18.2   1.256  1.334    570   0.0022 0.0023   
kRad::Util::Helpers::placeholder
17.0   1.173  0.029     95   0.0123 0.0003  Catalyst::__ANON__
10.5   0.726  0.020    665   0.0011 0.0000  DBIx::Class::Row::get_column
2.43   0.167  0.205    190   0.0009 0.0011   
DBIx::Class::Row::get_columns


Then a snippet from the calling tree.

DBIx::Class::InflateColumn::new
DBIx::Class::Row::new
DBIx::Class::Row::insert
DBIx::Class::Row::get_columns
    Data::Dumper::new
    Data::Dumper::DESTROY
    DBD::_::db::prepare_cached
DBIx::Class::Row::get_column
    DBI::common::FETCH
    AutoLoader::__ANON__
    Storable::_freeze
       Storable::net_mstore
    Storable::_freeze
       Storable::net_mstore
    DBIx::Class::ResultSet::__ANON__
    DBD::_::db::prepare_cached
DBIx::Class::InflateColumn::new
DBIx::Class::Row::new
DBIx::Class::Row::insert
DBIx::Class::Row::get_columns
    Data::Dumper::new
    Data::Dumper::DESTROY
    DBD::_::db::prepare_cached
DBIx::Class::Row::get_column
DBIx::Class::Row::get_column
DBIx::Class::Row::get_column
DBIx::Class::Row::get_column
    Storable::mretrieve
DBIx::Class::Row::get_column
DBIx::Class::Relationship::CascadeActions::update
DBIx::Class::InflateColumn::update
DBIx::Class::Row::update
DBIx::Class::Row::get_column
    DBD::_::db::prepare_cached
    Tie::IxHash::FIRSTKEY
    Tie::IxHash::FIRSTKEY



Thanks,
   konrad