パフォーマンスを改善せよ！大規模システム改修の仕事の進め方 / Improve performance with Big project for PHPerKaigi 2023

『パフォーマンスを改善せよ！』突如下された指令...あなたはこのミッションをクリアしなくてはなりません。
しかし、「方法論を知っていても実施困難」「改善効果が測りにくい」「予測を立てづらい」などの様々な課題を抱えているのが実情です。
では、効率的に確実にこのミッションを遂行するにはどうすればよいのか？

すぱらしいソフトウェアのお医者さん、ロブ・パイクは言いました。「推測するな、計測せよ。」　なんかかっこいい。

このトークでは、この格言の通りにパフォーマンス改善に挑んだ実話を基に「効率的な正しいアプローチ」「パフォーマンス改善方法」をご紹介させてもらいます。

■話さない内容
・詳細なツールの使い方
・解析結果の読み方

■主な内容

・パフォーマンス改善方法の紹介
・パフォーマンス改善業務の進め方
・パフォーマンス改善の失敗談

Transcript

1. #phperkaigi ©2023 RAKUS Co., Ltd. パフォーマンスを改善せよ！ 大規模システム改修の仕事の進め方 2023/03/24 PHPerKaigi 2023 前田啓佑
2. #phperkaigi 自己紹介 2
3. #phperkaigi 前田啓佑（まえだけいすけ） 年齢 ３５ 出身 大阪府 職歴 〜6年 動画配信やLIVE配信のサーバーサイドエンジニア
 iOS / Android / VRアプリ 色々 〜９年 SIer(防災）　インフラ側の調整とか 〜現在 サーバーサイドエンジニア　[株式会社ラクス] 趣味 ゲームつくる・やる 3 @taclose
4. #phperkaigi パフォーマンス改善やってますか？ 4
5. #phperkaigi このセッションについて 5 効率よく進めるに はどうしたらいい の？ 効率的な正しいアプローチ方法 をご紹介します！ パフォーマンス 改善ってどう進 めたらいいの？
6. #phperkaigi もう一度言います 6
7. #phperkaigi 7 効率的な正しいアプローチ方法 をご紹介します！ 改善手法 進め方 詳細なやり方は後回し ＜
8. #phperkaigi 体験談の前に 8
9. #phperkaigi 私の担当するサービス 9
   顧客毎にカスタマイズ可能な汎用データベースシステム ◦ テーブルの追加やフィールドの追加が可能 ◦ 絞り込み条件や並び替え条件が指定可能 ◦ フリーワード検索や関連テーブルの設定なんかもある
   初コミットされてから15年が経ちます パフォーマンス改善が難しい！ パフォーマンス改善が難しい！
10. #phperkaigi 私の担当するサービス 10 一覧画面は何個でも作成可能 ※RDBでいうViewに相当 動的に複雑な検索条件が可能 ※RDBでいうWHERE 表示情報もカスタマイズ可能
11. #phperkaigi 私の担当するサービス 11 internet User Hub DC Server … … Server キャッシュ データ PostgreSQL メール連携 パフォーマンス改善が難しい！
12. #phperkaigi 突如下された指令！！ 12
13. #phperkaigi 一覧画面を１５％速度改善せよ！ 13 〜1秒 922画面 3秒〜 32画面 MISSION①　全体で平均して１５％改善！ MISSION② ユーザが体感しやすいここも１５％改善！ 現在の表示速度でグループ分け 1秒〜3秒 321画面 ※全部で1275画面
14. #phperkaigi 一覧画面を１５％速度改善せよ！ 14 〜1秒 922画面 3秒〜 32画面 MISSION①　全体で平均して１５％改善！ MISSION② ユーザが体感しやすいここも１５％改善！ 現在の表示速度でグループ分け 1秒〜3秒 321画面 ※全部で1275画面
15. #phperkaigi 改善計画 15
16. #phperkaigi 16 計測 ボトルネック特定 改善・効果測定 改善成功 改善せよ！ 改善計画 推測するな、計測せよ！（ルール１参照） 「ボトルネックは予想外な場所にあるので、どこがボトルネックなの かをはっきりさせるまでは、推測を行ったり、スピードハックをして はならない。」 (by ロブ・パイク）
17. #phperkaigi パフォーマンス改善 - Take1 17 Take1の失敗は Take2で改善するよ！
18. #phperkaigi Take1 - 計測 18
19. #phperkaigi Take1 - 計測の段取り 19 • 1275画面全て計測するのは非効率だよなぁ... • そういえば、SlowQuery出てる画面あった な…そこ改善したら全体的にいけるんじゃ？ 段取りはこうしよう！ ①SlowQueryが出てる画面を見つける ②SlowQueryの原因を解決する
20. #phperkaigi
    SlowQueryが出てる画面を見つけよう！ Take1 - 計測 20 • 最遅は約63秒 • 3秒を超えた画面は32画面 • JMeterは基礎中の基礎！
21. #phperkaigi Take1 - 計測 21 SlowQueryを確認 SELECT data_xxx, data_xxx, .....
 FROM record_xxx LEFT JOIN record_xxx "xxx-xxx:xxx"
 ON ( record_xxx.data_xxx = "xxx-xxx:xxx".data_xxx) ....
 WHERE record_xxxxxx.fix_flag = xxxxxx
 AND ((((CASE WHEN LENGTH(CAST(data_xxx AS text)) = xxx THEN NULL 
 ELSE ... ORDER BY data_xxx DESC,record_xxx.id DESC LIMIT 101 • 脅威の8000文字超え ※１クエリーです。 名誉のために補足しておきますが、技術不足ではないんです！ あの複雑な一覧画面のSQLを動的に生成するには仕方ない
22. #phperkaigi Take1 - 計測 22
    SlowQueryの実行計画を確認 • PostgreSQLは壮絶な計画を 考えてらっしゃる。 拡大 • JOIN FILTERで4000万行削除 • 悪い所はわかった！ • EXPLAIN ANALYZEは基本！ • ボトルネックの特定完了！
23. #phperkaigi Take1 - 改善 23
24. #phperkaigi Take1 - 改善 24
    SQLチューニング ◦ 不要なJOINを削る ◦ サブクエリ化されている所をEXISTSに置き換える ◦ WHERE条件を最適化
    PostgreSQL ◦ version UP(12→14) ◦ 設定変更やパラレルクエリ • 他SQLチューニングは可能な限り実施 • 改修リスクや工数見合いで一部断念した ものもあった。 • モノリスなサーバ構成であるため、 思ったようなチューニングは出来な いと判断した。
25. #phperkaigi Take1 - 結果 25
26. #phperkaigi Take1 - 結果 26 この線より下＝改善した 修正後の処理時間（ミリ秒) 修正前の処理時間（ミリ秒） 60秒以上かかってたけど、数秒まで改善！ • 全体で16.28%改善 MISSION① 達成
27. #phperkaigi Take1 - 結果 27 修正後の処理時間（ミリ秒） 修正前の処理時間（ミリ秒） ０〜５秒を拡大表示 • １〜３秒の対象で6.1%改善 MISSION②未達 改善の対象 PostgreSQL ver upや、一覧取得の SQLチューニングはこの対象には 効果が薄かったようです。
28. #phperkaigi どうすりゃ良かったの！ 28
29. #phperkaigi Take1 - 結果 29 修正後の処理時間（ミリ 秒） 修正前の処理時間（ミリ 秒） ０〜５秒を拡大表示 改善の対象 PostgreSQL ver upや、一覧取得の SQLチューニングはこの対象には 効果が薄かったようです。 • これって推測じゃないか！ • 計測されてない！
30. #phperkaigi Take1 - 計測の段取り 30 • 1275画面全て計測するのは非効率だ よなぁ... • そういえば、SlowQuery出てる画面 あったな...そこ改善したらいけるん じゃ？ 段取りはこうしよう！ ①SlowQueryが出てる画面を見つける ②SlowQueryの原因を解決する 段取り考えてる時、既に推測が先行して、 １〜３秒帯の画面を無視してた。
31. #phperkaigi Take1 - どうすりゃ良かったの！ 31 〜1秒 922画面 3秒〜 32画面 1秒〜3秒 321画面 Take2では、ここがなぜ遅いのか？ ちゃんと計測して改善しよう！ Take1では、 このSlowQueryにだけ着目した 解決したい課題を包括するような計測 • を行わなければならない。
32. #phperkaigi パフォーマンス改善 - Take2 32
33. #phperkaigi Take2 - 計測 33 リベンジ！ 推測するな、計測せよ！(by ロブ・パイク）
34. #phperkaigi Take2 - 計測（プロファイリング） 34 プロファイリングとは？ 品質的特徴を明らかにする作業 ※今回の例なら処理に時間がかかってる場所を明らかにする作業です。 QCacheGrind + プロファイ リング プロファイリングを使えば、PHPの メソッド単位でどこが遅いのかが丸 わかり！ ※QCacheGrindを使って表示した例
35. #phperkaigi Take2 - 計測 プロファイル結果を確認 35
36. #phperkaigi Take2 - 計測（プロファイル結果） 36 [対象の画面] 　表示時間：18秒 　一覧取得のSQLがSlowQuery 94%が一覧取得のSQLが原因
37. #phperkaigi Take2 - 計測（プロファイル結果） 37 [対象の画面] 　表示時間：1.2秒 ③DBへの問い合わせ処理が117回！ →ここも何か無駄な事をやってそう ①一覧取得のSQL（4.96%） →Take1で処理時間１〜３秒を対象とした改 善が未達に終わった理由はこれ ②一覧取得のSQLに対して、 　その他のSQLが40%以上を占めている →ここにボトルネックがありそう
38. #phperkaigi Take2 - 計測（プロファイル結果） 38 その他クエリー（40%) 一覧取得のクエリー（5%） その他処理（55%) ボトルネックがありそうな所はココ 仮説「無駄なSQL呼び出しがありそう」 仮説「遅いSQLがありそう」 つまり、処理時間１〜３秒の画面の内訳は？
39. #phperkaigi Take2 - 計測 実行されたSQLを調査 39 その他クエリー（40%) ここに更にフォーカスして計測していきます。
40. #phperkaigi デバッグ＆実行計画 Take2 - 計測（実行されたSQLを調査） 40 [調査結果] • テーブル毎に以下をまとめました ◦ 問い合わせ回数(call数) ◦ 合計の処理時間(合計時間) ◦ 全体で何％を占めるか(全体％) ※実際テーブル数は30以上あります。（これは一部） call: 14069回 その他クエリー全体の55%!! access_info • プロセス内キャッシュに不具合を発見 • INDEX見直しが必要 • SQLチューニング必要
41. #phperkaigi その他のテーブルについても 同様に調査を実施しました。 41 その他クエリー（全体の40%） 他のテーブルも同じような不具合あるんじゃ ないの？改善の余地あるのでは？ 調査したがここは割愛します。 access_info（55%) その他のテーブル（45%）
42. #phperkaigi Take2 - 改善 最終的に実施した改善内 42
43. #phperkaigi Take2 - 改善 43
    SQLチューニング（一覧取得ではないSQL） ◦ 最適なINDEXを追加する（複数列INDEX） ◦ 不要なORDER句を削除等
    プロセス内キャッシュで不要なSQL処理を抑止する 10倍以上早くなるテーブルがたくさん！ SQL実行回数が激減！
44. #phperkaigi Take2 - 結果 （効果測定！） 44
45. #phperkaigi Take2 - 結果 45 その他クエリー（40%) 一覧取得のクエリー（5%） その他処理（55%) 改善 ※（１〜３秒帯の）全画面でプロファイリングした訳ではないので参考値です 一覧取得のクエリー（5%） その他クエリー（19%） その他処理（52%） 改善（24%）
46. #phperkaigi Take2 - 結果 46 グラフからは読み取りにくい （ミリ秒) （ミリ 秒） • 全体で24.2%改善 MISSION① 達成
47. #phperkaigi Take2 - 結果 47 5秒未満は確かに大きく改善！ 全画面がほぼ均一して0.25秒の改善し た結果となりました。 • １〜３秒の対象で24.3%改善 MISSION② 達成 （ミリ秒) （ミリ 秒）
48. #phperkaigi まとめ 48
49. #phperkaigi まとめ 49
    パフォーマンス改善の作法 ◦ 推測するな、計測せよ！ ◦ 解決したい課題を包括するように計測せよ！ ◦ 憶測や経験則で動くな（特に中堅）、計測せよ！
    効率的に進めるために ◦ 改善効果が一番大きい場所を見つけよ（計測せよ！） ◦ 遅い場所を知っていてもちゃんと計測せよ！（手戻り防止） ◦ 改善を実施したら効果測定せよ（計測せよ！）
50. #phperkaigi 技術的な話 （蛇足な話・省略した話） 50
51. #phperkaigi 汎用的 改善方法は幅広く知っておきましょう 51 インフラ プロファイリング スケールアウト スケールアップ オートスケール ラウンドロビン ラウンドロビン キャッシュ スループット レイテンシー ミドルウェア アプリケーション SQLチューニング PostgreSQLのチューニング PostgreSQLのINDEX見直し Apacheのチューニング 冗長化 リードレプリカ CDN PostgreSQLの統計情報 PHPのOPcache PHPのOPcache プロセス内キャッシュ KVSへのキャッシュ ローダの表示（体感） パフォーマンス改善に関係する言葉 　パフォーマンス改善方法にどんなものがあるのか？を知らないと、遅い 場所を見つけても「ここは時間がかかるのは仕方がない」で終わってしま います。なので、パフォーマンス改善について浅くても良いので広く知見 を持って挑んでほしいです。
52. #phperkaigi プロファイリング 52 Profile結果の出力方法 プロファイリングとは？ 品質的特徴を明らかにする作業 ※今回の例なら処理に時間がかかってる場所を明らかにする作業です。 zend_extension=/path/to/extension/xdebug.so xdebug.mode=profile xdebug.trace_format=0 xdebug.output_dir=/output/dir xdebug.start_with_request=yes xdebug.profiler_output_name = callgrind.out.%p [php.ini] PHPのプロファイル結果を出力するのには XDebugのprofileモードを利用します。
53. #phperkaigi プロファイリング 53 列名 内容 Function メソッド名 Incl. 該当メソッドが内部で実行したメソッド内の処理も含めた処理時間の占める割合 Self 該当メソッドが内部で実行したメソッド内の処理を含めない処理時間の占める割合 ※Self降順もしくはIncl.降順に並べるとボトルネックを見つけやすい Called 該当メソッドが実行された回数 QCacheGrind（Qキャッシュグラインド）の使い方
54. #phperkaigi プロファイリング 54 QCacheGrind（Qキャッシュグラインド）の使い方 該当メソッドがどこから何回呼ばれ たかがわかる 該当メソッドのIncl.値 注意：この図に全て表示する事は出来ないため、Incl.値で閾値が 設定されている。（Default:1%) このグラフだと14回しか呼ばれていないように見えるが、実際 には102回呼ばれています。 CLICK!!
55. #phperkaigi プロファイリング 55 PHPStormにもプロファイル結果を確認できる機能が用意されています。 PHPStormをお使いの方はこんな感じで見る 事も出来ます。参考までに！
56. #phperkaigi PostgreSQLで実行されたSQLの取得のコツ 56 log_destination = 'csvlog' logging_collector = on log_min_duration_statement = 0 [postgresql.conf] 実行された全SQLを調査するため、JMeterを走らせる前にPostgreSQL のログ出力の設定を変更。 ※PostgreSQL ver15からはjsonlogも指定可能 実行されたSQLとその処理時間が全て吐き出されるので、解析すれば 色々わかる。 今回はこのログを解析して各テーブルの合計処理時間とかを計算し たが、PostgreSQL15からはjsonフォーマットも増えました。 ミドルウェアのログ出力を変えると解析がグッと楽になるので、 Apacheとかも是非設定見直して下さい。
57. #phperkaigi OPcache 57 [opcache] zend_extension=/path/to/extension/opcache.so opcache.enable = 1 opcache.jit_buffer_size = 256M opcache.memory_consumption=128 opcache.interned_strings_buffer=8 opcache.max_accelerated_files=15000 opcache.revalidate_freq=0 opcache.enable_cli=1 opcache.validate_timestamps=0 [php.ini]　設定例 OPcacheとは？ PHPスクリプトをオペコードにコンパイルした結果をキャッシュしておく事で、 クラスのロードを高速化する事が出来ます ※今回はOPcacheのpreload機能までは利用していません。
58. #phperkaigi コンパイル コンパイル コンパイル ロード ロード ロード OPcache 58 index.phpにアクセス includeされたphp includeされたphp includeされたphp includeされたphp includeされたphp 中間コード(OPCode) プログラムの実行 OPcache無し ロード ロード ロード index.phpにアクセス includeされたphp includeされたphp 中間コード(OPCode) プログラムの実行 OPcache有り OPcache有り（preload有り） OPcode作成済み index.phpにアクセス プログラムの実行 OPcode作成済み 共有メモリにロード済み 高速化される処理はspl_autoload_register()メソッドを呼ぶ処理です。 OPcache無しでプロファイリングすると、その負荷を見る事が出来ますよ！
59. #phperkaigi 付録 59 OPcacheのPreloadの改善効果と手順 ◦ https://tech-blog.rakus.co.jp/entry/20230323/php OPcacheのPreloadについてのやり方をブログに昨日書いておきました。 詳細はこちらをみてください。 ※preloadがうまくできない！という人に対する追加記事は後日書く予定！
60. #phperkaigi ご清聴ありがとうございました 60