xhprofでパフォーマンスチューニング入門

本記事はマイネット Advent Calender7日目の記事です。
今回は社会人になってから(主にお腹周りの)成長が目覚ましい@w_cotaがお送りします。

はじめに

弊社ではスマートフォンゲームの運営を行っています。直近では他のゲーム会社からのタイトルを引き取って運用しているプロジェクトも増えてきております。弊社で開発したタイトルも含め、買収・協業のタイトルの中にはリリースから2年、3年と経過している長寿タイトルも多く見受けられます。
さて、長期間運営を重ねていきますと避けられない問題の一つが__技術的負債の積み重ね__かと思います。いかに優秀なエンジニアがいようと、いかに素晴らしい開発フローを採用していようとどうしても日々様々なタスクに追われる日常の業務の中では以下のようなシーンが発生し得るかと思います。

• イベントリリースまでもう時間無いし、ちょっと実装ダサいけどこのままリリースして次回直そう
• このページにバナー出したいんだけど、どうせ今回だけだしtplに掲載期間ベタ書きしちゃえ
• ここの処理、少し重いけど渡ってくるデータは最大100件までだしこのままでいいかな

少しの心の緩みが1年も経てば多大な負債に変わります。ダサい実装はリファクタリングされることなくいつの間にか次の新イベントに置き換わり、掲載期間をべた書きしたif文はいつの間かelseifが延々と連なっていき、今の所100件だからなんて油断してるといつの間にか100件が110件になり120件になり、最終的には1000件まで増えてる、なんて事は稀によくあることかと思われます。

そこでこの度意を決してPHPプロファイラとして有名なxhprof+xhguiを導入し、重くなってしまっていた処理をリファクタリングしてみた、という事がありましたのでその際の手順などをまとめてみました。

環境

• CentOS 6.4
• Apache 2.2
• PHP 5.3
• MySQL 5.5
• FuelPHP 1.7

xhprof導入

1. インストール

xhprofはドキュメントにもあります通り、PECLでインストール可能です。
xhprofのパッケージ情報を確認すると0.9.4が最新のようですので0.9.4をインストールします。

$ pecl install channel://pecl.php.net/xhprof-0.9.4

2. php.ini編集

実行時設定にある通り、php.iniに実行結果を保存するディレクトリを指定します。

[xhprof]
extension=xhprof.so
xhprof.output_dir="/var/log/xhprof/"

3. ログディレクトリ作成

上記で設定したディレクトリを作っておきます。ついでに権限も変更。

$ cd /var/log
$ mkdir xhprof
$ chmod 777 xhprof

最後にapacheを再起動して完了です。
正常にインストール出来ているとphpinfo()を確認した際にxhprofの欄が有効になっています。

xhgui導入

続いてプロファイル結果を可視化して分かりやすく表示する為のxhguiをインストールします。

1. ダウンロード

xhguiはgithubで公開されていますのでそちらからcloneするなりwgetするなりして取得します。
今回はgithubページからブラウザで直接取得しました。それを解凍し、諸々のファイルが置かれているxhgui-masterディレクトリをxhguiにリネームしてドキュメントルート以下へ配置します。

$ mkdir [hoge]/htdocs/xhgui
$ chown apache [hoge]/htdocs/xhgui
$ cp -r xhgui/* [hoge]/htdocs/xhgui/

2. httpd.conf編集

xhguiのReadmeにある通りに、先ほど配置したxhgui/extarnal/header.phpを実行させるために以下のように編集します。

httpd.conf

<VirtualHost *:80>
  php_admin_value auto_prepend_file "[hoge]/htdocs/xhgui/external/header.php"
  DocumentRoot [hoge]
  …
</VirtualHost>

3. config.php編集

xhgui/xhprof_lib/config.phpにあるDBへの接続情報を環境に合わせて修正します。
大体はDBのIPアドレス、ユーザとパスワード、アプリのURLだけかと思いますが、私の場合は$controlIPs[]にも自身がアクセスするローカルPCのIPアドレスを設定しました。

4. DBの設定

上記で設定したDBへ新たにxhprofデータベース(上記config.phpの内容に従って下さい)を作成し、その中に[hoge]/xhgui/xhprof_lib/utils/Db/Pdo.phpに記載されているCREATE TABLEクエリを実行して必要なテーブルを作成します。

graphviz導入

続いてプロファイル結果をグラフ表示するためのgraphvizをインストールします。

1. graphvizインストール

graphvizだけでなく、png変換などを行うgraphviz-gdも一緒に入れます。

# yum -y install graphviz graphviz-gd

2.config.php編集

[hoge]/xhgui/xhprof_lib/config.phpの内容を修正します。graphvizで使用するファイルなりディレクトリなりを設定しています。

$_xhprof['dot_binary']  = '/usr/bin/dot'; 
$_xhprof['dot_tempdir'] = '/tmp'; 
$_xhprof['dot_errfile'] = '/tmp/xh_dot.err';

解析してみる

1. index.php編集

FuelPHPにおいては[hoge]/htdocs/index.phpの中でbootstrap.phpを読み込む前後に以下を加えます。

if (function_exists('xhprof_enable')) {
    xhprof_enable();
}

// Boot the app
require APPPATH.'bootstrap.php';

if (function_exists('xhprof_disable')) {
    register_shutdown_function(function() {
        $xhprof_data = xhprof_disable();
        $XHPROF_ROOT = __DIR__.DIRECTORY_SEPARATOR.'xhgui';
        $XHPROF_SOURCE_NAME = 'fuelphp'
        define('XHPROF_LIB_ROOT', $XHPROF_ROOT . '/xhprof_lib/');
        global $_xhprof;
        include_once $XHPROF_ROOT . "/xhprof_lib/config.php";
        include_once $XHPROF_ROOT . "/xhprof_lib/utils/xhprof_lib.php";
        // include_once $XHPROF_ROOT . "/xhprof_lib/utils/xhprof_runs_mysql.php";
        include_once $XHPROF_ROOT . "/xhprof_lib/utils/xhprof_runs.php";
        $xhprof_runs = new XHProfRuns_Default();
        $run_id = $xhprof_runs->save_run($xhprof_data, $XHPROF_SOURCE_NAME);
    });
}

2. xhprop_lib/以下のファイルの所有者と権限を変更

私の環境ですと所有者を自身のユーザに変更、権限を777に設定しないとプロファイリングが行われませんでした。
詳細は要調査です…

ここまで行えばプロファイルの準備は完了です！

3. Let's プロファイル

解析を行いたいページにアクセスし、xhprofのページからRunIDをクリックすると以下のようなプロファイル画面が表示されるかと思います。

こちらの例ではカードゲームではよくありがちなデッキの自動構成処理を実行してみました。
但し所持カード枚数を仕様の10倍近くにした上で。24秒とは流石にとんでもないレスポンスタイムですね。

しかしこれだけでは何が何やら分からない。そこで「View Callgraph」をクリック。

するとgraphvizが先ほどのプロファイル結果を基に、どの関数がどれほど呼び出されてどれほどレスポンスに時間が掛かっているのかを描画してくれます。
赤いボックスが最もレスポンスが大きく、黄色がその次、太い矢印がレスポンスタイム的に一番食っている箇所です。

下の赤いボックスを拡大して見てみるとこのようになります。

想定の10倍のカード情報を引いてくるんだからそりゃあ重くもなりますよね…
流石にmysql自体のレスポンス改善までは手は出せないのでカード情報をいかに呼び出す回数を減らすか、という所を注視して矢印を辿っていきます。

呼び出し回数が多い処理なんかは一目瞭然。関数名なんかも表示されているのでそれを手掛かりにコツコツ。
関数の呼び出し順を変えてみるだとか、こういう場合はこっちの処理は読みに行かない、なんて作業をちくちく進めていけば結構簡単に改善されるもので、チューニング後に同じ処理を行ってみると…

あっさりと半分以下にまで抑える事が出来ました。
実際にリリースされている状態よりもかなり高負荷な状態ではありますが十分に改善が見られる結果かと思います。

おわりに

さて、極めてあっさりとxhprofを導入した手順とその活用例をご紹介させて頂きました。
ここで弊社アドベントカレンダー1日目の@takashabeの記事から引用を。

普段パフォーマンスは重要と思いつつ、実際にパフォーマンス問題に対処したことがない方は多いのではないでしょうか。パフォーマンスチューニングというと大抵社内のデキる人が対応して終わり、みたいなパターンも多いかと思います。

今回こちらのxhprofを導入してみましたが感想としては、見る箇所さえ分かってしまえば意外と簡単にパフォーマンスは改善出来る、という事です。
日々の積み重ねで出来た現在のソースコード達。一度立ち直ってリファクタリングの機会を設けてみるのも良いのではないでしょうか。

参考資料:
xhprofを使ってみた（インストール編） - Qiita
xhprofを使ってみた(XHGUIとCallgraphインストール編） - Qiita
FuelPHPで３種のprofilerを使ってみた- SlideShare
http://wiki.nonip.info/work/index.php?php%252F%25E9%2580%259F%25E5%25BA%25A6%25E6%2594%25B9%25E5%2596%2584%252FXHGui (リンク切れ)