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