[Dbix-class] profiling Cat/DBIx app

[Frank Speiser]

jason konrad wrote:
> 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
>
>
>
>
>
>
> _______________________________________________
> List: http://lists.rawmode.org/cgi-bin/mailman/listinfo/dbix-class
> Wiki: http://dbix-class.shadowcatsystems.co.uk/
> IRC: irc.perl.org#dbix-class
> SVN: http://dev.catalyst.perl.org/repos/bast/trunk/DBIx-Class/
> Searchable Archive: 
> http://www.mail-archive.com/dbix-class@lists.rawmode.org/
>
Hi Konrad,

Are you running your server with the -d flag on ?
If you are, turn that off and run your tests again.

-Frank

-- 
Frank Speiser
CTO
TAKKLE, Inc.
212.792.5854 (work)
212.792.5859 (fax)
frank at takkle.com