Devel::Profiler を使ってスクリプトのチューニング実践編
前回の Perl スクリプトで遅い場所を特定する方法 - Devel::Profiler / Devel::NYTProf のエントリで、
と書きましたが、プロファイラ使っていろいろ見つかったパフォーマンス劣化を招くモジュールについて少しだけまとめてみました。もちろん全ての環境で同じ結果になるとは限りませんし、僕が書いてるアプリに依存しまくっている前提ですが、何かの参考になればと。
想定していたパフォーマンスより１０倍遅い状態の時の Devel::Profiler の結果は以下に示すとおり。
Log::Dispatch::Config::config_dispatcher が全体の 50% 程度も占めています。その他 YAML 関連が占めて 35% 程度。この２つがチューニングできれば 100% / 25% ≒ ４倍の高速化が見込めるはずです。
perl -MDevel::Profiler test.cgi
dprofpp
Total Elapsed Time = 0.208314 Seconds
User+System Time = 0.209314 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
52.5 0.110 0.110 6 0.0183 0.0183 Log::Dispatch::Config::config_dispatcher
23.4 0.049 0.049 2 0.0245 0.0245 YAML::init_action_object
4.78 0.010 0.010 17 0.0006 0.0006 CGI::::param
4.78 0.010 0.189 2 0.0050 0.0946 Sledge::Pages::Base::init
4.78 0.010 0.069 2 0.0050 0.0345 YAML::Load
4.78 0.010 0.010 4 0.0025 0.0025 YAML::Base::new
0.00 0.000 0.000 28 0.0000 0.0000 CGI::param
0.00 0.000 0.000 13 0.0000 0.0000 Data::Dumper::Dump
0.00 0.000 0.000 37 0.0000 0.0000 CGI::self_or_default
0.00 0.000 0.000 17 0.0000 0.0000 YAML::Base::field
0.00 0.000 0.000 13 0.0000 0.0000 Data::Dumper::Dumper
0.00 0.000 0.110 2 0.0000 0.0550 Log::Dispatch::Config::create_instance
0.00 0.000 0.000 1 0.0000 0.0000 CGI::::escape
0.00 0.000 0.179 2 0.0000 0.0896 App::Pages::create_config
0.00 0.000 0.010 1 0.0000 0.0101 CGI::::new
Log::Dispatch::Configurator::YAML がそもそも遅い件
Webアプリにしろクライアントソフトにしろ、実際にサービスとして運用することを考えると、何かあったときの原因追及のためにログ出力が非常に重要だと考えています。僕的には Perl でアプリ書くときのログ機能として Log::Dispatch を利用しています。もっともより便利に使うために Log::Dispatch::Config を使って設定ファイルをくわせているわけですが、どうせなら YAML でと思っていた時期があって、そのときから Log::Dispatch::Configurator::YAML を使っていました。
今までは Log::Dispatch::Configurator::YAML を高速性は関係ない管理系ツールにしか使ってこなかったので気にもしなかったのですが、今回のプロファイラ情報を頼りにソースをトレースしてはじめて、
Log::Dispatch::Config::config_dispatcher → Log::Dispatch::Configurator::YAML の部分での性能劣化に気がつきました。でもってはじめて Log::Dispatch::Configurator::YAML のソースを見てみました。
package Log::Dispatch::Configurator::YAML; use base 'Log::Dispatch::Configurator'; use strict; use warnings; our $VERSION = '0.03'; use YAML ();
結論。use YAML () なので遅いです・・・orz
YAML::Syck じゃなかったとです。YAML::Syck 版をこしらえるのも面倒なので、あっさり Log::Dispatch::Configurator::YAML 使うのをやめて解決。Log::Dispatch::Configurator::AppConfig に変更してみて再度プロファイリング。
perl -MDevel::Profiler test.cgi
dprofpp
Total Elapsed Time = 0.154751 Seconds
User+System Time = 0.158751 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
69.2 0.110 0.110 6 0.0183 0.0183 Log::Dispatch::Config::config_dispatcher
12.6 0.020 0.020 2 0.0100 0.0100 AppConfig::file
6.30 0.010 0.010 2 0.0050 0.0050 Sledge::Config::safe_load
6.30 0.010 0.010 17 0.0006 0.0006 CGI::::param
5.67 0.009 0.009 3 0.0030 0.0030 CGI::_compile
0.00 0.000 0.019 1 0.0000 0.0189 CGI::::new
0.00 0.000 0.009 1 0.0000 0.0090 CGI::new
0.00 0.000 0.009 1 0.0000 0.0090 CGI::init
0.00 0.000 -0.000 2 0.0000 - CGI::charset
0.00 0.000 -0.000 37 0.0000 - CGI::self_or_default
0.00 0.000 -0.000 28 0.0000 - CGI::param
0.00 0.000 -0.000 2 0.0000 - CGI::::delete
0.00 0.000 -0.000 12 0.0000 - CGI::Util::rearrange
0.00 0.000 -0.000 4 0.0000 - CGI::all_parameters
0.00 0.000 -0.000 1 0.0000 - CGI::save_request
YAML 関連がいなくなってパフォーマンス向上。
ここで Log::Dispatch::Config::config_dispatcher が全体の 70% を占める結果に。
Log::Dispatch::Configurator::Configurator が遅い件
まずは Log::Dispatch::Config::config_dispatcher のソースコード。性能劣化ヶ所は eval qq{ require $dispclass }; の部分です。
sub config_dispatcher {
my($class, $disp, $var) = @_;
my $dispclass = $var->{class} or _croak "class param missing for $disp";
eval qq{require $dispclass};
_croak $@ if $@ && $@ !~ /locate/;
if (exists $var->{format}) {
$var->{callbacks} = $class->format_to_cb(delete $var->{format}, 2);
}
return $var;
}
Log::Dispatch::Config::config_dispatcher に限らず、必要なときに必要なものを require するテクはプラグイン的に機能を追加できるモジュールで良く用いられるテクです。このテクは非常に便利な反面、結構コストがかかる処理です。あらかじめ使うモジュールがわかっている場合は .cgi 側で最初から use しておくことで eval require の実行コストをほぼ０にすることが可能です。結果高速化することができます。
簡単な例で実験してみます。まずはテストスクリプトのコード。
use Log::Dispatch::Config;
#use Log::Dispatch::FileRotate;
#use Log::Dispatch::Email::MailSender;
Log::Dispatch::Config->configure('log.conf');
my $dispatcher = Log::Dispatch::Config->instance;
$dispatcher->info('this is info message');
$dispatcher->error('this is error message');
ログ設定ファイルはこんな感じ。
dispatchers = tracefile errorfile email tracefile.class = Log::Dispatch::FileRotate tracefile.min_level = info tracefile.filename = ./_trace.log tracefile.mode = append tracefile.TZ = JST tracefile.DatePattern = 'yyyy-MM-dd' tracefile.format = '[%d] [%p] %m at %F line %L%n' errorfile.class = Log::Dispatch::FileRotate errorfile.min_level = error errorfile.filename = ./_err.log errorfile.mode = append errorfile.TZ = JST errorfile.DatePattern = 'yyyy-MM-dd' errorfile.format = '[%d] [%p] %m at %F line %L%n' email.class = Log::Dispatch::Email::MailSender email.min_level = critical email.name = email email.to = [email protected] email.from = [email protected] email.subject = [system error] email.smtp = localhost
次に上記のスクリプトをプロファイルしてみる。
Total Elapsed Time = 0.272 Seconds User+System Time = 0.28 Seconds Exclusive Times %Time ExclSec CumulS #Calls sec/call Csec/c Name 85.0 0.238 0.238 3 0.0793 0.0793 Log::Dispatch::Config::config_dispatcher 10.3 0.029 0.029 1 0.0290 0.0290 Log::Dispatch::Config::_configurator_for 3.57 0.010 0.010 3 0.0033 0.0033 Log::Dispatch::Base::_apply_callbacks 0.00 0.000 0.029 1 0.0000 0.0290 Log::Dispatch::Config::configure 0.00 0.000 0.000 4 0.0000 0.0000 Log::Dispatch::Config::__instance 0.00 0.000 0.238 1 0.0000 0.2380 Log::Dispatch::Config::instance 0.00 0.000 0.238 1 0.0000 0.2380 Log::Dispatch::Config::create_instance 0.00 0.000 0.000 3 0.0000 0.0000 Log::Dispatch::Config::format_to_cb 0.00 0.000 0.000 2 0.0000 0.0000 PerlIO::Layer::find 0.00 0.000 0.000 1 0.0000 0.0000 Time::Local::timelocal 0.00 0.000 0.000 2 0.0000 0.0000 Time::Local::_zoneadjust 0.00 0.000 0.000 4 0.0000 0.0000 Time::Local::_timegm 0.00 0.000 0.000 5 0.0000 0.0000 Time::Local::_daygm 0.00 0.000 0.000 1 0.0000 0.0000 Time::Local::timegm 0.00 0.000 0.000 1 0.0000 0.0000 Log::Dispatch::new
次に use の部分をコメントアウトして最初から必要なモジュールを読み込んだ場合のプロファイル。
Total Elapsed Time = 0.03 Seconds User+System Time = 0.029 Seconds Exclusive Times %Time ExclSec CumulS #Calls sec/call Csec/c Name 68.9 0.020 0.020 1 0.0200 0.0200 Log::Dispatch::Config::_configurator_for 31.0 0.009 0.009 1 0.0090 0.0090 Params::Validate::validate 0.00 0.000 0.020 1 0.0000 0.0200 Log::Dispatch::Config::configure 0.00 0.000 0.000 2 0.0000 0.0000 Log::Dispatch::Config::__instance 0.00 0.000 0.009 1 0.0000 0.0090 Log::Dispatch::Config::instance 0.00 0.000 0.009 1 0.0000 0.0090 Log::Dispatch::Config::create_instance 0.00 0.000 0.000 3 0.0000 0.0000 Log::Dispatch::Config::format_to_cb 0.00 0.000 0.000 3 0.0000 0.0000 Log::Dispatch::Config::config_dispatcher 0.00 0.000 0.000 1 0.0000 0.0000 Log::Dispatch::new 0.00 0.000 0.000 1 0.0000 0.0000 Log::Dispatch::Base::_get_callbacks 0.00 0.000 0.009 1 0.0000 0.0090 Log::Dispatch::Email::MailSender::new 0.00 0.000 0.009 1 0.0000 0.0090 Log::Dispatch::Email::new
というわけで、この時点で Devel::Profiler 上での速度として
↓
Total Elapsed Time = 0.03 Seconds
と高速化できていることがわかります。
さて、話をもどして、パフォーマンス劣化中のスクリプトを上記の実験同様に予め use したバージョンでプロファイラを再度動かしてみる。
perl -MDevel::Profiler test.cgi
dprofpp
Total Elapsed Time = 0.043 Seconds
User+System Time = 0.04 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
25.0 0.010 0.010 3 0.0033 0.0033 CGI::_compile
25.0 0.010 0.010 28 0.0100 0.0100 CGI::escapeHTML
25.0 0.010 0.010 2 0.0050 0.0050 AppConfig::new
25.0 0.010 0.010 2 0.0050 0.0050 Params::Validate::validate
0.00 0.000 0.010 1 0.0000 0.0100 CGI::new
0.00 0.000 0.010 1 0.0000 0.0100 CGI::init
0.00 0.000 0.000 2 0.0000 0.0000 CGI::charset
0.00 0.000 0.000 37 0.0000 0.0000 CGI::self_or_default
0.00 0.000 0.000 28 0.0000 0.0000 CGI::param
0.00 0.000 0.000 2 0.0000 0.0000 CGI::::delete
0.00 0.000 0.000 12 0.0000 0.0000 CGI::Util::rearrange
0.00 0.000 0.000 4 0.0000 0.0000 CGI::all_parameters
0.00 0.000 0.000 1 0.0000 0.0000 CGI::save_request
この時点で Devel::Profiler 上での速度として、約５倍の高速化が図れています。
↓
Total Elapsed Time = 0.043 Seconds
実は Apache bench での計測での実速度はこの時点で７倍高速化されています。
チューニング前
Concurrency Level: 10
Time taken for tests: 9.229 seconds
Complete requests: 100
Failed requests: 0
Broken pipe errors: 0
Total transferred: 7340736 bytes
HTML transferred: 7297896 bytes
Requests per second: 10.84 [#/sec] (mean)
Time per request: 922.90 [ms] (mean)
Time per request: 92.29 [ms] (mean, across all concurrent requests)
Transfer rate: 795.40 [Kbytes/sec] received
チューニング後
Concurrency Level: 10
Time taken for tests: 1.329 seconds
Complete requests: 100
Failed requests: 0
Broken pipe errors: 0
Total transferred: 7275200 bytes
HTML transferred: 7233200 bytes
Requests per second: 75.24 [#/sec] (mean)
Time per request: 132.90 [ms] (mean)
Time per request: 13.29 [ms] (mean, across all concurrent requests)
Transfer rate: 5474.19 [Kbytes/sec] received
さて、ここまでプロファイルを Devel::Profiler を使ってきてチューニングしてきたのですが、使うプロファイラによって結構結果が変わります。この前ご紹介した Devel::NYTProf だとこんな感じ。
536 534 166 859.03345 859.03345 Exporter::import
168 168 123 644.27509 644.27509 vars::import
58 4 3 214.75836 214.75836 CGI::self_or_default
151 151 29 214.75836 214.75836 constant::import
7 7 1 0.04000 0.04000 Template::Config::load
437 1 1 0.02000 0.04000 DateTime::Locale::_register
448 5 6 0.02000 0.02000 Params::Validate::_validate (xsub)
2 1 2 0.01000 0.01000 DBI::bootstrap (xsub)
2 1 2 0.01000 0.01000 HTML::Parser::parse (xsub)
1 1 1 0.01000 214.80836 Sledge::Template::TTX::output
1 1 1 0.01000 0.02000 Sledge::Pages::Compat::import
3 1 1 0.01000 0.01000 CGI::_compile
1 1 1 0.01000 0.01000 DateTime::Locale::Catalog::Aliases
8 1 1 0.01000 0.01000 Mail::Field::_require_dir
2 2 1 0.01000 0.01000 Sledge::Config::safe_load
まぁなんにしろ、次のチューニング対象は CGI.pm であることは間違いなさそうです。mod_perl 上で動くアプリなので Apache::Request / Apache::Cookie を使って書き直せばさらにチューニングが進みそうです。
こうやってチューニングするたびに高速化が実感できていくのは、やっていて凄く楽しいです。
コメントやシェアをお願いします！