Upgrade to Pro — share decks privately, control downloads, hide ads and more …

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

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

uzulla

November 06, 2020
Tweet

More Decks by uzulla

Other Decks in Programming

Transcript

  1. プロファイル結果の可視化三本勝負 in PHP
    speaker: uzulla
    date: 2020/11/06
    at: Laravel 勉強会 in 札幌 vol.3

    View Slide

  2. bio
    @uzulla
    Laravelまったくわからん
    この間Livewireで感動しました
    そろそろ再⼊⾨するかと思っている
    まあ経験上多分すぐ破⾨(出家?)する
    この間のISUCON予選をPHPで突破しました
    「本戦?PHPなかった…ので…js…」「ダジャレやめろ」
    このあたりの話はトーク外雑談ででも

    View Slide

  3. 話す内容
    プロファイリング(データ収集)
    からの可視化
    call, tree, flame
    からのpreloadを雑に使う
    Tips

    View Slide

  4. まず課題を探す
    定規は測る対象がなければ孫の⼿でしかないので
    「今回Laravelの勉強会なので、当然Laravelだな!」

    View Slide

  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/

    View Slide

  6. なるほどね
    管理画⾯を使うにはDB設定がいる
    らしい(していない)
    時間もないので、何もせずこのま
    まつかう
    トップページをプロファイルしよ

    httpdはビルトインサーバー

    View Slide

  7. とりあえずxhprofいれる
    $ php -i |grep xhprof
    xhprof support => enabled
    はいってないなら⼊れる。

    View Slide

  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

    View Slide

  9. さて…
    $ find . |grep ".php$" |wc -l
    5071

    View Slide

  10. ララベルよくわからんので…
    「 index.php
    だけいじろう!」

    View Slide

  11. vi index.php
    /**
    * October - The PHP platform that gets back to basics.
    *
    * @package October
    * @author Alexey Bobkov, Samuel Georges
    */

    View Slide

  12. 突然タレを⼊れます
    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);
    });
    /**
    〜略

    View Slide

  13. もう⼀回OctoberCMSを開く
    $ php -S 127.0.0.1:3333
    $ open http://localhost:3333/

    View Slide

  14. ファイルが⽣成されていることを確認。
    $ ls xhprof/tmp/
    5f9e38ef7686c.
    /_80ms_.xhprof
    無いならなにか間違えている

    View Slide

  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

    View Slide

  16. Existing runsに⾊々でてくればOK

    View Slide

  17. ということで結果が⾒れる
    お⽬当てのCall graphは
    「View Full Callgraph」
    (注意: Laravelのアプリはすっご
    いコールが多いので、描画にすっ
    ごい時間かかります)

    View Slide

  18. Call graph

    View Slide

  19. View Slide

  20. View Slide

  21. 「めちゃ複雑でデカイコールグラフでてきた!!」

    View Slide

  22. 余談:view full callgraphがエラーになる場合
    Graphvizがはいっていない
    brew install graphviz
    apt install graphviz

    xhprof.output_dir=/path/to/tmp
    な指定が不⾜

    View Slide

  23. ここまでのまとめ
    index.php
    をちょっといじるだけでプロファイラを⼊れられる
    なにもかもわからんアプリでもらくらく!
    ビューワーは xhprof/xhprof_html/
    で php -S
    であげるのが便利
    リモートからつなぎたいなら、ポートフォワードすると良い
    なれると数分でここまで来ます
    「使ったことがある」ではなく、「秒でいれられる」ようになりましょう

    View Slide

  24. さて、Call graphを⾒ていきましょう
    雑な⾒⽅
    「⾚くてデカい奴がヤバい」
    「⻩⾊い奴は気になる」
    「⽩い所は⼀旦無視だが、いずれ倒すことになる」
    数字の読み⽅
    Inc → 「こいつから以下」がどれくらいかかっているか
    Excl → 「こいつ⾃体が」どれくらいかかっているか
    Incがデカイのをたどり、Exclがデカイのを探す
    ⽮印の太さ
    時間のかかり具合(≒
    処理の進む⽅向)

    View Slide

  25. 開始箇所を⾒る
    ⼤体右上
    total 72ms
    (プロファイラが起動してか
    ら、終了するまで)
    ここからたどっていく…のは
    ⾯倒なので、⾚い奴を探す

    View Slide

  26. View Slide

  27. ⾚い所
    autoload
    spl_autoload_call
    → Composer\Autoload\includeFile
    未ロードのクラスが最初に必要になった時にautoloadするあたり。
    「20msも⾷っている!ゆるせん!」
    「流⽯フルスタックFW!クラスが多い!」
    解決策として、preloadしてみましょう

    View Slide

  28. 雑なPreload⽤コード
    $ vi 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);
    }

    View Slide

  29. 雑にPreloadするphpファイルのリストをつくる
    $ echo " php_list.php
    $ find `pwd` |grep -e "\.php$" | php -R 'echo "\$list[] = \"$argn\";".PHP_EOL;' >> 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";
    //
    めっちゃ⻑いので省略

    View Slide

  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

    View Slide

  31. Preloadできるかテスト
    $ php -c ./php.ini -a
    {雑につっこんでいるので、⼤抵最初はFatal
    系のエラーが出る}
    Fatalがでないのに、Replが起きない(Bashに戻る)場合は、エラーレベル設定ミスでエ
    ラーがでてない可能性

    View Slide

  32. 全部つっこんでるので、うごかないことがある
    ダメをちまちまとリストからはずす…のは⾯倒なので
    grep -v
    で除外する。
    今回は以下のようにしてみたら、Warn⼭盛りだけどうごいた
    (WarnはPreloadで出るだけなので、アプリ実⾏時にはでない)
    略) | grep -e "\.php$" | grep -v -e "xhprof" -e "psysh" -e "RiakCache" |
    (りゃぁっく

    View Slide

  33. めちゃくちゃ Warningでてもシェルが起動すれば多分⼤丈夫!!!

    View Slide

  34. 「ヨシ!!!!」

    View Slide

  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
    は結構時間かかる。とはいえ「実⾏」ではないのでこんなもの

    View Slide

  36. 再度の計測結果

    View Slide

  37. ⾒えないので拡⼤
    72ms が 59ms に
    (何回か試すかぎり、まあ⼤体10〜20ms削れた)
    ほぼほぼ⽬的の箇所は削れた

    View Slide

  38. 残ってる⾚いやつ
    無事autoloadがきえましたが、な
    んだこいつは。
    なんかのキャッシュじゃないかと
    思うが、Laravel(も、October
    も)詳しくないので…
    調べるなら⼿前のコールにブレー
    クポイント打ったり
    xhprof_enable
    をムーブさせた

    まあ(⾚くても)50ms中2msを削
    るのは効果少なそう。
    省略!

    View Slide

  39. ハイパー雑にやっても普通にPreloadは効きます、Preload最⾼。
    「Warnでてもええやんw」
    Preloadは最⾼!Autoload Optimizationより効果ある!
    (というか究極Autoloadが不要になる)

    View Slide

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

    View Slide

  41. 再起動をどうするか?
    preloadすると、ファイル修正しても(再起動まで)反映されなくなる
    deployer
    の最後で systemctl restart
    すればいいんじゃないですかね?
    「⼀瞬落ちるじゃん」「PHPだからあきらめが肝⼼」
    (他の⾔語みたいにBG Deployするくらいしかなさそう)

    View Slide

  42. 話をxhprofに戻す
    コールグラフでなく表でソートす
    るのももちろん重要
    ⾊々ソートすると is_null
    が何千
    回もコールされてるとかわかって
    たのしいですね
    TimeのWallとCPUは、
    基本Wallみたほうがよいです
    Wall:実時間、CPU:処理時間
    wall≒
    cpu+(I/O待ち時間等)
    I/Oは重要なので。

    View Slide

  43. xhprofの⼩技
    ビューワのこの⼀覧は「ファイル
    名」です
    ⼯夫すると探しやすくなる
    処理時間とかいれると⾒やすい
    (なお、⾏末時刻はUTC)
    ただ、ファイル名の⽂字数・種に
    はfs固有の制限があるので注意

    View Slide

  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いれたりとか…
    が!⼿間かけてもダルいので、あきらめが肝⼼。

    View Slide

  45. ⼿間をかけるな!時間をかけろ!
    プロファイラを⼊れるのに⼿間取るより、(結果の)精査や、課題を⾒つけて解決に時
    間をかけろ!
    例:xdebug とかもプロファイラ機能があるが、ビューワーが⾯倒すぎる
    性能劣化が激しいし、延々Diskを消費するので、ちゃんと後で外すこと

    View Slide

  46. 余談:PhpStorm持ちならxdebugだけでCall Tree
    xdebug設定して、PhpStormのなんでもアクションで"Analyze xdebug〜"で、⽣成され
    るcachegrind(互換)⽣成ファイル選ぶだけ。かんたん(?)にみえますね?
    call tree とかいうやつ
    しかし、(やってみるとわかりますが)めっちゃみづらい
    コール数や、重い関数はわかるが…xhprofでもみれるし
    「ツリーだからわかりやすいかも!」ということはない
    Laravelみたいなコードだとコールが循環して迷⼦になる

    View Slide

  47. View Slide

  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
    #
    この⽣成ファイルを指定する

    View Slide

  49. 正直、使い所がない(主観です)
    PhpStormの機能としても放置されてる…と思う
    appendな出⼒を全部合算とかあればよいのに
    検索とかあればいいのに
    (ないんだよな)
    kcachegrind 等、他のcachegrind系可視化ツールを使ったほうが良いと思う
    (⼊れるの⾯倒だからつかっていない)

    View Slide

  50. Flame graph
    Call Graph(例:xhprof),Call Tree(例:cachegrind)以外にFlame Graphという可視化
    ⼀定サイクルでスタックトレースをサンプリングして、可視化する
    「どのURLが重い」等ではなく、「どの処理がいつもいる・深い」を探す
    (スレッド処理系⽂化圏の概念)
    サンプルがタイマーで取られるので、ボロボロこぼれる
    「複数のリクエストをまたいで」ビジュアライズしないと意味が薄い
    PHPだと不⼈気(パッとまともに動くものがない気がする)
    xhprofで⽣成されるデータを加⼯して、⽣成するツールはある
    xhprof_enable
    ではなく、 xhprof_sample_enable
    でログを取る
    サンプリング間隔は xhprof.sampling_interval
    で変更可能(初期0.1秒)

    View Slide

  51. View Slide

  52. View Slide

  53. カッコイイし、
    クリックしていくとスタック範囲をフィ
    ルタしていける

    View Slide

  54. View Slide

  55. フレームグラフは…
    「(index.phpから流れる)アプリ全体」が俯瞰できる
    結果…
    FWがめっちゃ重いとか
    DBやKVS、外部APIコールの時間がめっちゃかかっているとか
    仮に⾃分の書いた部分が0msだとしてもどうしようもないことがわかる

    View Slide

  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
    # …
    などで、⼀定時間負荷をかけつづける。⼤量にファイルが⽣成される。
    #
    時間をかければかけるほど、精度が上がる。はず。⼀般的には。
    #
    しかし重い!

    View Slide

  57. #
    ツールをDL
    する、FlameGraph
    ⽣成ツール
    $ git clone [email protected]:brendangregg/FlameGraph.git
    #
    変換ツール…
    の本家(?)がうごかんので、ちょっといじったものです
    $ git clone [email protected]: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

    View Slide

  58. カッコイイんだけど
    正直、PHPだと⾊々調整が必要
    サンプリング間隔を調整したり
    xhprof.sampling_interval
    ⼤量にできるxhprofファイルを修正毎にちゃんと消す必要があるし
    (スレッド⽂化圏ではこれが問題にならない…)
    SVG⽣成するのにコマンド叩くの⾯倒だし
    しかし⾒た⽬はかっこいい!(笑)

    View Slide

  59. 余談
    変換コード改変すれば、
    xhprof_enable
    データでフレー
    ム(???)グラフもかけないこ
    とはない
    炎が海苔になってしまうので意味
    はない
    FlameGraphのデータ⽣成は⽐較的
    簡単なので、⾃作すると楽しいか

    View Slide

  60. まとめ
    ⾊々な可視化がある
    重いURLがわかっているなら、Call Graphで詳細解析
    時間がかかっている箇所が全くわからないなら、Flame Graphも有り
    (というほど、遅いURLを探せないことなんてあるのか?)
    PHPでデーモン書く時代(要出典)なので需要が上がると思う(独⾃⾒解)

    View Slide

  61. まとめ
    コードにちまちまストップウォッチをいれる時代ではない
    ホットスポットを想像でさがしたり、針⼩棒⼤は良くない
    「論より証拠」を⼀番に出す奴が強い
    ⼿早く可視化して、適切に迅速な改善を!
    「カネがあるならNewRelicとかいれたらいいよ」

    View Slide

  62. 私のまとめ
    私「Laravelで組まれたアプリ、チューニングのコツを教えて下さい!」
    ??「吊るしのフルスタックフレームワークでチューニングとかいったら負け」

    View Slide