http://d.hatena.ne.jp/nekokak/20060127/1138335790
Class::DBI v3.0.14で上記URLにあったシンプルなRetrieveをDevel::DProfでプロファイリングしてみた。
/usr/local/bin/perl
-MNikkiSite::Data::Loader -d:DProf -e '
for(1..10000) {
my $it = NikkiSite::Data::Users->search({ uid => "daisuke" });
while (my $rec = $it->next) { print $rec->uid, "\n"}
}'
最初、1..100くらいでやってみたのだけど、これがロードタイムのほうが遥かに大きくて、base::importとかBEGINブロックとか、そういうのばっかりがカウントされるので、10000回まで大きくしてみた。
で、これをdprofppでみてみる：
daisuke$ dprofpp -f 'YAML|Params::Validate|DateTime|NikkiSite' -O 20
<snip>
Total Elapsed Time = 18.86988 Seconds
User+System Time = 7.494887 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
8.47 0.635 0.635 162584 0.0000 0.0000 Class::Accessor::Fast::__ANON__
5.42 0.406 0.996 10000 0.0000 0.0001 Class::DBI::SQL::Transformer::_do_
transformation
4.95 0.371 2.363 10000 0.0000 0.0002 Class::DBI::sth_to_objects
4.92 0.369 0.376 100802 0.0000 0.0000 Class::Data::Inheritable::__ANON__
4.58 0.343 0.839 10185 0.0000 0.0001 DBIx::ContextualFetch::st::_untain
t_execute
4.54 0.340 1.699 10000 0.0000 0.0002 Class::DBI::transform_sql
4.31 0.323 0.323 10186 0.0000 0.0000 DBI::st::execute
4.06 0.304 0.789 130776 0.0000 0.0000 Class::DBI::Column::name_lc
4.00 0.300 0.300 10106 0.0000 0.0000 DBD::Pg::db::_ping
3.63 0.272 1.064 130096 0.0000 0.0000 Class::DBI::Column::__ANON__
3.31 0.248 0.248 71077 0.0000 0.0000 DBI::common::FETCH
3.23 0.242 0.241 20010 0.0000 0.0000 Class::DBI::_require_class
3.03 0.227 0.328 20000 0.0000 0.0000 DBIx::ContextualFetch::st::fetch
2.98 0.223 1.382 20000 0.0000 0.0001 Class::DBI::Iterator::next
2.92 0.219 0.785 10000 0.0000 0.0001 Class::DBI::Search::Basic::_search
_for
2.82 0.211 1.039 20000 0.0000 0.0001 Class::DBI::Search::Basic::_qual_b
ind
2.39 0.179 0.179 40142 0.0000 0.0000 Class::DBI::ColumnGrouper::group_c
ols
2.19 0.164 0.277 10000 0.0000 0.0000 Class::DBI::_fresh_init
2.13 0.160 0.254 10000 0.0000 0.0000 DBD::_::db::prepare_cached
2.13 0.160 0.340 10000 0.0000 0.0000 Class::DBI::_my_iterator
ふーん、結構色々やってるなぁ。name_lc()とかはキャッシュするだけでカットできる（Class::DBI::Column::__ANON__も同じname_lcを使ってるからその分だけはやくできる）。あとのはもう、コールスタックを減らすくらいしか最適化の場所がないような・・・
というわけで、時間もないので一番簡単にわかるところで２行ハックして再度プロファイリング。
# Class/DBI/Column.pm use strict; use base 'Class::Accessor::Fast'; use Carp;__PACKAGE__->mk_accessors(
qw/name name_lc accessor mutator placeholder is_constrained/
);<snip>
sub new {
my $class = shift;
my $name = shift or croak "Column needs a name";
my $opt = shift || {};
return $class->SUPER::new(
{
name => $name
name_lc => lc $name,
accessor => $name,
mutator => $name,
_groups => {},
placeholder => '?',
%$opt,
}
);
}
さー、これで１００００回走らせてプロファイリング
daisuke$ dprofpp -f 'YAML|Params::Validate|DateTime|NikkiSite' -O 20
Total Elapsed Time = 16.16692 Seconds
User+System Time = 7.034115 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
8.15 0.573 0.573 162584 0.0000 0.0000 Class::Accessor::Fast::__ANON__
6.38 0.449 2.011 10000 0.0000 0.0002 Class::DBI::sth_to_objects
5.60 0.394 0.394 10186 0.0000 0.0000 DBI::st::execute
5.13 0.361 0.368 100802 0.0000 0.0000 Class::Data::Inheritable::__ANON__
4.49 0.316 0.316 10106 0.0000 0.0000 DBD::Pg::db::_ping
3.67 0.258 0.887 10000 0.0000 0.0001 Class::DBI::SQL::Transformer::_do_
transformation
3.67 0.258 0.383 20006 0.0000 0.0000 Class::DBI::ColumnGrouper::find_co
lumn
3.54 0.249 0.777 10185 0.0000 0.0001 DBIx::ContextualFetch::st::_untain
t_execute
3.43 0.241 0.651 130096 0.0000 0.0000 Class::DBI::Column::__ANON__
3.11 0.219 0.226 20010 0.0000 0.0000 Class::DBI::_require_class
3.06 0.215 1.535 10000 0.0000 0.0002 Class::DBI::transform_sql
2.94 0.207 0.566 10000 0.0000 0.0001 Class::DBI::_live_object_key
2.83 0.199 1.421 20000 0.0000 0.0001 Class::DBI::Iterator::next
2.66 0.187 0.953 20000 0.0000 0.0000 Class::DBI::Search::Basic::_qual_b
ind
2.66 0.187 0.316 10000 0.0000 0.0000 Class::DBI::_fresh_init
2.66 0.187 0.308 30064 0.0000 0.0000 Class::DBI::ColumnGrouper::primary
2.45 0.172 0.738 10000 0.0000 0.0001 Class::DBI::Search::Basic::_search
_for
2.32 0.163 0.163 40142 0.0000 0.0000 Class::DBI::ColumnGrouper::group_c
ols
2.00 0.141 0.230 10000 0.0000 0.0000 Class::DBI::Search::Basic::new
2.00 0.141 0.285 30000 0.0000 0.0000 Class::DBI::_attrs
ほい、name_lcは消えた。２行で10%違ったらたいしたもんだと思います。ふーん、なんかまだ色々できそうな予感。怪しいものとしてはColumnGrouperかな。
