Advanced PHP debugger

php

犯人はNP_BlackListで、PHPスクリプトの性能が悪い現象を解析するためにPHP用のプロファイラを使ったので忘れないうちにメモを書いておきます。

† APD (Advanced PHP debugger)

今回はプロファイラとしてしか使っていませんが、APDのドキュメントやPECLのサマリにはA full-featured engine-level profiler/debuggerと書いてあるので、デバッガとしての機能もいろいろとあるようです。

† セットアップ

ダウンロードはPECLのAPDから可能です。PHP 4.4.0で最新版のAPD 1.0.1を使おうとしたところ、PHPが古いと怒られてしまったので、今回は0.9.2をインストールしました。あとで分かったことですが、1.0.1と0.9.2はリリース日が同じなのでおそらく1.0.x系がPHP5用で、0.9.x系がPHP4用のような気がします。

ビルド・インストール手順はこんな感じ。

# tar zxvf apd-0.9.2.tgz
# cd apd-0.9.2
# phpize
# ./configure
# make install

プログラムのトレース情報を人が読めるようにするため「pprofp」というツールがディレクトリに入っているので、必要に応じて/usr/local/binとかにコピーしておいた方がいいでしょう。僕はこのツールが見つけられなくて後ではまったので。

† PHPへの組み込み

APDはzendモジュールなので、php.iniの書き換えてPHP起動時にモジュールが読み込まれるようにする必要があります。ということでphp.iniに以下の記述を追加。

php.ini(追加分のみ)

zend_extension = /usr/local/lib/php/extensions/no-debug-non-zts-20020429/apd.so
apd.dumpdir = /tmp
apd.statement_tracing = 0

apd.soがある場所は環境によって違うので、APDインストール時にどこにapd.soがインストールされたのかは確認しておく必要があります。また、"apd.dumpdir"はトレース情報を格納するためのディレクトリなので必ず指定しておきましょう。これらの設定が済んだらApacheを再起動します。その後phpinfo()でモジュールがロードされているか確認しておくと間違いがないです。

† トレース情報を取得してみる

準備ができたのでトレース情報を取得してみます。今回のトレース対象はNucleusなので、Nucleusの設定ファイルであるconfig.phpの上部にトレースを開始するための関数を記述しました。

config.php (追加分のみ)

apd_set_pprof_trace();

この状態でNucleusのサイトを表示すると、"apd.dumpdir"で指定したディレクトリに「prof.(プロセスID).(連番)」のようなトレース情報が入ったファイルができます。

公開しているウェブアプリのトレース情報を取得する場合には、必要な分のファイルが取得できたことが確認できたら、プログラム中の"apd_set_pprof_trace();"はすぐに削除した方がよいです。僕の場合、ちょうどYahooのロボットがやってきていた時間帯だったので、気がついたらトレースファイルが数百個できてしまっていました。

† 解析する

トレース情報はこんな感じで出力されます。

cat pprof.27289.6 (先頭だけ)

#Pprof [APD] v0.9.2
caller=/htdocs/config.php

END_HEADER
! 1 /htdocs/config.php
& 1 main 2
+ 1 1 5
& 2 apd_set_pprof_trace 2
+ 2 1 5
@ 0 5 1000 0 401
- 2
& 4 file_exists 1

テキストなので読もうと思えば読めなくもないのですが、読みやすい形式に変換することが賢明です。これはAPD付属の"pprofp"というコマンドで行うことができます。

# pprofp -R /tmp/pprof.27289.6

Trace for /htdocs/config.php
Total Elapsed Time = 1.08
Total System Time  = 0.06
Total User Time    = 0.23


         Real         User        System             secs/    cumm
%Time (excl/cumm)  (excl/cumm)  (excl/cumm) Calls    call    s/call  Memory Usage Name
--------------------------------------------------------------------------------------
6 0.00 1.06  0.00 0.22  0.00 0.06     1  0.0000   1.0618            0 selector
6 0.00 1.06  0.00 0.22  0.00 0.06     1  0.0000   1.0608            0 skin::parse
2 0.01 0.86  0.00 0.50  0.00 0.13   542  0.0000   0.0016            0 parser::doaction
4 0.00 0.78  0.00 0.43  0.00 0.12   386  0.0000   0.0020            0 call_user_func_array
8 0.00 0.76  0.00 0.07  0.00 0.01   108  0.0000   0.0071            0 manager::notify
7 0.00 0.74  0.00 0.05  0.00 0.01   186  0.0000   0.0040            0 call_user_func
6 0.00 0.53  0.00 0.00  0.00 0.00     1  0.0000   0.5335            0 np_blacklist::event_preskinparse
6 0.00 0.53  0.00 0.00  0.00 0.00     1  0.0000   0.5335            0 np_blacklist::blacklist
5 0.00 0.53  0.00 0.00  0.00 0.00     1  0.0000   0.5327            0 pbl_updateblacklist
4 0.53 0.53  0.00 0.00  0.00 0.00     3  0.1774   0.1774            0 fopen
3 0.00 0.50  0.00 0.30  0.00 0.08   155  0.0000   0.0032            0 parser::parse
3 0.00 0.33  0.00 0.18  0.00 0.05    21  0.0000   0.0155            0 actions::parse_plugin
6 0.00 0.24  0.00 0.13  0.00 0.03     2  0.0000   0.1218            0 np_showblogs::doskinvar
6 0.00 0.23  0.00 0.13  0.00 0.03     2  0.0000   0.1165            0 blog::showusingquery
7 0.15 0.16  0.00 0.01  0.00 0.00     3  0.0492   0.0528            0 ob_end_flush
7 0.00 0.16  0.00 0.01  0.00 0.00     1  0.0000   0.1585            0 np_linkcounter::event_postskinparse
6 0.10 0.10  0.01 0.01  0.00 0.00   168  0.0006   0.0006            0 mysql_query
5 0.00 0.09  0.00 0.01  0.00 0.00   118  0.0000   0.0008            0 sql_query
2 0.00 0.05  0.00 0.02  0.00 0.00    40  0.0000   0.0011            0 itemactions::parse_plugin
6 0.02 0.04  0.02 0.04  0.00 0.00   277  0.0001   0.0001            0 preg_replace_callback

あとは表示されたこのデータを読むだけです。まずこのデータの２カラム目の数値が最大の部分を探します。この例の場合には、fopen()の0.53というのが最大値になっているのが分かると思います。この例の場合、全体の実行時間（"Total Elapsed Time"）が1.08秒なので、この部分だけで全体の半分近くの時間を消費していることが分かります。

このように性能を劣化させている原因がわかったら、その部分がプログラム中のどこであるのかを確定していきます。たいていの場合原因となっている部分の直前の行がその原因を含んでいる部分になります^*1。この例の場合には"pbl_updateblacklist"が性能を劣化させる部分であるということが分かります。

この方法で部位が特定できない場合には"pprofp -t"を使って、call treeを出力させてその中を検索していく方法もあります。

# pprofp -t /tmp/pprof.27289.6 (先頭だけ)

main
  apd_set_pprof_trace
  file_exists
  include
    checkvars
      phpversion (9x)
    getnucleuspatchlevel
    error_reporting
    phpversion
    include_once

今回はひとつの処理が遅かっただけなので、すぐに性能劣化の原因が分かったのですが、場合によっては、そんなに遅くない処理をループなのでものすごい回数呼び出したりしている場合もあるので、その関数の実行回数であるCallsの部分に注目することも必要になってくると思います。