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

by 前田啓佑

Slide 1

Slide 1 text

Slide 2

Slide 2 text

#phperkaigi 自己紹介 2

Slide 3

Slide 3 text

#phperkaigi 前田啓佑（まえだけいすけ）年齢３５出身大阪府職歴〜6年動画配信やLIVE配信のサーバーサイドエンジニア  iOS / Android / VRアプリ色々〜９年 SIer(防災）　インフラ側の調整とか〜現在サーバーサイドエンジニア　[株式会社ラクス] 趣味ゲームつくる・やる 3 @taclose

Slide 4

Slide 4 text

#phperkaigi パフォーマンス改善やってますか？ 4

Slide 5

Slide 5 text

#phperkaigi このセッションについて 5 効率よく進めるにはどうしたらいいの？効率的な正しいアプローチ方法をご紹介します！パフォーマンス改善ってどう進めたらいいの？

Slide 6

Slide 6 text

#phperkaigi もう一度言います 6

Slide 7

Slide 7 text

#phperkaigi 7 効率的な正しいアプローチ方法をご紹介します！改善手法進め方詳細なやり方は後回し＜

Slide 8

Slide 8 text

#phperkaigi 体験談の前に 8

Slide 9

Slide 9 text

#phperkaigi 私の担当するサービス 9 顧客毎にカスタマイズ可能な汎用データベースシステム ○ テーブルの追加やフィールドの追加が可能 ○ 絞り込み条件や並び替え条件が指定可能 ○ フリーワード検索や関連テーブルの設定なんかもある初コミットされてから15年が経ちますパフォーマンス改善が難しい！パフォーマンス改善が難しい！

Slide 10

Slide 10 text

#phperkaigi 私の担当するサービス 10 一覧画面は何個でも作成可能 ※RDBでいうViewに相当動的に複雑な検索条件が可能 ※RDBでいうWHERE 表示情報もカスタマイズ可能

Slide 11

Slide 11 text

#phperkaigi 私の担当するサービス 11 internet User Hub DC Server … … Server キャッシュデータ PostgreSQL メール連携パフォーマンス改善が難しい！

Slide 12

Slide 12 text

#phperkaigi 突如下された指令！！ 12

Slide 13

Slide 13 text

#phperkaigi 一覧画面を１５％速度改善せよ！ 13 〜1秒 922画面 3秒〜 32画面 MISSION①　全体で平均して１５％改善！ MISSION② ユーザが体感しやすいここも１５％改善！現在の表示速度でグループ分け 1秒〜3秒 321画面 ※全部で1275画面

Slide 14

Slide 14 text

#phperkaigi 一覧画面を１５％速度改善せよ！ 14 〜1秒 922画面 3秒〜 32画面 MISSION①　全体で平均して１５％改善！ MISSION② ユーザが体感しやすいここも１５％改善！現在の表示速度でグループ分け 1秒〜3秒 321画面 ※全部で1275画面

Slide 15

Slide 15 text

#phperkaigi 改善計画 15

Slide 16

Slide 16 text

#phperkaigi 16 計測ボトルネック特定改善・効果測定改善成功改善せよ！改善計画推測するな、計測せよ！（ルール１参照）「ボトルネックは予想外な場所にあるので、どこがボトルネックなのかをはっきりさせるまでは、推測を行ったり、スピードハックをしてはならない。」 (by ロブ・パイク）

Slide 17

Slide 17 text

#phperkaigi パフォーマンス改善 - Take1 17 Take1の失敗は Take2で改善するよ！

Slide 18

Slide 18 text

#phperkaigi Take1 - 計測 18

Slide 19

Slide 19 text

#phperkaigi Take1 - 計測の段取り 19 ● 1275画面全て計測するのは非効率だよなぁ... ● そういえば、SlowQuery出てる画面あったな…そこ改善したら全体的にいけるんじゃ？段取りはこうしよう！ ①SlowQueryが出てる画面を見つける ②SlowQueryの原因を解決する

Slide 20

Slide 20 text

#phperkaigi SlowQueryが出てる画面を見つけよう！ Take1 - 計測 20 ● 最遅は約63秒 ● 3秒を超えた画面は32画面 ● JMeterは基礎中の基礎！

Slide 21

Slide 21 text

#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を動的に生成するには仕方ない

Slide 22

Slide 22 text

#phperkaigi Take1 - 計測 22 SlowQueryの実行計画を確認 ● PostgreSQLは壮絶な計画を考えてらっしゃる。拡大 ● JOIN FILTERで4000万行削除 ● 悪い所はわかった！ ● EXPLAIN ANALYZEは基本！ ● ボトルネックの特定完了！

Slide 23

Slide 23 text

#phperkaigi Take1 - 改善 23

Slide 24

Slide 24 text

#phperkaigi Take1 - 改善 24 SQLチューニング ○ 不要なJOINを削る ○ サブクエリ化されている所をEXISTSに置き換える ○ WHERE条件を最適化 PostgreSQL ○ version UP(12→14) ○ 設定変更やパラレルクエリ ● 他SQLチューニングは可能な限り実施 ● 改修リスクや工数見合いで一部断念したものもあった。 ● モノリスなサーバ構成であるため、思ったようなチューニングは出来ないと判断した。

Slide 25

Slide 25 text

#phperkaigi Take1 - 結果 25

Slide 26

Slide 26 text

#phperkaigi Take1 - 結果 26 この線より下＝改善した修正後の処理時間（ミリ秒) 修正前の処理時間（ミリ秒） 60秒以上かかってたけど、数秒まで改善！ ● 全体で16.28%改善 MISSION① 達成

Slide 27

Slide 27 text

#phperkaigi Take1 - 結果 27 修正後の処理時間（ミリ秒）修正前の処理時間（ミリ秒）０〜５秒を拡大表示 ● １〜３秒の対象で6.1%改善 MISSION②未達改善の対象 PostgreSQL ver upや、一覧取得の SQLチューニングはこの対象には効果が薄かったようです。

Slide 28

Slide 28 text

#phperkaigi どうすりゃ良かったの！ 28

Slide 29

Slide 29 text

#phperkaigi Take1 - 結果 29 修正後の処理時間（ミリ秒）修正前の処理時間（ミリ秒）０〜５秒を拡大表示改善の対象 PostgreSQL ver upや、一覧取得の SQLチューニングはこの対象には効果が薄かったようです。 ● これって推測じゃないか！ ● 計測されてない！

Slide 30

Slide 30 text

#phperkaigi Take1 - 計測の段取り 30 ● 1275画面全て計測するのは非効率だよなぁ... ● そういえば、SlowQuery出てる画面あったな...そこ改善したらいけるんじゃ？段取りはこうしよう！ ①SlowQueryが出てる画面を見つける ②SlowQueryの原因を解決する段取り考えてる時、既に推測が先行して、１〜３秒帯の画面を無視してた。

Slide 31

Slide 31 text

#phperkaigi Take1 - どうすりゃ良かったの！ 31 〜1秒 922画面 3秒〜 32画面 1秒〜3秒 321画面 Take2では、ここがなぜ遅いのか？ちゃんと計測して改善しよう！ Take1では、このSlowQueryにだけ着目した解決したい課題を包括するような計測 ● を行わなければならない。

Slide 32

Slide 32 text

#phperkaigi パフォーマンス改善 - Take2 32

Slide 33

Slide 33 text

#phperkaigi Take2 - 計測 33 リベンジ！推測するな、計測せよ！(by ロブ・パイク）

Slide 34

Slide 34 text

#phperkaigi Take2 - 計測（プロファイリング） 34 プロファイリングとは？品質的特徴を明らかにする作業 ※今回の例なら処理に時間がかかってる場所を明らかにする作業です。 QCacheGrind + プロファイリングプロファイリングを使えば、PHPのメソッド単位でどこが遅いのかが丸わかり！ ※QCacheGrindを使って表示した例

Slide 35

Slide 35 text

#phperkaigi Take2 - 計測プロファイル結果を確認 35

Slide 36

Slide 36 text

#phperkaigi Take2 - 計測（プロファイル結果） 36 [対象の画面] 　表示時間：18秒　一覧取得のSQLがSlowQuery 94%が一覧取得のSQLが原因

Slide 37

Slide 37 text

#phperkaigi Take2 - 計測（プロファイル結果） 37 [対象の画面] 　表示時間：1.2秒 ③DBへの問い合わせ処理が117回！ →ここも何か無駄な事をやってそう ①一覧取得のSQL（4.96%） →Take1で処理時間１〜３秒を対象とした改善が未達に終わった理由はこれ ②一覧取得のSQLに対して、　その他のSQLが40%以上を占めている →ここにボトルネックがありそう

Slide 38

Slide 38 text

#phperkaigi Take2 - 計測（プロファイル結果） 38 その他クエリー（40%) 一覧取得のクエリー（5%）その他処理（55%) ボトルネックがありそうな所はココ仮説「無駄なSQL呼び出しがありそう」仮説「遅いSQLがありそう」つまり、処理時間１〜３秒の画面の内訳は？

Slide 39

Slide 39 text

#phperkaigi Take2 - 計測実行されたSQLを調査 39 その他クエリー（40%) ここに更にフォーカスして計測していきます。

Slide 40

Slide 40 text

#phperkaigi デバッグ＆実行計画 Take2 - 計測（実行されたSQLを調査） 40 [調査結果] ● テーブル毎に以下をまとめました ○ 問い合わせ回数(call数) ○ 合計の処理時間(合計時間) ○ 全体で何％を占めるか(全体％) ※実際テーブル数は30以上あります。（これは一部） call: 14069回その他クエリー全体の55%!! access_info ● プロセス内キャッシュに不具合を発見 ● INDEX見直しが必要 ● SQLチューニング必要

Slide 41

Slide 41 text

#phperkaigi その他のテーブルについても同様に調査を実施しました。 41 その他クエリー（全体の40%）他のテーブルも同じような不具合あるんじゃないの？改善の余地あるのでは？調査したがここは割愛します。 access_info（55%) その他のテーブル（45%）

Slide 42

Slide 42 text

#phperkaigi Take2 - 改善最終的に実施した改善内 42

Slide 43

Slide 43 text

#phperkaigi Take2 - 改善 43 SQLチューニング（一覧取得ではないSQL） ○ 最適なINDEXを追加する（複数列INDEX） ○ 不要なORDER句を削除等プロセス内キャッシュで不要なSQL処理を抑止する 10倍以上早くなるテーブルがたくさん！ SQL実行回数が激減！

Slide 44

Slide 44 text

#phperkaigi Take2 - 結果（効果測定！） 44

Slide 45

Slide 45 text

#phperkaigi Take2 - 結果 45 その他クエリー（40%) 一覧取得のクエリー（5%）その他処理（55%) 改善 ※（１〜３秒帯の）全画面でプロファイリングした訳ではないので参考値です一覧取得のクエリー（5%）その他クエリー（19%）その他処理（52%）改善（24%）

Slide 46

Slide 46 text

#phperkaigi Take2 - 結果 46 グラフからは読み取りにくい（ミリ秒) （ミリ秒） ● 全体で24.2%改善 MISSION① 達成

Slide 47

Slide 47 text

#phperkaigi Take2 - 結果 47 5秒未満は確かに大きく改善！全画面がほぼ均一して0.25秒の改善した結果となりました。 ● １〜３秒の対象で24.3%改善 MISSION② 達成（ミリ秒) （ミリ秒）

Slide 48

Slide 48 text

#phperkaigi まとめ 48

Slide 49

Slide 49 text

#phperkaigi まとめ 49 パフォーマンス改善の作法 ○ 推測するな、計測せよ！ ○ 解決したい課題を包括するように計測せよ！ ○ 憶測や経験則で動くな（特に中堅）、計測せよ！効率的に進めるために ○ 改善効果が一番大きい場所を見つけよ（計測せよ！） ○ 遅い場所を知っていてもちゃんと計測せよ！（手戻り防止） ○ 改善を実施したら効果測定せよ（計測せよ！）

Slide 50

Slide 50 text

#phperkaigi 技術的な話（蛇足な話・省略した話） 50

Slide 51

Slide 51 text

#phperkaigi 汎用的改善方法は幅広く知っておきましょう 51 インフラプロファイリングスケールアウトスケールアップオートスケールラウンドロビンラウンドロビンキャッシュスループットレイテンシーミドルウェアアプリケーション SQLチューニング PostgreSQLのチューニング PostgreSQLのINDEX見直し Apacheのチューニング冗長化リードレプリカ CDN PostgreSQLの統計情報 PHPのOPcache PHPのOPcache プロセス内キャッシュ KVSへのキャッシュローダの表示（体感）パフォーマンス改善に関係する言葉　パフォーマンス改善方法にどんなものがあるのか？を知らないと、遅い場所を見つけても「ここは時間がかかるのは仕方がない」で終わってしまいます。なので、パフォーマンス改善について浅くても良いので広く知見を持って挑んでほしいです。

Slide 52

Slide 52 text

#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モードを利用します。

Slide 53

Slide 53 text

#phperkaigi プロファイリング 53 列名内容 Function メソッド名 Incl. 該当メソッドが内部で実行したメソッド内の処理も含めた処理時間の占める割合 Self 該当メソッドが内部で実行したメソッド内の処理を含めない処理時間の占める割合 ※Self降順もしくはIncl.降順に並べるとボトルネックを見つけやすい Called 該当メソッドが実行された回数 QCacheGrind（Qキャッシュグラインド）の使い方

Slide 54

Slide 54 text

#phperkaigi プロファイリング 54 QCacheGrind（Qキャッシュグラインド）の使い方該当メソッドがどこから何回呼ばれたかがわかる該当メソッドのIncl.値注意：この図に全て表示する事は出来ないため、Incl.値で閾値が設定されている。（Default:1%) このグラフだと14回しか呼ばれていないように見えるが、実際には102回呼ばれています。 CLICK!!

Slide 55

Slide 55 text

#phperkaigi プロファイリング 55 PHPStormにもプロファイル結果を確認できる機能が用意されています。 PHPStormをお使いの方はこんな感じで見る事も出来ます。参考までに！

Slide 56

Slide 56 text

#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とかも是非設定見直して下さい。

Slide 57

Slide 57 text

#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機能までは利用していません。

Slide 58

Slide 58 text

#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無しでプロファイリングすると、その負荷を見る事が出来ますよ！

Slide 59

Slide 59 text

#phperkaigi 付録 59 OPcacheのPreloadの改善効果と手順 ○ https://tech-blog.rakus.co.jp/entry/20230323/php OPcacheのPreloadについてのやり方をブログに昨日書いておきました。詳細はこちらをみてください。 ※preloadがうまくできない！という人に対する追加記事は後日書く予定！

Slide 60

Slide 60 text

#phperkaigi ご清聴ありがとうございました 60