こんにちは。やまゆです。
サービスをリリースするにあたり、事前のシナリオテスト・負荷試験はなくてはならない項目です。
そこで主に API ごとの成功率、レイテンシ（リクエストしてからレスポンスが返ってくるまでの時間）、レスポンスサイズなどを計測し、想定されるユーザー数でも快適に遊べることを保証できるように改善を加えていきます。
改善の際、重くない部分をチューニングしてもほとんど効果が出ないので、「この API のどの部分（関数）に時間がかかっているのか？」を知ることが重要です。
それらを実際に動作している環境で計測し、可視化することを「プロファイリング」と呼ぶことがあります。
これは、ターゲットとする機能の実行時間について、「このメソッドに何秒かかった」や「全体の x % がこのメソッドで消費されている」などを確認するための仕組みです。
例えば PDOStatement::execute の割合が大きい場合、 SQL の発行から結果が返ってくるまでに時間がかかっている、ということが確認出来ます。その場合は、 PHP ではなく SQL に時間がかかっている（＝ボトルネックは PHP ではなく SQL である）ことを証明出来ます。
これまでの PHP プロファイリングは？
これまでの PHP(5.x~) では、下記のプロファイリングツールが使われることが多かった印象です。
xdebug
かなり昔からあるデバッグ用の php extension です。プロファイリングに限らず、デバッグで使われる様々なサポートをしてくれます。
- ステップ実行: IDE と連携し、ブレイクポイントを張って 1 行ずつ実行して変数の中身を確認したりすることが出来ます
var_dump関数の出力をより綺麗にします- トレーシング: 関数の実行順序やその引数などを可視化できます(
debug_backtraceみたいなものを自動で出してくれる奴です) - プロファイリング: 各関数の処理にどれくらいの時間がかかったか、全体の何 % を占めているかを確認出来ます
- コードカバレッジ: テストがどれくらい網羅されているかを集計してくれます
xdebug を有効にした状態だと、動作がかなり遅くなる（PHPUnit では自動的に xdebug を OFF にして実行してくれたりします）こと、プロファイリングの出力が Cachegrind という形式で、少し扱いづらいことなどの欠点もあるので、うまく使い分けていくような extension です。
xhprof
Meta(Facebook) 社が以前開発していたプロファイリングツールです。現在はメンテナンスされていないので、 PHP 8 だと動かせないかもしれません（未検証）。
現行ですと、 tideways/php-xhprof-extension を使えば PHP 8 でも動作します。
NewRelic / DataDog
有料の SaaS ですが、監視サービスで PHP を対象にトレースする機能を持ったものがあります。こちらは積極的にメンテされているので、予算の都合があえば利用すると楽ですね。
Reli とは？
Reli は PHP で書かれたサンプリングプロファイラ(あるいは VM 状態検査器)です。実行中の PHP スクリプトに関する情報をプロセスの外側から読み取ることができます。スタンドアローンのCLIツールなので、ターゲットとなるプログラムには何の修正も必要ありません。
https://github.com/reliforp/reli-prof
Reli は弊社員のいがらしさん謹製の OSS プロダクトです。
先ほど紹介した xdebug や xhprof などは、 C 言語で記述された PHP extension を対象のアプリケーションに導入し、その extension や agent を経由して計測を行います。
しかし、この Reli はそういった extension を用いず、アプリケーション側の修正不要で簡単にトレーシングを行ってくれます。計測を実行する側で必要なのは PHP 8(と FFI, pcntl あたりの extension)だけです。 pecl を使ったりビルドしたりすることなく、手軽に使えるのが大きなメリットですね。計測対象のアプリケーションは PHP 7.0+ のみが要件となっています。
xdebug, xhprof は、アプリケーション側で実行中に関数実行をフックして計測するため、パフォーマンスに影響が出ます。例えば phpunit を xdebug 付きで実行すると、無効時の数倍の時間がかかります。
Reli の場合は、別のプロセスで PHP のアプリケーションプロセスの情報を定期的に取得し、それを貯めることが出来るため、計測対象のパフォーマンスをほぼ損ねることなくトレーシングが可能です。
とにかく動かしてみる
まず計測対象のアプリケーション(ここでは Laravel テンプレート)を動かします。
$ composer create-project laravel/laravel reli-example-app
Creating a "laravel/laravel" project at "./reli-example-app"
...
$ cd reli-example-app
reli-example-app $ php artisan serve
INFO Server running on [http://127.0.0.1:8000].
Press Ctrl+C to stop the server
で、別のターミナルを立ち上げて動作確認します。
reli-example-app $ curl http://localhost:8000 -I
HTTP/1.1 200 OK
Host: localhost:8000
Date: Fri, 17 Feb 2023 01:06:46 GMT
Connection: close
X-Powered-By: PHP/8.2.3
Content-Type: text/html; charset=UTF-8
Cache-Control: no-cache, private
この例では Windows WSL2 Ubuntu 20.04 上で直接動かしていますが、コンテナを使って起動しても問題ありません。
次に計測を行う reli 側を用意します。 docker で動かすことも出来ますが、今回は create-project してホスト機（WSL2 環境上）で直接動かすことにします。なお環境によっては reli コマンドの実行に sudo が必要かもしれません。
$ composer create-project reliforp/reli-prof
...
$ cd reli-prof
reli-prof $ ./reli i:top -P "^\/usr\/bin\/php8\.2 -S 127\.0\.0\.1:8000"
./reli i:top コマンドを実行することで、対象のプロセスの監視を開始し、現在の PHP 処理の時間当たりの支配率を確認することが出来ます。
-P "^\/usr\/bin\/php8\.2 -S 127\.0\.0\.1:8000" という引数で、監視したいプロセスのコマンドラインを正規表現で指定しています。 apache2 や php-fpm など複数のプロセスに対して監視することも可能です。
空の Laravel プロジェクトだとほとんどサンプリング出来ていないですが、ある程度の規模のプロジェクトであれば有効なデータを観測できるはずです。
reli-prof $ ./reli i:daemon -P "^\/usr\/bin\/php8\.2 -S 127\.0\.0\.1:8000" > traces.log
このプロセスを起動している状態で何度かブラウザでアクセスしてみると、 traces.log にトレース結果が出力されます。
0 <unknown> <unknown>:-1
1 <unknown> <unknown>:-1
0 <unknown> <unknown>:-1
0 GrahamCampbell\ResultType\Success::flatMap /home/m-yamagishi/repos/reli-example-app/vendor/graham-campbell/result-t
ype/src/Success.php:93
1 Dotenv\Parser\EntryParser::parse /home/m-yamagishi/repos/reli-example-app/vendor/vlucas/phpdotenv/src/Parser/EntryP
arser.php:48
2 Dotenv\Parser\Parser::Dotenv\Parser\{closure} /home/m-yamagishi/repos/reli-example-app/vendor/vlucas/phpdotenv/src/
Parser/Parser.php:46
3 GrahamCampbell\ResultType\Success::flatMap /home/m-yamagishi/repos/reli-example-app/vendor/graham-campbell/result-t
ype/src/Success.php:93
4 Dotenv\Parser\Parser::Dotenv\Parser\{closure} /home/m-yamagishi/repos/reli-example-app/vendor/vlucas/phpdotenv/src/
Parser/Parser.php:45
5 array_reduce <unknown>:-1
6 Dotenv\Parser\Parser::process /home/m-yamagishi/repos/reli-example-app/vendor/vlucas/phpdotenv/src/Parser/Parser.ph
p:44
7 Dotenv\Parser\Parser::Dotenv\Parser\{closure} /home/m-yamagishi/repos/reli-example-app/vendor/vlucas/phpdotenv/src/
Parser/Parser.php:28
8 GrahamCampbell\ResultType\Success::flatMap /home/m-yamagishi/repos/reli-example-app/vendor/graham-campbell/result-type/src/Success.php:93
...
こんな感じのログが出力されるんですが、さすがにこれだけだとよくわからないので、内蔵されているコンバータを使ってグラフに変換してみます。
reli-prof $ ./reli c:flamegraph < traces.log > traces.svg
これで svg ファイルが生成されるので、ブラウザ等で開きます。
こんな感じのグラフが表示されます。
Laravel でアプリケーションの実装がほとんどない場合は、 dotenv のパースが結構支配的みたいですね。
なお <unknown> と出ているのは、トレース取得中に対象プロセスの状態が変化するなどして関数名の取得に失敗したもので、プロファイラの実行時に -S オプションを付けると減り、より正確なトレースになる（ただし計測時に対象プロセスの動作を一瞬止めるため、計測対象のパフォーマンスは低下する）そうです。
ただ、これでもちょっと見づらいというかあまり直感的ではないので、もう一つの出力形式である speedscope 対応の形式で出力してみます。
reli-prof $ ./reli c:speedscope < traces.log > speedscope.json
出力された json を https://www.speedscope.app で読み込むと、よりインタラクティブに操作出来るようになります。
このページは選択した json をサーバにアップロードしたりせず、ローカルで完結しているので業務コードに使っても問題ないでしょう。
時系列順に並べるだけでなく、処理が重い順に並び替えたり、テーブル形式で支配率を確認したり出来るのでとても便利です。
reli が出力するトレースデータは、「かかった時間(秒)」は乗っておらず、単位は「サンプルが取れた数」になっています。
デフォルトの設定だと 10 ms ごとに 1 回くらいの頻度でトレースしているので、 10 だったら大体 100ms くらいと想定するのが良さそうです。
—
コマンドで言えばたったの数回で計測し可視化することが出来る、非常に使いやすいシンプルなツールなんですが、裏では（私自身よくわかっていないですが）他のプロセス情報を垣間見るという面白いアプローチをしています。
業務では、実際にこのプロファイリングを元にチューニングを実施し、最適化を進めています。普通に実用性が高いので、みなさんも是非使ってみてくださいね。
—
巨大な PHP プロジェクトのチューニングをしてみたい、高負荷案件をこなしてみたいという方は是非採用情報をご覧ください！
