gihyo.jpサイトのロゴ

Perl Hackers Hub

第17回Webアプリケーションのパフォーマンス改善（2）

2013-02-19

前回の（1）はこちらから。

ボトルネックの特定

システムの現状が把握できたところで、ボトルネックの特定に取りかかります。アプリケーションのレスポンスタイムのうち、どこにどれぐらいの時間がかかっているのかを特定していきましょう。

Time::HiResによる簡単な計測

Time::HiResモジュールを利用することで、特定の個所にどれぐらい時間がかかっているのかを計測できます（リスト5⁠）⁠。

リスト5　Time::HiResの使用例
use Time::HiRes qw/ gettimeofday tv_interval /;
my $t0 = [ gettimeofday ]; # 計測開始
... # 処理時間を計測したい処理
my $elapsed = tv_interval($t0); # 経過時間（秒）

ここは遅いだろう、という部分に目星が付いている場合には、処理時間を確実に計測するために有効です。得られた経過時間はCPU時間ではなく実時間ですので、ネットワークのI/Oなども含めた処理時間が計測されています。

Devel::KYTProfによる計測

特定の個所が遅いという目星が付いてはいないが、DBI経由でのデータベース処理やLWPを利用した外部へのHTTPアクセスのどこかが遅いのではないか、という場合、Devel::KYTProfを使用することで、それらのメソッド呼び出しに要した処理時間をログに出力できます（リスト6、図2⁠）⁠。

リスト6　Devel::KYTProfの使用例
use Devel::KYTProf;
use DBI;
use LWP::UserAgent;
my $dbh = DBI->connect("dbi:mysql:database=test");
my $sth = $dbh->prepare("SELECT * FROM foo WHERE name = ?");
$sth->execute("bar");
my $ua = LWP::UserAgent->new;
my $res = $ua->get("http://example.com/");
図2　リスト6の実行結果
73.651 ms [DBI] connect dbi:mysql:database=test | main:4
13.390 ms [DBI::st] SELECT * FROM foo WHERE name = ? (bind: bar) (0 rows) | main:6
416.913 ms [LWP::UserAgent] GET http://example.com/ | main:8

デフォルトで計測可能なメソッドは次のとおりです。

  • LWP::UserAgentのrequest
  • Furl::HTTPのrequest
  • DBIのconnect、execute
  • Cache::Memcached::Fastのadd、append、set、get、gets、delete、prepend、replace、cas、incr、decr
  • MogileFS::Clientのedit_file、read_file、store_file、store_content、get_paths、get_file_data、delete、rename

このほかにも、任意のクラスのメソッド呼び出しに対して計測を行うように設定できます。たとえばText::Xslate->renderを計測したい場合はリスト7のように記述します（図3⁠）⁠。

リスト7　プロファイリングするメソッドを追加
Devel::KYTProf->add_prof(
    "Text::Xslate",
    "render",
    sub {
        my ($orig, $self, $file, $args) = @_;
        return sprintf '%s %s', "render", $file;
    }
);
my $xs = Text::Xslate->new;
$xs->render("test.xs", { foo => 1 });
図3　リスト7の実行結果
1.972 ms [Text::Xslate] render test.xs | main:12

Devel::KYTProfは特定のメソッド呼び出しのみをTime::HiResを使用した計測処理でwrapするというしくみのため、オーバーヘッドが小さいのが特徴です。特にネットワーク越しの処理に適用する場合は、KYTProf側の処理時間に比べてネットワークアクセスにかかる時間のほうがはるかに大きいため、本番環境で有効にしてもほぼ性能上の影響を与えることなくプロファイルできます。

ただし、デフォルトではすべての対象メソッド呼び出しに対してログが出力されるため、本番環境で有効にすると大量のログが出力されてしまいます。次のようにthresholdを設定することで、一定以上時間のかかった処理のみを抽出するのがよいでしょう。

# 100ms 以上かかった場合のみログを出力
Devel::KYTProf->threshold(100);

Devel::NYTProfによるプロファイリング

どこが問題なのか見当が付かない場合は、すべての処理をプロファイリングする高機能プロファイラDevel::NYTProfを使用しましょう。

perlに-d:NYTProfオプションを付けて実行するとnytprof.outというプロファイルデータが出力され、それをnytprofhtmlコマンドで処理することで、読みやすいHTMLとして結果を閲覧できます（図4、図5⁠）⁠。

図4　Devel::NYTProfの使用例
$ perl -d:NYTProf yourprogram.pl
$ nytprofhtml
図5　Devel::NYTProfが出力するHTMLページ
図5　Devel::NYTProfが出力するHTMLページ

コードのどの部分が何回呼ばれ、どれぐらい時間がかかっているのかをすべて洗い出してくれますし、ソースコードまでHTML上で閲覧できる非常に強力なプロファイラです。

Devel::NYTProfはPerl VMのディスパッチテーブルを書き換えることで計測処理を行います。すべての処理を計測するプロファイラとしては高速で、プロファイリングを行わない場合に比べても、実際のアプリケーションでは数倍程度の処理速度の低下で実行できます。

PSGIアプリケーションサーバへの適用

Devel::NYTProfは比較的高速とはいえ、本番環境ですべてのリクエストに対して有効にしてしまうのは負荷的な問題で無理があります。PSGIアプリケーションをPreforkタイプのアプリケーションサーバ（Starman、Starletなど）で実行している場合には、リスト8のようにPOSIX::AtForkを使用することで、一部の子プロセスのみでプロファイリングを有効にするという手法があります。

リスト8　一部の子プロセスのみでプロファイリングを有効に
# app.psgi
use POSIX::AtFork qw/:all/;
my @opts = qw( addpid=1 start=no sigexit=1
               forkdepth=0 file=/tmp/nytprof.out );
$ENV{"NYTPROF"} = join ":", @opts;
require Devel::NYTProf;
pthread_atfork(
    undef,
    undef,
    sub {
        DB::enable_profile() if $$ % 11 == 0;
    },
);
$app; # PSGI app

リスト8では、POSIX::AtForkによってfork()が発生したタイミングでフックをかけ、forkされた子プロセスが自らのプロセスID（$$）を参照し、ここでは11で割り切れる場合のみプロファイリングを有効に設定しています。アプリケーションサーバで起動する子プロセス数に近い素数でプロセスIDが割り切れる場合のみ有効にすると、そのホストではほぼ常に1プロセスのみがプロファイリングが有効で動作する状態になります。このため、本番環境でも全体の性能に大きな影響を与えずに、プロファイルを取得できます。

リスト8の設定ではプロファイルデータは /tmp/nytprof.out.$$
（$$はプロセスID）というファイルに保存されますが、子プロセスが終了するまではnytprofhtmlで処理できない、中途半端な状態になっています。そのため実際には、子プロセスを一定数のリクエストを処理したら終了するように設定し[1]⁠、終了後のプロファイルデータをnytprofhtmlで処理して閲覧してください。

＜続きの（3）はこちらです。＞

おすすめ記事

記事・ニュース一覧