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

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

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

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

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

■主な内容

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

Transcript

1. #phperkaigi
   ©2023 RAKUS Co., Ltd.
   パフォーマンスを改善せよ！
   大規模システム改修の仕事の進め方
   2023/03/24 PHPerKaigi 2023
   前田啓佑
   

   View Slide

2. #phperkaigi
   自己紹介
   2
   

   View Slide

3. #phperkaigi
   前田啓佑（まえだけいすけ）
   年齢 ３５
   出身 大阪府
   職歴 〜6年 動画配信やLIVE配信のサーバーサイドエンジニア

   iOS / Android / VRアプリ 色々
   〜９年 SIer(防災）　インフラ側の調整とか
   〜現在 サーバーサイドエンジニア　[株式会社ラクス]
   趣味 ゲームつくる・やる
   3
   @taclose
   

   View Slide

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

   View Slide

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

   View Slide

6. #phperkaigi
   もう一度言います
   6
   

   View Slide

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

   View Slide

8. #phperkaigi
   体験談の前に
   8
   

   View Slide

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

   View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

15. #phperkaigi
    改善計画
    15
    

    View Slide

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

    View Slide

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

    View Slide

18. #phperkaigi
    Take1 - 計測
    18
    

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

23. #phperkaigi
    Take1 - 改善
    23
    

    View Slide

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

    View Slide

25. #phperkaigi
    Take1 - 結果
    25
    

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

48. #phperkaigi
    まとめ
    48
    

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide

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

    View Slide