[Dbix-class] profiling Cat/DBIx app

[jason konrad]

ah yes. the debug was on which did explain the call to Data::Dumper  
during get_columns. With  the debug option off the timing results  
were the same.

On Jul 20, 2007, at 1:50 PM, Frank Speiser wrote:

> 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 at 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
>
>
> _______________________________________________
> 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 at lists.rawmode.org/