プロファイル結果の可視化三本勝負 in PHP

speaker uzulla
in "Laravel 勉強会 in 札幌 vol.3"
https://larasap.connpass.com/event/193566/

ref:
https://github.com/uzulla/xhprof-flamegraphs

Transcript

1. プロファイル結果の可視化三本勝負 in PHP speaker: uzulla date: 2020/11/06 at: Laravel 勉強会 in 札幌 vol.3
2. bio @uzulla Laravelまったくわからん この間Livewireで感動しました そろそろ再⼊⾨するかと思っている まあ経験上多分すぐ破⾨（出家？）する この間のISUCON予選をPHPで突破しました 「本戦？PHPなかった…ので…js…」「ダジャレやめろ」 このあたりの話はトーク外雑談ででも
3. 話す内容 プロファイリング（データ収集） からの可視化 call, tree, flame からのpreloadを雑に使う Tips
4. まず課題を探す 定規は測る対象がなければ孫の⼿でしかないので 「今回Laravelの勉強会なので、当然Laravelだな！」
5. 「laravelまったくわからん」 LaravelでできてるOSS…？なにがいいの…？ OctoberCMSってやつをつかうことにした 最近名前を知ったからであって、理由は特にない $ curl -s https://octobercms.com/api/installer | php $ php -S 127.0.0.1:3333 $ open http://127.0.0.1:3333/
6. なるほどね 管理画⾯を使うにはDB設定がいる らしい（していない） 時間もないので、何もせずこのま まつかう トップページをプロファイルしよ う httpdはビルトインサーバー
7. とりあえずxhprofいれる $ php -i |grep xhprof xhprof support => enabled はいってないなら⼊れる。
8. https://github.com/longxinH/xhprof 「今回はこのxhprofにするぜ（fbが諦めたので、forkが⾊々ある…）」 $ git clone https://github.com/longxinH/xhprof.git ./xhprof $ cd xhprof/extension/ $ phpize $ ./configure $ make && sudo make install $ vi /path/to/php.ini # 先頭にでも追加 extension = xhprof.so $ mkdir -p xhprof/tmp $ chmod 777 xhprof/tmp
9. さて… $ find . |grep ".php$" |wc -l 5071
10. ララベルよくわからんので… 「 index.php だけいじろう！」
11. vi index.php <?php /** * October - The PHP platform that gets back to basics. * * @package October * @author Alexey Bobkov, Samuel Georges */
12. 突然タレを⼊れます <?php ini_set("xhprof.output_dir", __DIR__."/xhprof/tmp"); define("START_AT", microtime(true)); require_once (__DIR__ . '/xhprof/xhprof_lib/utils/xhprof_runs.php'); xhprof_enable(XHPROF_FLAGS_CPU | XHPROF_FLAGS_MEMORY); register_shutdown_function(function () { $id = preg_replace('|/|u', " ／", $_SERVER['REQUEST_URI']); $id = preg_replace('/[^a-zA-Z0-9 ／]/u', "-", $id); $id .= "_" . sprintf("%d", (microtime(true) - START_AT)) . "ms_"; $runs = new XHProfRuns_Default(); $runs->save_run(xhprof_disable(), $id); }); /** 〜略
13. もう⼀回OctoberCMSを開く $ php -S 127.0.0.1:3333 $ open http://localhost:3333/
14. ファイルが⽣成されていることを確認。 $ ls xhprof/tmp/ 5f9e38ef7686c. ／_80ms_.xhprof 無いならなにか間違えている
15. 別シェルで xhprof ビューワーを⽴ち上げる $ php -d xhprof.output_dir=`pwd`/xhprof/tmp \ -S 127.0.0.1:3334 \ -t xhprof/xhprof_html/ # cli でphp.ini のxhprof の出⼒先dir 指定と # ビルトインサーバーのIPaddr:port 指定と # ビューワーアプリのDocRoot 指定してます $ open http://127.0.0.1:3334
16. Existing runsに⾊々でてくればOK
17. ということで結果が⾒れる お⽬当てのCall graphは 「View Full Callgraph」 （注意: Laravelのアプリはすっご いコールが多いので、描画にすっ ごい時間かかります）
18. Call graph
21. 「めちゃ複雑でデカイコールグラフでてきた！！」
22. 余談：view full callgraphがエラーになる場合 Graphvizがはいっていない brew install graphviz apt install graphviz 等 xhprof.output_dir=/path/to/tmp な指定が不⾜
23. ここまでのまとめ index.php をちょっといじるだけでプロファイラを⼊れられる なにもかもわからんアプリでもらくらく！ ビューワーは xhprof/xhprof_html/ で php -S であげるのが便利 リモートからつなぎたいなら、ポートフォワードすると良い なれると数分でここまで来ます 「使ったことがある」ではなく、「秒でいれられる」ようになりましょう
24. さて、Call graphを⾒ていきましょう 雑な⾒⽅ 「⾚くてデカい奴がヤバい」 「⻩⾊い奴は気になる」 「⽩い所は⼀旦無視だが、いずれ倒すことになる」 数字の読み⽅ Inc → 「こいつから以下」がどれくらいかかっているか Excl → 「こいつ⾃体が」どれくらいかかっているか Incがデカイのをたどり、Exclがデカイのを探す ⽮印の太さ 時間のかかり具合（≒ 処理の進む⽅向）
25. 開始箇所を⾒る ⼤体右上 total 72ms （プロファイラが起動してか ら、終了するまで） ここからたどっていく…のは ⾯倒なので、⾚い奴を探す
27. ⾚い所 autoload spl_autoload_call → Composer\Autoload\includeFile 未ロードのクラスが最初に必要になった時にautoloadするあたり。 「20msも⾷っている！ゆるせん！」 「流⽯フルスタックFW！クラスが多い！」 解決策として、preloadしてみましょう
28. 雑なPreload⽤コード $ vi preload.php <?php # preload.php こいつをphp.ini に書く ini_set("error_reporting", '-1'); ini_set("display_errors",'1'); ini_set("log_errors",'1'); include "php_list.php"; foreach ($list as $file) { opcache_compile_file($file); }
29. 雑にPreloadするphpファイルのリストをつくる $ echo "<?php $list=[];" > php_list.php $ find `pwd` |grep -e "\.php$" | php -R 'echo "\$list[] = \"$argn\";".PHP_EOL;' >> php_list.php <?php $list=[]; # php_list.php # 「『とにかく、`.php` ファイル全部いれてみた』などと供述しており」 $list[] = "/tmp/sample/php_list.php"; $list[] = "/tmp/sample/server.php"; $list[] = "/tmp/sample/bootstrap/autoload.php"; $list[] = "/tmp/sample/bootstrap/app.php"; $list[] = "/tmp/sample/index.php"; // めっちゃ⻑いので省略
30. php.iniで読み込み設定する # （今回cli でテストするので、`php --ini` で場所しらべて⼀回コピー） $ cp /etc/php.ini php.ini $ vi php.ini # 先頭にでも追記 opcache.enable_cli=1 opcache.preload=/tmp/sample/preload.php
31. Preloadできるかテスト $ php -c ./php.ini -a ｛雑につっこんでいるので、⼤抵最初はFatal 系のエラーが出る｝ Fatalがでないのに、Replが起きない（Bashに戻る）場合は、エラーレベル設定ミスでエ ラーがでてない可能性
32. 全部つっこんでるので、うごかないことがある ダメをちまちまとリストからはずす…のは⾯倒なので grep -v で除外する。 今回は以下のようにしてみたら、Warn⼭盛りだけどうごいた （WarnはPreloadで出るだけなので、アプリ実⾏時にはでない） 略） | grep -e "\.php$" | grep -v -e "xhprof" -e "psysh" -e "RiakCache" | （りゃぁっく
33. めちゃくちゃ Warningでてもシェルが起動すれば多分⼤丈夫!!!
34. 「ヨシ！！！！」
35. 起動速度（？） $ wc -l php_list.php 4834 php_list.php # 雑に追加した結果のファイル数 $ time php -c phpop.ini -r "echo 1;" ( ハチャメチャなWarning) 1 real 0m0.916s user 0m0.621s sys 0m0.274s $ time php -r "echo 1;" 1 real 0m0.123s user 0m0.057s sys 0m0.057s 0.916 - 0.123 = 0.793(sec) # 絞り込まないPreload は結構時間かかる。とはいえ「実⾏」ではないのでこんなもの
36. 再度の計測結果
37. ⾒えないので拡⼤ 72ms が 59ms に (何回か試すかぎり、まあ⼤体10〜20ms削れた) ほぼほぼ⽬的の箇所は削れた
38. 残ってる⾚いやつ 無事autoloadがきえましたが、な んだこいつは。 なんかのキャッシュじゃないかと 思うが、Laravel（も、October も）詳しくないので… 調べるなら⼿前のコールにブレー クポイント打ったり xhprof_enable をムーブさせた り まあ（⾚くても）50ms中2msを削 るのは効果少なそう。 省略！
39. ハイパー雑にやっても普通にPreloadは効きます、Preload最⾼。 「Warnでてもええやんｗ」 Preloadは最⾼！Autoload Optimizationより効果ある！ （というか究極Autoloadが不要になる）
40. まあ、本当はもっとちゃんとPreloadは調整していきましょう。 数を絞り込む、地道に。 Preloadされるphpリストの「正しい作り⽅」は確⽴されてない（個⼈の主観） どうやってファイルリストつくるか？ 「真⼼込めて⼿作業」で運⽤していくのはつらい LibをアプデするとPathが変わるｗ ある程度⾃動化しないとやってられない
41. 再起動をどうするか？ preloadすると、ファイル修正しても（再起動まで）反映されなくなる deployer の最後で systemctl restart すればいいんじゃないですかね？ 「⼀瞬落ちるじゃん」「PHPだからあきらめが肝⼼」 （他の⾔語みたいにBG Deployするくらいしかなさそう）
42. 話をxhprofに戻す コールグラフでなく表でソートす るのももちろん重要 ⾊々ソートすると is_null が何千 回もコールされてるとかわかって たのしいですね TimeのWallとCPUは、 基本Wallみたほうがよいです Wall:実時間、CPU:処理時間 wall≒ cpu+(I/O待ち時間等) I/Oは重要なので。
43. xhprofの⼩技 ビューワのこの⼀覧は「ファイル 名」です ⼯夫すると探しやすくなる 処理時間とかいれると⾒やすい （なお、⾏末時刻はUTC） ただ、ファイル名の⽂字数・種に はfs固有の制限があるので注意
44. # ⼯夫例 $id = preg_replace('|/|u', " ／", $_SERVER['REQUEST_URI']); $id = preg_replace('/[^a-zA-Z0-9 ／]/u', "-", $id); $id .= "_" . sprintf("%d", ((microtime(true) - START_AT))*1000) . "ms_"; $runs = new XHProfRuns_Default(); $runs->save_run(xhprof_disable(), $id); やり⽅は⾊々あるが、「ファイル名なので」 / とか ? とか & とかがあるとおかしくな る、それを避ける必要はある 例えば、 / は全⾓ ／ にするとか（他も同様に…） まあビューワーを改造しちゃってもいいかもね ここらへん、⾊々⼯夫すると便利。 ログインIDいれたりとか… が！⼿間かけてもダルいので、あきらめが肝⼼。
45. ⼿間をかけるな！時間をかけろ！ プロファイラを⼊れるのに⼿間取るより、（結果の）精査や、課題を⾒つけて解決に時 間をかけろ！ 例：xdebug とかもプロファイラ機能があるが、ビューワーが⾯倒すぎる 性能劣化が激しいし、延々Diskを消費するので、ちゃんと後で外すこと
46. 余談：PhpStorm持ちならxdebugだけでCall Tree xdebug設定して、PhpStormのなんでもアクションで"Analyze xdebug〜"で、⽣成され るcachegrind(互換)⽣成ファイル選ぶだけ。かんたん(?)にみえますね？ call tree とかいうやつ しかし、(やってみるとわかりますが)めっちゃみづらい コール数や、重い関数はわかるが…xhprofでもみれるし 「ツリーだからわかりやすいかも！」ということはない Laravelみたいなコードだとコールが循環して迷⼦になる
48. $ php -i |grep xdebug xdebug xdebug support => enabled ( 省略) $ mkdir xdebug_prof/ zend_extension="xdebug.so" # ini_set では設定できんのよなあ、他の⽅法はあるがぐぐってください xdebug.profiler_enable=1 xdebug.profiler_output_dir=/tmp/sample/xdebug_prof $ php -c ./php.ini -S 127.0.0.1:3333 $ ls xdebug_prof/ cachegrind.out.7613 # この⽣成ファイルを指定する
49. 正直、使い所がない（主観です） PhpStormの機能としても放置されてる…と思う appendな出⼒を全部合算とかあればよいのに 検索とかあればいいのに （ないんだよな） kcachegrind 等、他のcachegrind系可視化ツールを使ったほうが良いと思う （⼊れるの⾯倒だからつかっていない）
50. Flame graph Call Graph(例:xhprof),Call Tree(例:cachegrind)以外にFlame Graphという可視化 ⼀定サイクルでスタックトレースをサンプリングして、可視化する 「どのURLが重い」等ではなく、「どの処理がいつもいる・深い」を探す （スレッド処理系⽂化圏の概念） サンプルがタイマーで取られるので、ボロボロこぼれる 「複数のリクエストをまたいで」ビジュアライズしないと意味が薄い PHPだと不⼈気(パッとまともに動くものがない気がする) xhprofで⽣成されるデータを加⼯して、⽣成するツールはある xhprof_enable ではなく、 xhprof_sample_enable でログを取る サンプリング間隔は xhprof.sampling_interval で変更可能(初期0.1秒)
53. カッコイイし、 クリックしていくとスタック範囲をフィ ルタしていける
55. フレームグラフは… 「（index.phpから流れる）アプリ全体」が俯瞰できる 結果… FWがめっちゃ重いとか DBやKVS、外部APIコールの時間がめっちゃかかっているとか 仮に⾃分の書いた部分が0msだとしてもどうしようもないことがわかる
56. 以下、Flame graphの作り⽅ # index.php にいれるサンプルコード # コールグラフ作ったときのそれとコードが違う、共存不可能 ini_set("xhprof.output_dir", __DIR__ . "/xhprof/tmp"); ini_set("xhprof.sampling_interval", "100"); // デフォルト100000 require_once(__DIR__ . '/xhprof/xhprof_lib/utils/xhprof_runs.php'); xhprof_sample_enable(); register_shutdown_function(function () { $runs = new XHProfRuns_Default(); $runs->save_run(xhprof_disable(), (string)microtime(true)); }); $ rm xhprof/tmp/* # 過去データは必ず⼀度消す $ ab -n 1000 http://localhost:3333 # … などで、⼀定時間負荷をかけつづける。⼤量にファイルが⽣成される。 # 時間をかければかけるほど、精度が上がる。はず。⼀般的には。 # しかし重い！
57. # ツールをDL する、FlameGraph ⽣成ツール $ git clone git@github.com:brendangregg/FlameGraph.git # 変換ツール… の本家（？）がうごかんので、ちょっといじったものです $ git clone git@github.com:uzulla/xhprof-flamegraphs.git # xhprof 結果dir を指定し、⼤量のxhprof ファイルを処理する $ xhprof-flamegraphs/xhprof-sample-to-flamegraph-stacks xhprof/tmp \ | FlameGraph/flamegraph.pl > flamegraph.svg # ⽣成されたsvg をブラウザで開くと、クリック操作できます $ open flamegraph.svg
58. カッコイイんだけど 正直、PHPだと⾊々調整が必要 サンプリング間隔を調整したり xhprof.sampling_interval ⼤量にできるxhprofファイルを修正毎にちゃんと消す必要があるし （スレッド⽂化圏ではこれが問題にならない…） SVG⽣成するのにコマンド叩くの⾯倒だし しかし⾒た⽬はかっこいい！（笑）
59. 余談 変換コード改変すれば、 xhprof_enable データでフレー ム（？？？）グラフもかけないこ とはない 炎が海苔になってしまうので意味 はない FlameGraphのデータ⽣成は⽐較的 簡単なので、⾃作すると楽しいか も
60. まとめ ⾊々な可視化がある 重いURLがわかっているなら、Call Graphで詳細解析 時間がかかっている箇所が全くわからないなら、Flame Graphも有り （というほど、遅いURLを探せないことなんてあるのか？） PHPでデーモン書く時代(要出典)なので需要が上がると思う(独⾃⾒解)
61. まとめ コードにちまちまストップウォッチをいれる時代ではない ホットスポットを想像でさがしたり、針⼩棒⼤は良くない 「論より証拠」を⼀番に出す奴が強い ⼿早く可視化して、適切に迅速な改善を！ 「カネがあるならNewRelicとかいれたらいいよ」
62. 私のまとめ 私「Laravelで組まれたアプリ、チューニングのコツを教えて下さい！」 ??「吊るしのフルスタックフレームワークでチューニングとかいったら負け」