Pro Yearly is on sale from $80 to $50! »

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

271fad8d53cd1f12f2b4b6d38e3d7bd3?s=47 uzulla
November 06, 2020

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

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

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

271fad8d53cd1f12f2b4b6d38e3d7bd3?s=128

uzulla

November 06, 2020
Tweet

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

  19. None
  20. None
  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 (プロファイラが起動してか ら、終了するまで) ここからたどっていく…のは ⾯倒なので、⾚い奴を探す

  26. None
  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でてもええやんw」 Preloadは最⾼!Autoload Optimizationより効果ある! (というか究極Autoloadが不要になる)

  40. まあ、本当はもっとちゃんとPreloadは調整していきましょう。 数を絞り込む、地道に。 Preloadされるphpリストの「正しい作り⽅」は確⽴されてない(個⼈の主観) どうやってファイルリストつくるか? 「真⼼込めて⼿作業」で運⽤していくのはつらい LibをアプデするとPathが変わるw ある程度⾃動化しないとやってられない

  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みたいなコードだとコールが循環して迷⼦になる
  47. None
  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秒)
  51. None
  52. None
  53. カッコイイし、 クリックしていくとスタック範囲をフィ ルタしていける

  54. None
  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で組まれたアプリ、チューニングのコツを教えて下さい!」 ??「吊るしのフルスタックフレームワークでチューニングとかいったら負け」