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)
[EMAIL PROTECTED]
_______________________________________________
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/
