俺の PHP プロファイラの話 PHP スクリプトで PHP 処理系のメモリをのぞき込む

Transcript

1. 俺の PHP プロファイラの話 PHP スクリプトで PHP 処理系のメモリをのぞき込む 五十嵐 進士 / sji / sj-i / @sji_ch　 株式会社インフィニットループ
2. 自己紹介 @sji_ch SNS 上のアイコンは GitHub が自動生成した奴
3. 生まれも育ちも仙台
4. ふつうのサラリーマン 株式会社インフィニットループ仙台支社所属 スマホゲーのサーバサイドプログラマ
5. Agenda プロファイラとは 自作 PHP プロファイラ Reli の紹介 Reli の処理時間計測機能 Reli のメモリ解析機能 Reli の内部構造 まとめ
6. プロファイラとは
7. プロファイラってこういうやつ 性能解析ツール 実行中のプログラムの挙動を収集 ボトルネックを見つけるのに使える
8. ボトルネック 80:20 の法則 ごく一部の処理がマシン資源の大部分を使う 実行時間やメモリ使用量など 一部を直すだけで大幅に改善しがち 瓶の首の細さが水の出る速度を決める
9. 推測するな、計測せよ プロファイラのようなツールでの計測が要る 憶測でコードを直しているヒマはない 実際のリソース使用量を見る
10. 当てずっぽうでは当たらない ボトルネックはシステム全体の中の一部 あてずっぽうで直すとハズレが多い ある程度以上の規模のシステムで改善点を突き 止めるのは当てずっぽうでは難しい 砂漠でゴマ粒を、haystack で needle を探すよ うなもの 膨大な時間をつぎ込めばできる、しかしその 時間はない
11. 俺のプロファイラの話
12. Reli 2020 年頃から個人的に作っている PHP 製ツール 趣味でも仕事でも使ってる PHP の PHP による PHP のためのプロファイラ 実行中のプログラムの処理内容やメモリ内容を確認できる CLI ツール 無修正の解析対象プログラムをプロセス外から解析 https://github.com/reliforp/reli-prof
13. デモ
14. 4 年前にもタガヤスで話した 実は 4 年前のタガヤスでも同じネタで話した PHP で実行中のスクリプトの動作を下から覗き見る https://speakerdeck.com/sji/php-deshi-zhong-nosukuriputonodong-zuo-woxia-karasi-ki-ru
15. というかずっと同じネタをこすり続けてる ここ数年の技術トークのけっこうな割合がこれについての話な気がする PHP Conference Fukuoka 2019: PHPの関数実行とその計測 PHPerKaigi 2022: PHP で PHP のプロファイラをつくろう PHPerKaigi 2023: 時間を気にせず普通にカンニングもしつつ ISUCON12 本選問題を PHP でやってみる PHP Conference Tokyo 2023: PHP で PHP のメモリプロファイラをつくろう PHPerKaigi 2024: PHP で読む楽しいコアダンプ
16. strrev('php-profiler') → reliforp-php → Reli for P(PHP) 元は php-profiler という名前 ライセンス問題から名前の変更が必要に 最適化のために取った処理系由来のコードが PHP ライセンス PHP ライセンスは「PHP hogehoge」のような名前を許可しない テキトーに選んだ PHP の文字列操作関数を元の名前へ適用した上で変形
17. Reli の機能: 実行内容取得
18. トレース取得 実行中のプロセスのコールトレースを取得 プロセス ID で対象を指定 今どの関数やメソッド・ファイル・行の処理を実行中か どこから呼ばれているか さらにそれがどこから呼ばれているか さらにそれがどこから呼ばれているか 「このスクリプト本当に動いてる？処理進んでそう？」を確認できる composer install が遅いな、ちゃんと進んでるかな、などもわかる $ sudo php ./reli i:trace -p 2182685 0 time_nanosleep <internal>:-1 1 Reli\Lib\Loop\LoopMiddleware\NanoSleepMiddleware::invoke /home/sji/work/reli/src/Lib/Loop/LoopMiddlew 2 Reli\Lib\Loop\LoopMiddleware\KeyboardCancelMiddleware::invoke /home/sji/work/reli/src/Lib/Loop/LoopMi 3 Reli\Lib\Loop\LoopMiddleware\RetryOnExceptionMiddleware::invoke /home/sji/work/reli/src/Lib/Loop/Loop 4 Reli\Lib\Loop\Loop::invoke /home/sji/work/reli/src/Lib/Loop/Loop.php:26 5 Reli\Command\Inspector\GetTraceCommand::execute /home/sji/work/reli/src/Command/Inspector/GetTraceCom 6 Symfony\Component\Console\Command\Command::run /home/sji/work/reli/vendor/symfony/console/Command/Com 7 Symfony\Component\Console\Application::doRunCommand /home/sji/work/reli/vendor/symfony/console/Applic 8 Symfony\Component\Console\Application::doRun /home/sji/work/reli/vendor/symfony/console/Application.p 9 Symfony\Component\Console\Application::run /home/sji/work/reli/vendor/symfony/console/Application.php 10 <main> /home/sji/work/reli/reli:45
19. daemon モードでのトレース取得 プロセス ID でなくコマンドラインの正規表現パターンで対象を指定 毎秒プロセスリストを監視し、条件にマッチするプロセスを見つけるたびアタッチ 対象の プロセス ID を決め打てる場合ばかりではない、ので必要 apache や fpm などのワーカプロセスは数リクエスト処理したら生え変わり、とかもある 「とにかく fpm のこの名前の pool のワーカ」といった指定が可能 Reli は複数のワーカプロセスを生やす 複数ターゲットから同時にトレースを取得可能 デフォルトでは 8 並列で待ち受け、設定で増やせる $ sudo php ./reli i:daemon -P "^/usr/sbin/httpd"
20. トレースを集めると嬉しいこと → ボトルネックの特定
21. よくあるプログラムは関数実行の連続 プログラムの実行は処理の連続 処理内容はいくつかの単位で区切れる ファイルや関数、行番号、VM 命令など ある処理を持つ部品が別の部品へ、の呼び出し の連続
22. サンプリングプロファイラの原理 だいたい等間隔でコールトレースを取得 長く実行される処理ほど引っかかる確率が高い 多くのサンプルを集めれば多くの時間を使って いる処理がわかる
23. speedscope でのコールトレースの集計・可視化 集めたコールトレースを speedscope で可視化 reli の出力を標準出力リダイレクトで集める reli の speedscope 変換機能を使って speedscope 用の JSON に変換 フレームグラフで遅い部分が視覚的に分かる ある処理の caller と callee それぞれを集計表示 URL の振り分け処理から呼ばれてる処理を見れば遅い URL が分かる DB アクセスのような末端処理を呼ぶ処理を見れば遅いクエリが分かる
24. speedscope のデモ
25. top-like モード 毎秒で top コマンドっぽく集計表示 挙動的には daemon と同様
26. 参考情報 元ネタは phpspy phpspy の元ネタは rbspy python 用で py-spy というものも
27. Reli の機能: メモリ内容解析
28. PHP 処理系のメモリ管理概要 スクリプトで値が必要になったら処理系が自動で必要サイズの領域を確保 関数呼び出しでのローカル変数領域や new でのプロパティ領域など データの種類によっては参照カウントを処理系が管理 mod_php や fpm の構成ではリクエストごとにほぼ全解放 普段はプログラマが意識しなくてよい
29. 参照カウント 「何箇所で使われているか」のカウンタ 参照型の値は同じ領域への参照箇所が増えるたび参照カウントを 1 増やす オブジェクト、配列、文字列、リソース、PHP 参照 関数終了でのローカル変素破棄など、参照が減るたび参照カウントを 1 減らす 参照カウントが 0 になった領域は自動で解放 循環参照は M&S 風の GC で別途解放
30. リクエストごとのメモリ領域 PHP 処理系のメモリは ZendMM が管理 Zend Memory Manager ZendMM には 2 種類のメモリ領域 リクエストごとリセットされるメモリ領域 リクエストをまたいで残る永続メモリ領域 どちらも最終的には OS からもらう仮想メモリ領 域を使う 名前の Zend は Zeev と Andi の名前から memory_get_usage() などで取れるのはリクエス トごとの領域
31. 普段の PHPer はメモリを意識しなくて済む メモリは値を使う時に勝手に裏で確保されるもの メモリは値が不要になったら勝手に裏で解放されるもの メモリはリクエストが終わったら勝手に裏で解放されるもの ほとんどのリクエストは短命、メモリリークをほとんど気にしなくてよい
32. 長時間実行プロセスでは話が別 mod_php や fpm 以外の環境で PHP を動かすシーンも増えてきた RoadRunner や Swoole などの AltFPM バッチ処理やジョブキューのワーカー 静的解析器など開発用の PHP ツール これらのプロセスは長時間生きたり、大量のデータを処理することが多い メモリリークが問題になることも どこにどれだけメモリを使っているか把握が必要
33. Reli のメモリ解析モード プロセス ID で指定したプロセスのメモリ内容を解析 どこでどんなサイズの何が参照されているかの情報を一通り取得・解析 JSON で構造化した内容にまとめてプロセスの状態をガッと出力 jq などの JSON クエリでプロセスの状態をクエリできる
34. 取得できる内容 処理系のコンパイル時の作業用領域 実行中のコールトレースと各コールフレームの ローカル変数 グローバル変数の領域 文字列、配列、オブジェクトの実体領域 各定数用の領域 各クラスの静的プロパティ領域 各関数の静的変数領域 各クラスや関数定義の管理情報 VM スタックサイズ 関数ごとのコンパイル後 VM 命令列 全オブジェクト表
35. JSON 出力の嬉しさ: クエリ可能性 定型のクエリで色々なプロセスのメモリ状態を解析できる 知識のスニペット化 処理系メモリ内のどこをどう見てたどれば使える情報を得られるか 気合があれば目 grep もギリできる 性能的には微妙なので将来は RDB に突っ込みたい SQL の方がクエリもちょっと書きやすい、気がする
36. 種類別にサイズの大きな領域ランキングを集計する例 cat memory_analyzed.json | jq .location_types_summary | jq -r '(["location_type", "count", "memory_usag location_type | count | memory_usage ============= | ===== | ============ ZendStringMemoryLocation | 38045 | 1992633 ZendArrayTableMemoryLocation | 538 | 991352 ZendOpArrayBodyMemoryLocation | 1323 | 921840 ZendArrayTableOverheadMemoryLocation | 416 | 370896 ZendOpArrayHeaderMemoryLocation | 1356 | 325440 ZendClassEntryMemoryLocation | 179 | 88784 ZendArgInfosMemoryLocation | 1228 | 82080 RuntimeCacheMemoryLocation | 354 | 42976 ZendObjectMemoryLocation | 273 | 40744 ZendPropertyInfoMemoryLocation | 371 | 20776
37. インスタンスがメモリを多く食っている クラスのランキングを集計する例 cat memory_analyzed.json | jq .class_objects_summary | jq -r '(["class_name", "count", "memory_usage"] class_name | count | memory_usage ========== | ===== | ============ Closure | 62 | 20336 DI\\Definition\\ObjectDefinition | 12 | 2016 Fiber | 5 | 1480 DI\\Definition\\Helper\\AutowireDefinitionHelper | 10 | 1200 Revolt\\EventLoop\\Internal\\SignalCallback | 7 | 952 DI\\Definition\\Reference | 12 | 864 Amp\\Internal\\FutureState | 6 | 816 Amp\\ByteStream\\ReadableResourceStream | 3 | 696 DI\\Definition\\ObjectDefinition\\MethodInjection | 9 | 648 Monolog\\Level | 8 | 576
38. サイズの大きな文字列を 参照元付きでランキング表示する例 cat $memory_analyzed_reli | jq '. as $root | path(..|objects|select(."#type"=="StringContext"))| . as $ size | node_id | path ==== | ======= | ==== 93450252 | 14396 | context.call_frames.2.local_variables.serialized_messages.referenced.array_element 45285439 | 14377 | context.call_frames.2.local_variables.content.array_elements.0.value 168289 | 59466 | context.class_table.psalm\\internal\\provider\\fileprovider.static_properties.open 72415 | 59264 | context.class_table.psalm\\internal\\provider\\fileprovider.static_properties.open 37639 | 59200 | context.class_table.psalm\\internal\\provider\\fileprovider.static_properties.open 34919 | 59160 | context.class_table.psalm\\internal\\provider\\fileprovider.static_properties.open 32192 | 58802 | context.class_table.psalm\\internal\\provider\\fileprovider.static_properties.open 26572 | 59044 | context.class_table.psalm\\internal\\provider\\fileprovider.static_properties.open 26459 | 59154 | context.class_table.psalm\\internal\\provider\\fileprovider.static_properties.open 26336 | 58754 | context.class_table.psalm\\internal\\provider\\fileprovider.static_properties.open
39. サイズの大きな配列を参照元付きでランキング表示する例 cat memory_analyzed.json | jq '. as $root | path(..|objects|select(."#type"=="ArrayHeaderContext"))| . size | count | node_id | path ==== | ===== | ======= | ==== 319520 | 7937 | 42380 | context.class_table.jetbrains\\phpstormstub\\phpstormstubsmap.constants.CONS 222944 | 4919 | 27618 | context.class_table.jetbrains\\phpstormstub\\phpstormstubsmap.constants.FUNC 203616 | 3917 | 82513 | context.interned_strings 59424 | 1345 | 23577 | context.class_table.jetbrains\\phpstormstub\\phpstormstubsmap.constants.CLAS 54944 | 1205 | 19586 | context.class_table.composerautoloaderinitfa3d2d2c0bbb9c2389347803a32247de.s 1984 | 46 | 19254 | context.class_table.composerautoloaderinitfa3d2d2c0bbb9c2389347803a32247de.s 1248 | 31 | 23472 | context.class_table.composer\\autoload\\composerstaticinitfa3d2d2c0bbb9c2389 1248 | 31 | 1845 | context.call_frames.25.symbol_table.array_elements.__composer_autoload_files 1216 | 30 | 1754 | context.call_frames.25.symbol_table.array_elements._SERVER.value 800 | 17 | 620 | context.call_frames.7.local_variables.container.object_properties.fetchedDef
40. あるオブジェクトの参照元をすべて列挙する例 cat memory_analized.json | jq 'path(..|objects|select(."#reference_node_id"==3 or ."#node_id"==3))|join "context.call_frames.0.local_variables.project_analyzer" "context.call_frames.1.local_variables.project_analyzer" "context.class_table.psalm\\internal\\analyzer\\projectanalyzer.static_properties.instance" "context.objects_store.17"
41. コールトレースの取得 cat memory_analyzed.json | jq -r '(["frame_no", "function", "line"] | (., map(length*"="))),(path(.cont frame_no function line ======== ======== ==== 0 system 4 1 {closure}(/home/sji/work/oss/tmp/pdfparser_test/test.php:11-21) 20 2 Smalot\\PdfParser\\Font::uchr 150 3 Smalot\\PdfParser\\Font::loadTranslateTable 230 4 Smalot\\PdfParser\\Font::init 78 5 Smalot\\PdfParser\\Document::init 90 6 Smalot\\PdfParser\\Document::setObjects 316 7 Smalot\\PdfParser\\Parser::parseContent 122 8 Smalot\\PdfParser\\Parser::parseFile 90 9 <main>
42. 特定のコールフレームの 特定のローカル変数の値を出力する例 cat memory_analyzed.json | jq '.context.call_frames."1".local_variables|{abc, def}' { "abc": { "#node_id": 142, "#type": "ScalarValueContext", "#value": 506895433343375 }, "def": { "#node_id": 143, "#type": "ScalarValueContext", "#value": 9958150 } }
43. コアダンプからの読み取り Reli のメモリ解析機能はコアダンプの読み取りにも対応 プロセス死亡時の PHP レベルでの状況を詳しく調べられる gdb も処理系のデバッグシンボルもいらない 生きてるプロセスも gcore でごく短い間止めるだけで解析できる コアダンプ取得の時間しか要らない 生きてるプロセスの直接のメモリ解析は時間がかかり、プロダクションで使い辛い コアだけ吐いておけば後でじっくり根本原因を（現実的な手間の範囲で）追える トラブル対応でプロセスの再起動など急場しのぎの対応が要る場合も状況を保存できる その場にいない詳しい人が後で調べる、も可能
44. 仕組み
45. ざっくりの概観 対象プロセスの重要構造体のアドレスを特定 処理系の ELF バイナリと procfs のメモリマップを解析 FFI でシステムコールを呼び別プロセスの処理系内のメモリを読む gdb などのデバッガと同じようなことをやる 処理系内部のメモリレイアウトの知識を持って内部情報を解釈 FFI で処理系内の C 構造体定義を読み込む ポインタをたどり実行中の関数・VM命令のトレースやメモリ内容を収集
46. 将来の展望 スレッドセーフ版処理系への対応度を上げる トレース取得のついででスポットでのメモリ解析を可能に より多くの状況で安定して動くように 高速化・省メモリ化 エラーや例外の発生時にのみ情報を取る機能 SQL でのプロセス状態のクエリ 別サーバへ取得した情報を集約可能に チュートリアルの拡充
47. おしまい