はじめまして！クイックに中途入社して早１年になりますソフトウェアエンジニアのたかにーです。
今回は弊社サイトの高速化に取り組んだ際に、プロファイラを用いてボトルネック調査をした時のお話をしたいと思います。
パフォーマンス改善を行うにあたり、重そうな場所を手当たり次第チューニングしたくなるところですが、まずはプログラムを計測してどこがボトルネックとなっているかを見極めることが重要です。
「Goの父」とも呼ばれるロブ・パイク氏も「Rob Pike's 5 Rules of Programming（プログラミング5カ条）」において、以下のようにおっしゃっていますね。
1. プログラムがどこで時間を費やすかはわからない。ボトルネックは意外な場所で発生するので、ボトルネックがどこにあるかを証明するまでは、臆測でスピードハックを試みてはならない。
2. 測定せよ。測定して、コードのある部分が他の部分を圧倒しない限り、速度の調整をしてはいけない。
（引用元：Rob Pike's 5 Rules of Programming）
ということで、ボトルネックを特定すべくプロファイラによる調査を行いました。
プロファイラとは
プロファイラとは、コンピュータプログラムが実行される様子を監視・記録し、プログラム中の各箇所の動作順や実行時間などを集計・解析するプログラム。ソフトウェアの開発環境や実行環境の機能の一部として提供され、プログラムの性能測定・解析を行うことができる。
（引用元：プロファイラ 【profiler】）
プログラムをプロファイラにかけることで、各関数の呼び出し頻度やそれにかかる時間を計測することができます。つまりチューニング対象である実行頻度の高い箇所や実行時間の長い箇所を知ることができるわけですね。
世には様々なプロファイラ・ツールが存在しますが、今回は
- 測定の対象がPHP（Laravel）
- 目的は解析ではなくその先の高速化なので、導入が容易なもの
ということで、導入事例やドキュメントが豊富で、解析したいコード範囲を容易に指定できるPHPの階層型プロファイラxhprofを採用しました。
※他ツールとの詳細な比較に関しては、ここでは割愛させていただきます。
xhprofの導入手順
解析対象としたい開発環境は以下になります。
環境環境
開発環境にプロファイラを導入するのに加えて、解析結果の表示用環境も用意します。プロファイルビューアとしてはxhprof-htmlを利用しました。開発環境に同居させることも可能だったのですが、出来るだけ余計なコードを含めたくなかったため別環境としました。 github.com
ではxhpforの導入手順について見ていきましょう。
- 構成
./
├ docker-compose.yml
├ logs/xhprof/
├ dev-app/
│ ├ Dockerfile
│ ├ etc/php.ini
│ └ var/log/httpd/xhprof/
└ xhprof-viewer/
├ Dockerfile
├ tmp/xhprof/
└ xhprof-html/
- dev-app/Dockerfile
開発環境(dev-app)にxhprofをインストールします。 拡張機能のソースをコンパイルするのに必要なため、php-develもインストールが必要です。
RUN yum update -y \ # install php-devel && yum install -y php-devel # install pickle && curl -s -L https://github.com/FriendsOfPHP/pickle/releases/latest/download/pickle.phar -o /usr/bin/pickle \ && chmod 755 /usr/bin/pickle \ # install xhprof && pickle install --defaults xhprof
- php.ini
php拡張モジュールにxhprofを追加し、解析結果の出力先を設定します。
extension=xhprof.so xhprof.output_dir=/var/log/httpd/xhprof/
次に、解析結果表示用の環境（xhprof-viewer）を準備します。
- xhprof-viewer/Dockerfile
解析結果を格納するためのログディレクトリを用意し、後述するコールグラフ描画のためにgraphvizをインストールします。
FROM php:7.3-apache # install graphviz RUN apt -y update RUN apt install -y graphviz # log directory RUN mkdir /tmp/xhprof RUN chmod 777 /tmp/xhprof/
xhprof-viewerにxhprof-htmlを配置します。
# git clone https://github.com/sters/xhprof-html.git .
最後にそれぞれのコンテナで解析結果を共有するための設定を追加します。
- docker-compose.yml
# dev-app : 解析対象の開発環境
dev-app:
volumes:
- ./logs/xhprof:/var/log/httpd/xhprof
# xhprof-viewer : プロファイラビューワー
xhprof-viewer:
volumes:
- ../xhprof-html/:/var/www/html/
- ./logs/xhprof:/tmp/xhprof/
xhprofの使い方
ここではxhprofの使い方について紹介していきたいと思います。
xhprofの使い方自体は非常にシンプルです。
解析したいコードの開始位置と終了位置に以下のコードを入れることで、プロファイル結果を得ることができます。
xhprof_enable(XHPROF_FLAGS_NO_BUILTINS | XHPROF_FLAGS_MEMORY); // 開始位置
〜中略（解析対象のプログラム）〜
$data = xhprof_disable(); // 終了位置. $dataにプロファイル結果が格納される
file_put_contents('結果ファイル名', serialize($data)); // xhprof-htmlを用いるため結果をserialize
xhprof_enableには定義済みの定数を指定して、解析対象を調整することが可能です。
www.php.net
上記の例では
XHPROF_FLAGS_NO_BUILTINS ：ビルトイン関数 (内部関数) をスキップする
XHPROF_FLAGS_MEMORY ：メモリのプロファイル情報を出力に含める
という設定にしています。
実際の運用では他のメンバーが使いやすいように、プロファイラの開始 / 終了周りの処理をサービスコンテナにしてFacadeを作成し、Middlewareからコールされるようにすることで、APIを含む全てのhttp(s)リクエストの解析を簡単に行えるようにしました。
また、プロファイラを行うか否かはコードに直接記載するのではなく、Redisキャッシュに保存した値によって制御するようにしました。該当のキャッシュ値を開発用のデバッグ機能で操作することで、コードに手を入れることなく気軽にプロファイラを利用できます。
xhprofによる解析結果
ここからはxhprofによって得られる解析結果について紹介したいと思います。
プロファイラ結果をxhprof-htmlで確認すると、以下のような形でリクエストごとの解析結果へのリンクが表示されます。
上記リンクから遷移すると、解析結果の詳細を確認することができます。
それぞれの関数が何回コールされているか、関数自体にどれぐらい時間が掛かっているかを確認することできます。
各項目については以下の通りです。
| 項目名 | 内容 |
|---|---|
| Function Name | コールされた関数名 |
| Calls | 関数がコールされた回数 |
| Incl. Wall Time | 関数全体の処理時間 処理をネストした場合、全経過時間を含むことになる |
| Excl. Wall Time | 該当関数からコールされた関数の実行時間を除外した関数の純粋な処理時間(microsec) Excl. Wall TimeをCallsで割ると1回あたりの処理時間になる |
View Full Callgraphのリンクからはコールグラフが確認でき、全体の処理の流れやボトルネックをわかりやすく可視化することも可能です。赤く表示されているのが問題がありそうな箇所です。
またFunction Nameのリンクからは、それぞれの関数のParent function（コール元関数）やChild functions（コールしている関数）を確認することができます。
関数単体の処理時間が大きい場合は関数自体がボトルネックと言えますし、１回ごとの処理時間は短いもののコール数が多すぎて全体の処理時間に与える影響が大きい場合は、Parent functionを辿ることでコール元の処理に問題が無いか？といったアプローチをすることができるわけですね。
実際に見つかったボトルネック
解析結果を通じて、ボトルネックになっているホットスポットあるいはホットパスがいくつも発見されました。
- ループ内でのDBアクセス
- マスタデータの重複取得
- 大量のDB取得値に対する複数回のCollection::whereコール
具体的なパフォーマンスチューニングについてはここでは触れませんが、発見したボトルネックに対して適切に改修していくことで、大きな速度改善に繋げることができました。
まとめ
プロファイラによるボトルネック調査について紹介させていただきました。
パフォーマンスチューニングに限った話では無いかと思いますが、しっかりと計測し原因を突き止めることが結果として効率的な課題解決に繋がるということを実感した次第です。
皆様もぜひプロファイラを用いてご自分の書いたソースコードを解析してみてください。
＼\『真のユーザーファーストでマーケットを創造する』仲間を募集中です!! /／
