Devel::Profiler を使ってスクリプトのチューニング実践編

前回の Perl スクリプトで遅い場所を特定する方法 - Devel::Profiler / Devel::NYTProf のエントリで、

Sledge フレームワーク自身が重くないことは今までの経験でわかってるのですが、どうにもソースを見直しているだけでは原因が特定できない・・・そんな活躍するのがプロファイラです。プロファイラの御陰で遅いヶ所を特定することができ、無事に想定するパフォーマンスを得ることができました。この内容に関してはまた別エントリにて。

と書きましたが、プロファイラ使っていろいろ見つかったパフォーマンス劣化を招くモジュールについて少しだけまとめてみました。もちろん全ての環境で同じ結果になるとは限りませんし、僕が書いてるアプリに依存しまくっている前提ですが、何かの参考になればと。

- スポンサーリンク -

想定していたパフォーマンスより10倍遅い状態の時の Devel::Profiler の結果は以下に示すとおり。
Log::Dispatch::Config::config_dispatcher が全体の 50% 程度も占めています。その他 YAML 関連が占めて 35% 程度。この2つがチューニングできれば 100% / 25% ≒ 4倍の高速化が見込めるはずです。

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 の実行コストをほぼ0にすることが可能です。結果高速化することができます。

簡単な例で実験してみます。まずはテストスクリプトのコード。

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        = drk@drk7.jp
email.from      = drk@drk7.jp
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.272 Seconds
 ↓
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 上での速度として、約5倍の高速化が図れています。

Total Elapsed Time = 0.208314 Seconds
 ↓
Total Elapsed Time = 0.043 Seconds

実は Apache bench での計測での実速度はこの時点で7倍高速化されています。

./ab -n 100 -c 10 'http://localhost/cgi-bin/test.cgi'

チューニング前

    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 を使って書き直せばさらにチューニングが進みそうです。

こうやってチューニングするたびに高速化が実感できていくのは、やっていて凄く楽しいです。

- スポンサーリンク -