Webパフォーマンス改善ハンズオン

2023/9月に社内で実施したWebパフォーマンス改善ハンズオンのスライド資料になります。

Transcript

1. WEB パフォーマンス改善 ハンズオン
2. 本ハンズオンの目的 本を読んでも分かった気になっちゃう。 手を動かして経験してみよう！ 学ぶこと • パフォーマンス改善の進め方 • パフォーマンス改善の方法 ◦ nginx ◦ MySQL ◦ Linux(Ubuntu) ※ApacheやPostgreSQLに知識の流用は可能
3. アジェンダ １日目 • 各種環境ログイン • 座学①：モニタリング • モニタリング準備（ハンズオン） ◦ 各種ツールの説明 ◦ 各種インストール手順等 • 座学②：パフォーマンス改善 • パフォーマンス改善（ハンズオン） ◦ 計測してみる ◦ 改善してみる ◦ ベンチマークサーバ使ってみる • 付録：その他改善まとめ ２日目 • ハンズオン（１時間） ◦ 各自private-isuの改善を行う • 結果発表（１５分） ◦ 全チームのスコアを計測！ • 感想（１５分）
4. 準備作業 ハンズオンで利用する環境へのログイン方法について説明します。 お手元のターミナルソフトにて、鍵認証方式にてハンズオン環境にSSH接続してください。 以下、”RLogin”ツールでログインする場合の例 エントリー名 ：任意 プロトコル ：ssh ホスト名(ｻｰﾊﾞIPｱﾄﾞﾚｽ) ：別途提示 ログインユーザ名 ：ubuntu [SSH認証鍵]をクリックして、 別途配布するキーペアファイルを選択。
5. ログインできたら 無事にログインできたら、自分の環境情報を少し確認してみましょう。 # OS情報 $ lsb_release -a $ cat /etc/os-release # ホスト名確認 $ hostname # ホスト名を変更する場合 $ sudo hostnamectl set-hostname {ホスト名} # IPアドレス（プライベート） $ ip -br -4 address # IPアドレス（グローバル） ※AWSでは、サーバのインターフェイスに設定されている訳ではなくて、プライベートIPにマ ッピングされているため、通常のコマンドでは確認できない。 $ curl http://checkip.amazonaws.com/ （実行例） ~# lsb_release -a No LSB modules are available. Distributor ID: Ubuntu Description: Ubuntu 22.04.2 LTS Release: 22.04 Codename: jammy ~# hostname isucon-bench.server ~# ip -br -4 address lo UNKNOWN 127.0.0.1/8 ens5 UP XXX.XX.XX.XX/20 metric 100 ~# curl http://checkip.amazonaws.com/ XXX.YYY.ZZZ.AAA
6. 座学①：モニタリング
7. モニタリングとは。 とりあえず細かいことは置いといて「なんか、リソース状況とか見るんでしょ？」 → では、Linux環境における手動での内部監視を実施してみましょう（P.29～） • topコマンド ：主にCPU利用率を確認したい（だけじゃない） • freeコマンド ：メモリ利用状況を確認 Tasks: 113 total, 1 running, 112 sleeping, 0 stopped, 0 zombie %Cpu(s): 0.0 us, 3.1 sy, 0.0 ni, 96.9 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st MiB Mem : 3827.7 total, 2604.6 free, 605.3 used, 617.8 buff/cache MiB Swap: 0.0 total, 0.0 free, 0.0 used. 2982.1 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 1 root 20 0 166332 11516 8316 S 0.0 0.3 1:00.48 systemd 2 root 20 0 0 0 0 S 0.0 0.0 0:00.40 kthreadd 3 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 rcu_gp 4 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 rcu_par_gp 5 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 slub_flushwq 6 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 netns 8 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 kworker/0:0H-events_highpri 10 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 mm_percpu_wq 11 root 20 0 0 0 0 I 0.0 0.0 0:00.00 rcu_tasks_rude_kthread 12 root 20 0 0 0 0 I 0.0 0.0 0:00.00 rcu_tasks_trace_kthread 13 root 20 0 0 0 0 S 0.0 0.0 0:00.13 ksoftirqd/0 14 root 20 0 0 0 0 I 0.0 0.0 0:00.20 rcu_sched 15 root rt 0 0 0 0 S 0.0 0.0 0:00.05 migration/0 $ free -h total used free shared buff/cache available Mem: 3.7Gi 605Mi 2.5Gi 0.0Ki 617Mi 2.9Gi Swap: 0B 0B 0B
8. 実際に負荷かけてみる① なんとなく正常な状態なのは分かるけど、実際に負荷をかけたらどうなるのか。（P.30） まずは、stressコマンドを使えるようにパッケージをインストール。 $ sudo apt install stress そのあと、別ターミナル画面を開いて以下のように負荷をかける。（終了するときは、Ctrl＋C） $ stress --cpu 2 → topコマンドで確認 $ stress -m 2 --vm-bytes 512M --vm-hang 0 → freeコマンドで確認 top - 16:38:37 up 4:40, 3 users, load average: 0.31, 0.07, 0.02 Tasks: 120 total, 3 running, 117 sleeping, 0 stopped, 0 zombie %Cpu(s): 99.7 us, 0.3 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st MiB Mem : 3827.7 total, 2449.1 free, 602.4 used, 776.2 buff/cache MiB Swap: 0.0 total, 0.0 free, 0.0 used. 2983.4 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 3578 root 20 0 3704 256 256 R 100.0 0.0 0:09.51 stress 3577 root 20 0 3704 256 256 R 99.7 0.0 0:09.50 stress 1 root 20 0 167804 13052 8316 S 0.0 0.3 1:01.46 systemd 2 root 20 0 0 0 0 S 0.0 0.0 0:00.40 kthreadd $ free -h total used free shared buff/cache available Mem: 3.7Gi 1.6Gi 1.4Gi 0.0Ki 776Mi 1.9Gi Swap: 0B 0B 0B
9. 実際に負荷かけてみる② 負荷をかけた際のモニタリングツール実行結果の変化が確認できたと思います。 この他にも、以下のようなツールを利用する事で様々なリソース状況を確認できます。 ❏ vmstat ：CPU・メモリ・Disk I/O情報など ❏ sysstat (sarコマンド) ：CPU ❏ w / uptime ：ロードアベレージ ❏ dstat ：CPU・I/O・ネットワーク転送量 ※個別のインストールが必要なツールもあります ubuntu@nakai-server:~$ vmstat 1 20 -t procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu----- -----timestamp----- r b swpd free buff cache si so bi bo in cs us sy id wa st JST 0 0 0 2523680 30012 765032 0 0 16 9 111 193 1 0 99 0 0 2023-09-19 17:12:11 0 0 0 2523428 30012 765032 0 0 0 0 207 386 0 0 100 0 0 2023-09-19 17:12:12 0 0 0 2523428 30012 765032 0 0 0 0 206 387 0 0 100 0 0 2023-09-19 17:12:13 0 0 0 2523428 30012 765032 0 0 0 0 211 386 0 0 100 0 0 2023-09-19 17:12:14 0 0 0 2523428 30012 765032 0 0 0 0 221 394 0 0 100 0 0 2023-09-19 17:12:15 0 0 0 2523428 30012 765032 0 0 0 0 220 386 0 0 100 0 0 2023-09-19 17:12:16 0 0 0 2523428 30012 765032 0 0 0 0 228 407 0 0 100 0 0 2023-09-19 17:12:17 0 0 0 2523428 30012 765032 0 0 0 0 222 401 0 0 100 0 0 2023-09-19 17:12:18 2 0 0 1634624 30012 765032 0 0 0 0 316 419 2 17 82 0 0 2023-09-19 17:12:19 ★ここで負荷かけた 0 0 0 1472840 30012 765032 0 0 0 0 224 390 1 3 97 0 0 2023-09-19 17:12:20 0 0 0 1472840 30012 765032 0 0 0 0 219 390 0 0 100 0 0 2023-09-19 17:12:21 0 0 0 1472840 30012 765032 0 0 0 0 224 390 0 0 100 0 0 2023-09-19 17:12:22 0 0 0 1472840 30012 765032 0 0 0 0 212 388 0 0 100 0 0 2023-09-19 17:12:23
10. リアルタイムな負荷状況は確認できたけど。 システム運用上、手動でのリアルタイムな確認だけでは不十分です。 ╺ Webサービスのレスポンスが遅かったので原因を調査してほしい - 何がボトルネックだったのか原因追及が必要（CPU・Mem・Disk I/Oなど） - リソースではなく、ミドルウェアやアプリの設定パラメータが要因かも ╺ 新機能リリース後にパフォーマンスがどう変化したか確認したい - 時系列でのパフォーマンスの推移をウォッチ こういった場合に備えて、様々な種類のリソース情報を定期的に取得・蓄積しておく事が重要となります。 モニタリングツールの導入（P.31～） • メトリクスを自動で収集し保存 • 保存したメトリクスをWebブラウザ等で時系列順に表示 • メトリクスが特定の閾値に達すると通知を行う メトリクス＝その時の状態を定量的に示した値
11. モニタリングツール OSSのツールとしては、Nagios・Zabbix・Prometheus・・・などがある。 以下はZabbixの場合です • WEBモニタリング機能含めたオールインワンパッケージ ◦ 他ではグラフィカル機能が脆弱なので、Grafanaなど外部ソフトと連携させるケースがほとんど ◦ オールインワンタイプならではの弊害も • 監視クライアントには、Zabbixエージェントを実装。（SNMPなども利用可能） 管理者 監視サーバ 監視対象 Zabbix-Server WEB＋PHP Database 監視リク エスト アラート通知 各種設定、 閲覧 監視データ保存 Zabbix-Agent SNMP 収集データ 送付 シンプルチェック 監視実行
12. 改めて、モニタリングの意義。 ◀引用元：https://www.cybertrust.co.jp/zabbix/about-zabbix.html 適切なモニタリングを実施する事で、以下のような事が可能となる（はず）。 • 「通常とは異なる状態」を検知して修正に着手 ---> パフォーマンス改善 • キャパシティプランニング（システム増強の判断材料） • コスト最適化（スペック過不足修正）※リソースは有限。お金かかる。
13. 座学① まとめ メトリクス の収集 蓄積 異常状態をリアル タイムで検知 傾向分析 リソース最適化 インフラコスト 最適化 キャパシティ プランニング ボトルネックの 追跡・調査 復旧対応 システム改修 ハンズオンのテーマ
14. 座学②：パフォーマンス改善
15. そのまえに この資料はハンズオン参加者全員に配ります。 なので、メモは不要です。 後で見返したり、ハンズオン２日目の時の参考資料にしてください。 実務的な事を言えば、パフォーマンス改善の目標や目的も大事ですが、今回はそういった話は 一旦除外します。 パフォーマンス改善を実体験してもらうのが趣旨です。
16. パフォーマンス改善のフロー よくみる水道管で説明する。 通信網 データ ベース パフォーマンス改善の基本はボトルネックとなって いる場所を改修することです。 図はWebの処理の流れの一部を簡略的に現したもの です。この例だと、データベースをチューニングし ても水の流れる量は変わりません。なので、パフォ ーマンス改善の流れは • 計測する（遅い場所を見つける） • チューニングする（改修する） • 計測する（効果測定する） この繰り返し作業になります。 ボトルネック以外は触らないでください アプリ
17. Webサービスの構造理解 • 構造を理解しないと改善方法は見えてきませんが、 最初は荒い解像度での理解で問題なし • 計測して問題を見つけていく中で高い解像度で理 解を深めていけば良い 「DBのこのQueryが遅い！」とわかったなら、なぜ遅いのか を調べて理解すれば良い。 図でいうなら、DBの裏にはDiskがあるが、Diskは１回のアク セスで何byte持ってこれるのか？秒間のIO速度は？なんて事 は今は気にしなくて良い。 （そして、そんな事は忘れてもよい） 図：引用元「達人が教えるWebパフォーマンスチューニング」
18. ハンズオンの範囲 • サーバのスペックを上げたり、台数増やすとかは 範囲外です。 • 簡単にでもOSのチューニングも部分的にいきた いが、付録に記載程度に留める事になるかも • nginx、PHP、MySQLのチューニングがメイン となります 図：引用元「達人が教えるWebパフォーマンスチューニング」
19. private-isu チューニング開始
20. 今からやる事 パフォーマンス改善の準備及びフローを体験する • WebAppサーバにて計測の準備 ◦ ログフォーマットの変更やPHPに変更 etc. • BenchMarkerサーバにログインして計測する ◦ BenchMarkerの実行 • WebAppサーバに入って遅い原因を調査・修正 ◦ ログを確認、設定の変更 etc. これを繰り返す
21. web server login • AWSにsshでログインしてください # ssh ubuntu@12.34.WEB.IP -i ~/.ssh/isucon-key.pem • isuconユーザーに切り替えてください $ sudo su - isucon • Private IPを調べて下さい（後で使います） • WebブラウザでIscogramを開いて触ってみる ◦ URL: http://12.34.WEB.IP/ にアクセス ◦ ユーザ登録 ◦ コメント投稿 ◦ 画像投稿などなど # Private IP 確認 $ hostname -I 12.34.PRV.IP 📄IPアドレスは各チームで違うので資料上 は以下とします。 WebServer：12.34.WEB.IP WebServerのPrivateIP：12.34.PRV.IP BenchmarkServer：56.78.BM.IP 📄負荷をかける際に指定するIPです 📄みんなログイン出来るまで待って下さい
22. PHP enable • PHPを有効化させてください # Ruby 無効化 $ sudo systemctl stop isu-ruby $ sudo systemctl disable isu-ruby # nginx 設定を変更 $ sudo rm /etc/nginx/sites-enabled/isucon.conf $ sudo ln -s /etc/nginx/sites-available/isucon-php.conf /etc/nginx/sites- enabled/ # nginx 再起動 $ sudo systemctl reload nginx # PHP 有効化 $ sudo systemctl start php8.1-fpm $ sudo systemctl enable php8.1-fpm 📄デフォルトではRuby 📄PHPでやりたいチームはこちら
23. Go enable • Goを有効化させてください # ruby 無効化 $ sudo systemctl stop isu-ruby $ sudo systemctl disable isu-ruby # Go 有効化 $ sudo systemctl start isu-go $ sudo systemctl enable isu-go # エラーなどの出力 $ sudo journalctl -f -u isu-go 📄Goでやりたいチームはこちら
24. nginx log format • nginxのログフォーマットを変更 # backup 作成 設定ミスった時の戻し用 $ sudo cp -pr /etc/nginx/nginx.conf /etc/nginx/__nginx.conf.20230913 # vimコマンドで設定書き換え $ sudo vim /etc/nginx/nginx.conf # access_logの指定を削除し、 # 右の通り、log_formatとaccess_logを指定する # 変更した差分を確認し、意図した変更しかないかを確認する $ diff /etc/nginx/nginx.conf /etc/nginx/__nginx.conf.20230913 💡後でログを解析するため log_format json escape=json '{"time": "$time_iso8601",' '"host": "$remote_addr",' '"port": "$remote_port",' '"method": "$request_method",' '"uri": "$request_uri",' '"status": "$status",' '"body_bytes": "$body_bytes_sent",' '"referer": "$http_referer",' '"ua": "$http_user_agent",' '"request_time": "$request_time",' '"response_time": "$upstream_response_time"}'; access_log /var/log/nginx/access.log json;
25. nginx log format • 設定を有効化し、ログを確認する # nginx シンタックスエラーが起きていない事を確認 $ sudo nginx -t nginx: the configuration file /etc/nginx/nginx.conf syntax is ok nginx: configuration file /etc/nginx/nginx.conf test is successful # logを削除(json形式じゃないlogが解析の邪魔となる） $ sudo rm /var/log/nginx/access.log # nginx 再起動（設定が有効化される） $ sudo systemctl reload nginx # logを確認しながらブラウザでアクセスしてみる $ sudo tail -f /var/log/nginx/access.log 💡解析できるようにjson形式 ではないログは消しておきまし ょう $ diff -u /etc/nginx/__nginx.conf.20230913 /etc/nginx/nginx.conf - - access_log /var/log/nginx/access.log; + log_format json escape=json '{"time": "$time_iso8601",' + '"host": "$remote_addr",' + '"port": "$remote_port",' + '"method": "$request_method",' + '"uri": "$request_uri",' + '"status": "$status",' + '"body_bytes": "$body_bytes_sent",' + '"referer": "$http_referer",' + '"ua": "$http_user_agent",' + '"request_time": "$request_time",' + '"response_time": "$upstream_response_time"}'; + access_log /var/log/nginx/access.log json; error_log /var/log/nginx/error.log;
26. MySQL slow query output • slow queryを出力するように設定変更を行う # 設定変更前にバックアップ $ cd /etc/mysql/mysql.conf.d/ $ sudo cp -pr mysqld.cnf __mysqld.cnf.20230914 # vimで変更を行う $ sudo vim mysqld.cnf -> 変更内容は右を参照 # MySQL 再起動 $ sudo systemctl restart mysql.service 💡long_query_time=0 SQLのログ全て吐くぞ！ # 変更差分は以下 $ sudo diff -u __mysqld.cnf.20230914 mysqld.cnf # Here you can see queries with especially long duration -# slow_query_log = 1 -# slow_query_log_file = /var/log/mysql/mysql-slow.log -# long_query_time = 2 +slow_query_log = 1 +slow_query_log_file = /var/log/mysql/mysql-slow.log +long_query_time = 0
27. web server monitoring • bench markerを走らせるので、監視状態にしましょう #負荷を監視 $ top top - 19:09:05 up 1:08, 1 user, load average: 0.00, 0.00, 0.00 Tasks: 109 total, 1 running, 108 sleeping, 0 stopped, 0 zombie %Cpu(s): 0.3 us, 0.7 sy, 0.0 ni, 99.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st MiB Mem : 3843.5 total, 2731.3 free, 614.4 used, 497.8 buff/cache MiB Swap: 0.0 total, 0.0 free, 0.0 used. 2993.6 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 22 root 20 0 0 0 0 S 0.3 0.0 0:00.04 ksoftirqd/1 612 mysql 20 0 1785564 428168 35940 S 0.3 10.9 0:11.39 mysqld 1 root 20 0 101952 12928 8276 S 0.0 0.3 0:02.74 systemd 2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd 3 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 rcu_gp 💡ログは後からでも見れるが、 詳細な負荷は今しか観れない 📄99%暇してる状態ですね！
28. benchmarker server login & execute • benchmarkerを実行し、現在の状態を計測してみましょう # benchmarkerのサーバにログイン $ ssh ubuntu@56.78.BM.IP -i ~/.ssh/isucon-key.pem # isuconユーザに切り替え $ sudo su - isucon # benchmarkerのディレクトリに移動 $ cd ~/private_isu.git/benchmarker/ # benchmarker 実行 ※2分くらいかかります $ ./bin/benchmarker -u ./userdata -t http://{各自web serverのプライベートIP}/ { "pass": true, "score": 741, "success": 853, "fail": 9, "messages": [ "リクエストがタイムアウトしました (POST /login)", "リクエストがタイムアウトしました (POST /register)" ] } 📄スコア741点！タイムアウトとかも発生している。 計算式： 成功(GET) x 1 + 成功(POST) x 2 + 成功(画像投稿) x 5 - (サーバエラー(error) x 10 + 失敗(exception)数 x 20 + 遅延(POST) x 100)
29. web server monitoring • bench marker中の負荷状況を見てみましょう # 負荷を監視 $ top top - 19:32:48 up 1:32, 1 user, load average: 0.54, 0.12, 0.04 Tasks: 108 total, 1 running, 107 sleeping, 0 stopped, 0 zombie %Cpu(s): 99.7 us, 0.3 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.0 hi, 0.0 si, 0.0 st MiB Mem : 3843.5 total, 2715.8 free, 625.9 used, 501.8 buff/cache MiB Swap: 0.0 total, 0.0 free, 0.0 used. 2982.0 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 612 mysql 20 0 1790724 431264 35956 S 199.3 11.0 0:40.65 mysqld 1880 ubuntu 20 0 10912 4016 3300 R 0.3 0.1 0:00.05 top 1965 isucon 20 0 210960 23612 11880 S 0.3 0.6 0:00.02 php-fpm8.1 1 root 20 0 101952 12928 8276 S 0.0 0.3 0:02.77 systemd 2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd 3 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 rcu_gp 4 root 0 -20 0 0 0 I 0.0 0.0 0:00.00 rcu_par_gp 💡mysqlがやばそうだ... 📄CPUのリソースが枯渇 📄mysqlがボトルネックになっている
30. web server log analytics • alpをインストールして解析してみましょう。 # 作業ディレクトリ変更 $ cd /usr/local/src # unzipコマンドをインストール $ sudo apt-get install zip # alpをインストール $ sudo wget https://github.com/tkuchiki/alp/releases/download/v1.0.16/alp_linux_amd64.zip $ sudo unzip alp_linux_amd64.zip $ sudo install alp /usr/local/bin/alp 💡grepとかでも解析できるけ ど、ツールがあると便利
31. web server log analytics • alpを確認 $ cat /var/log/nginx/access.log | alp json -o count,method,uri,min,avg,max,sum -m "/image/.+,/posts/[0- 9]+,/@.+" --sort=sum -r +-------+--------+--------------------+-------+-------+-------+---------+ | COUNT | METHOD | URI | MIN | AVG | MAX | SUM | +-------+--------+--------------------+-------+-------+-------+---------+ | 49 | GET | / | 0.452 | 6.288 | 9.984 | 308.092 | | 532 | GET | /image/.+ | 0.000 | 0.546 | 8.652 | 290.544 | | 14 | GET | /@.+ | 0.596 | 3.500 | 4.972 | 49.002 | | 40 | POST | /login | 0.004 | 0.783 | 5.072 | 31.308 | | 4 | GET | /posts | 6.804 | 7.659 | 8.428 | 30.636 | | 25 | GET | /posts/[0-9]+ | 0.060 | 1.108 | 4.128 | 27.692 | | 7 | POST | / | 0.004 | 0.922 | 4.280 | 6.452 | | 4 | GET | /logout | 1.004 | 1.186 | 2.260 | 4.744 | | 5 | POST | /register | 0.012 | 0.565 | 1.172 | 2.824 | | 5 | POST | /comment | 0.008 | 0.466 | 1.980 | 2.328 | ...(省略）... 💡/ のアクセスが一番遅い 平均で見てもかなり遅い 📄TOPが遅い（一番改善の余地がでかい） 📄画像取得や投稿も時間はかかっているが一番 遅い場所を攻めるのが定石
32. MySQL log analytics • MySQL標準のログ解析 $ sudo mysqldumpslow /var/log/mysql/mysql-slow.log -s t | head Reading mysql slow query log from /var/log/mysql/mysql-slow.log Count: 1302 Time=0.20s (263s) Lock=0.00s (0s) Rows=2.8 (3650), isuconp[isuconp]@localhost SELECT * FROM `comments` WHERE `post_id` = 'S' ORDER BY `created_at` DESC LIMIT N Count: 1327 Time=0.06s (75s) Lock=0.00s (0s) Rows=1.0 (1327), isuconp[isuconp]@localhost SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = 'S' Count: 25 Time=0.21s (5s) Lock=0.00s (0s) Rows=7.9 (198), isuconp[isuconp]@localhost SELECT * FROM `comments` WHERE `post_id` = 'S' ORDER BY `created_at` DESC Count: 49 Time=0.06s (3s) Lock=0.00s (0s) Rows=10001.7 (490085), isuconp[isuconp]@localhost 💡コメント一覧の取得が実行回 数が多く時間がかかっている ❓理由は明確ではない 📄2.8行返すのに3650行もスキャンしているの は何か臭う
33. MySQL log analytics (pt-query-digest) • percona-toolkitのインストール • pt-query-digestの実行 # percona-toolkitのインストール $ sudo apt update $ sudo apt install percona-toolkit # pt-query-digestの実行 $ sudo pt-query-digest --group-by fingerprint --order-by Query_time:sum /var/log/mysql/mysql-slow.log # 630ms user time, 20ms system time, 35.93M rss, 41.89M vsz # Current date: Tue Sep 19 17:05:50 2023 # Hostname: ip-XXX-XX-XX-XX # Files: /var/log/mysql/mysql-slow.log # Overall: 9.16k total, 23 unique, 115.92 QPS, 4.35x concurrency _________ # Time range: 2023-09-19T07:40:17 to 2023-09-19T07:41:36 # Attribute total min max avg 95% stddev median # ============ ======= ======= ======= ======= ======= ======= ======= # Exec time 344s 1us 290ms 38ms 230ms 73ms 113us # Lock time 10ms 0 55us 1us 1us 1us 1us # Rows sent 518.71k 0 9.77k 58.00 2.90 717.75 0.99 # Rows examine 251.31M 0 97.68k 28.10k 97.04k 43.80k 0.99 # Query size 2.48M 27 999.74k 283.50 80.10 13.63k 38.53
34. MySQL log analytics (pt-query-digest) • pt-query-digestによる解析 # Profile # Rank Query ID Response time Calls R/Call V/M It # ==== ============================== ============== ===== ====== ===== == # 1 0x624863D30DAC59FA168492821... 257.7752 75.0% 1276 0.2020 0.02 SELECT comments # 2 0x422390B42D4DD86C7539A5F45... 73.7715 21.5% 1298 0.0568 0.01 SELECT comments # MISC 0xMISC 12.3436 3.6% 6584 0.0019 0.0 <21 ITEMS>
35. MySQL log analytics (pt-query-digest) • pt-query-digestによる解析 # Profile # Rank Query ID Response time Calls R/Call V/M It # ==== ============================== ============== ===== ====== ===== == # 1 0x624863D30DAC59FA168492821... 257.7752 75.0% 1276 0.2020 0.02 SELECT comments # 2 0x422390B42D4DD86C7539A5F45... 73.7715 21.5% 1298 0.0568 0.01 SELECT comments # MISC 0xMISC 12.3436 3.6% 6584 0.0019 0.0 <21 ITEMS> # Query 1: 16.15 QPS, 3.26x concurrency, ID 0x624863D30DAC59FA16849282195BE09F at byte 3269909 # (省略) # Attribute pct total min max avg 95% stddev median # ============ === ======= ======= ======= ======= ======= ======= ======= # Count 13 1276 # Exec time 74 258s 40ms 290ms 202ms 253ms 67ms 219ms # Lock time 20 2ms 1us 35us 1us 2us 1us 1us # Rows sent 0 3.50k 0 3 2.81 2.90 0.71 2.90 # Rows examine 48 121.69M 97.66k 97.66k 97.66k 97.04k 0 97.04k # Query size 4 104.79k 82 85 84.09 84.10 1.21 80.10 # (省略) # Tables # SHOW TABLE STATUS FROM `isuconp` LIKE 'comments'¥G # SHOW CREATE TABLE `isuconp`.`comments`¥G # EXPLAIN /*!50100 PARTITIONS*/ SELECT * FROM `comments` WHERE `post_id` = '9989' ORDER BY `created_at` DESC LIMIT 3¥G 💡3500行を返すために1億2169 万行をスキャンしている 💡INDEXがない！
36. MySQL Explain • Explainを確認し、チューニングする # mysql に接続する $ mysql -u isuconp -p isuconp # 実行計画を確認する mysql> EXPLAIN SELECT * FROM `comments` WHERE `post_id` = '9989' ORDER BY `created_at` DESC LIMIT 3¥G *************************** 1. row *************************** id: 1 select_type: SIMPLE table: comments partitions: NULL type: ALL possible_keys: NULL key: NULL key_len: NULL ref: NULL rows: 99161 filtered: 10.00 Extra: Using where; Using filesort 1 row in set, 1 warning (0.00 sec) 📄possible_keys: INDEXの利用状況 📄rows: スキャンされた数 📄Extra:オプティマイザの実行計画
37. MySQL tuning • Commentsテーブルに有効なINDEXを付与する # INDEXを付与 mysql> ALTER TABLE comments ADD INDEX post_id_idx(post_id, created_at DESC); # 実行計画を確認 mysql> EXPLAIN SELECT * FROM `comments` WHERE `post_id` = '9989' ORDER BY `created_at` DESC LIMIT 3¥G *************************** 1. row *************************** id: 1 select_type: SIMPLE table: comments partitions: NULL type: ref possible_keys: post_id_idx key: post_id_idx key_len: 4 ref: const rows: 5 filtered: 100.00 Extra: NULL 1 row in set, 1 warning (0.00 sec) 📄INDEXが使われており、スキャンされた行 数も5行、Extra無し
38. benchmarker execute(再び) • 再度計測の準備 • 再計測する # ログの退避 $ sudo mv /var/log/mysql/mysql-slow.log /tmp/__mysql-slow.log.20230919-01 # MySQL再起動(ログファイル再生成される) $ sudo systemctl restart mysql.service $ ./bin/benchmarker -u ./userdata -t http://12.34.PRV.IP/ # 今回 { "pass": true, "score": 23121, "success": 21410, "fail": 0, "messages": [] } # 前回 { "pass": true, "score": 741, "success": 853, "fail": 9, "messages": [ "リクエストがタイムアウトしました (POST /login)", "リクエストがタイムアウトしました (POST /register)" ] } 💡劇的に改善している 💡計測前にlogの退避をする事 で比較が可能！
39. 2日目に対する Hint
40. web server monitoring • bench marker中の負荷状況を見てみましょう 💡mysqlがやばそうだ... ubuntu@ip-172-31-19-62:~$ top top - 18:25:26 up 24 min, 1 user, load average: 2.29, 0.55, 0.18 Tasks: 111 total, 3 running, 108 sleeping, 0 stopped, 0 zombie %Cpu(s): 71.0 us, 24.7 sy, 0.0 ni, 0.2 id, 0.2 wa, 0.0 hi, 4.0 si, 0.0 st MiB Mem : 3843.5 total, 2133.5 free, 778.9 used, 931.2 buff/cache MiB Swap: 0.0 total, 0.0 free, 0.0 used. 2826.3 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 694 mysql 20 0 1800980 595296 36528 S 102.3 15.1 0:31.89 mysqld 540 isucon 20 0 204816 18500 12484 R 14.3 0.5 0:03.96 php-fpm8.1 1258 isucon 20 0 204816 18060 12048 S 14.3 0.5 0:03.55 php-fpm8.1 1349 isucon 20 0 206864 20092 12052 S 13.3 0.5 0:03.54 php-fpm8.1 539 isucon 20 0 210960 24628 12800 S 12.6 0.6 0:03.79 php-fpm8.1 534 www-data 20 0 56540 7196 4680 S 12.3 0.2 0:02.99 nginx 1465 isucon 20 0 206864 20112 12052 S 12.3 0.5 0:03.32 php-fpm8.1 449 memcache 20 0 414456 7876 3516 S 3.0 0.2 0:01.08 memcached 535 www-data 20 0 56200 7044 4680 S 1.0 0.2 0:00.41 nginx 1156 ubuntu 20 0 10896 3996 3300 R 0.7 0.1 0:00.08 top 13 root 20 0 0 0 0 R 0.3 0.0 0:00.05 ksoftirqd/0 📄CPUのリソースが枯渇 📄mysqlがボトルネックになっている
41. MySQL log analytics • pt-query-digestの実行 # バイナリーデータがだらっと出るのでファイル出力 $ sudo pt-query-digest /var/log/mysql/mysql-slow.log | tee /tmp/digest.txt # 出力を確認 $ head -n100 /tmp/digest.txt # 8.6s user time, 40ms system time, 49.40M rss, 55.35M vsz # Current date: Tue Sep 19 18:31:34 2023 # Hostname: ip-XXX-XX-XX-XX # Files: /var/log/mysql/mysql-slow.log # Overall: 142.72k total, 26 unique, 2.30k QPS, 2.85x concurrency ________ # Time range: 2023-09-19T09:23:43 to 2023-09-19T09:24:45 # Attribute total min max avg 95% stddev median # ============ ======= ======= ======= ======= ======= ======= ======= # Exec time 177s 1us 186ms 1ms 2ms 9ms 113us # Lock time 219ms 0 17ms 1us 1us 50us 1us # Rows sent 10.28M 0 9.86k 75.52 2.90 844.71 0.99 # Rows examine 48.49M 0 97.79k 356.27 9.83 4.37k 0.99 # Query size 58.66M 27 1.14M 430.97 84.10 17.29k 38.53 📄スキャン数と返却数は問題なさそう
42. MySQL log analytics • pt-query-digestの実行 # Profile # Rank Query ID Response time Calls R/Call V/M Item # ==== ============================= ============= ===== ====== ===== ==== # 1 0x4858CF4D8CAA743E839C127C... 80.9466 45.8% 911 0.0889 0.01 SELECT posts # 2 0x19759A5557089FD5B718D440... 18.0758 10.2% 12734 0.0014 0.00 SELECT posts # 3 0xCDEB1AFF2AE2BE51B2ED5CF0... 16.5464 9.4% 244 0.0678 0.01 SELECT comments # 4 0x7A12D0C8F433684C3027353C... 16.4759 9.3% 150 0.1098 0.01 SELECT posts # 5 0x396201721CD58410E070DA94... 15.1694 8.6% 61515 0.0002 0.00 SELECT users # 6 0x624863D30DAC59FA16849282... 6.6564 3.8% 23912 0.0003 0.00 SELECT comments # 7 0x422390B42D4DD86C7539A5F4... 6.3023 3.6% 25194 0.0003 0.00 SELECT comments # 8 0x009A61E5EFBD5A5E4097914B... 5.9607 3.4% 93 0.0641 0.04 INSERT posts # 9 0xAA65B65D6FEC3514934B1439... 4.7462 2.7% 244 0.0195 0.00 SELECT posts # MISC 0xMISC 5.7416 3.3% 17722 0.0003 0.0 <17 ITEMS> 💡ボトルネックがコメント一覧 ではなくなった 📄postsのSELECTが重い様子
43. MySQL log analytics • pt-query-digestの実行 # Query 1: 15.02 QPS, 1.31x concurrency, ID 0x4858CF4D8CAA743E839C127C71B69E75 at byte 64028201 # (省略) # Attribute pct total min max avg 95% stddev median # ============ === ======= ======= ======= ======= ======= ======= ======= # Count 0 931 # Exec time 46 81s 14ms 167ms 87ms 116ms 20ms 87ms # Lock time 0 1ms 0 44us 1us 1us 1us 1us # Rows sent 85 8.92M 9.77k 9.86k 9.81k 9.80k 49.50 9.80k # Rows examine 36 17.84M 19.53k 19.72k 19.63k 19.40k 0 19.40k # Query size 0 83.64k 92 92 92 92 0 92 # (省略) # Tables # SHOW TABLE STATUS FROM `isuconp` LIKE 'posts'¥G # SHOW CREATE TABLE `isuconp`.`posts`¥G # EXPLAIN /*!50100 PARTITIONS*/ SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC¥G 📄スキャン数と返却数に違和感はない 📄EXPLAINをみてみるべき
44. MySQL log analytics • EXPLAINを確認し、チューニングしてみる # MySQLに接続 $ mysql -u isuconp -p isuconp # 実行計画を確認 mysql> EXPLAIN SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC¥G *************************** 1. row *************************** id: 1 select_type: SIMPLE table: posts partitions: NULL type: ALL possible_keys: NULL key: NULL key_len: NULL ref: NULL rows: 9856 filtered: 100.00 Extra: Using filesort 1 row in set, 1 warning (0.00 sec) 📄INDEXが使われていない 📄フルスキャンされている
45. MySQL log analytics • EXPLAINを確認し、チューニングしてみる 🚫マネしてはいけません！ # INDEXを追加 mysql> ALTER TABLE posts ADD INDEX created_at_idx(created_at DESC); # EXPLAINを再度実行 mysql> EXPLAIN SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC¥G *************************** 1. row *************************** id: 1 select_type: SIMPLE table: posts partitions: NULL type: ALL possible_keys: NULL key: NULL key_len: NULL ref: NULL rows: 9856 filtered: 100.00 Extra: Using filesort 1 row in set, 1 warning (0.00 sec) 📄INDEXが使われていない 📄フルスキャンされている 📄何も改善していない
46. MySQL log analytics • EXPLAINを確認し、チューニングしてみる 🚫マネしてはいけません！ # EXPLAINを再度実行 mysql> EXPLAIN SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` force index (created_at_idx) ORDER BY `created_at` DESC¥G *************************** 1. row *************************** id: 1 select_type: SIMPLE table: posts partitions: NULL type: index possible_keys: NULL key: created_at_idx key_len: 4 ref: NULL rows: 9856 filtered: 100.00 Extra: NULL 1 row in set, 1 warning (0.00 sec) 📄強制的にINDEX使う事は出来る （速くなってるかはわからない）
47. MySQL log analytics • EXPLAINを確認し、チューニングしてみる 🚫マネしてはいけません！ # EXPLAINを再度実行 mysql> EXPLAIN SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` force index (created_at_idx) ORDER BY `created_at` DESC¥G *************************** 1. row *************************** id: 1 select_type: SIMPLE table: posts partitions: NULL type: index possible_keys: NULL key: created_at_idx key_len: 4 ref: NULL rows: 9856 filtered: 100.00 Extra: NULL 1 row in set, 1 warning (0.00 sec) 📄強制的にINDEX使う事は出来る 📄0.00secなので、速くなってるかはわからない） 📄オプティマイザ的にはオススメしないやり方 📄別の回避策を探しましょう ※全行取得する必要あるの？
48. 次はどうする？
49. パフォーマンス改善のフロー（再び） よくみる水道管で説明する。 通信網 データ ベース パフォーマンス改善の基本はボトルネックとなって いる場所を改修することです。 図はWebの処理の流れの一部を簡略的に現したもの です。この例だと、データベースをチューニングし ても水の流れる量は変わりません。なので、パフォ ーマンス改善の流れは • 計測する（遅い場所を見つける） • チューニングする（改修する） • 計測する（効果測定する） この繰り返し作業になります。 ボトルネック以外は触らないでください アプリ
50. 1日目終了 お疲れ様でした！
51. appendix
52. VSCodeからRemote SSHでLinuxにSSH接続 • VSCode に Remote - SSH 拡張機能 をインストールします • ターミナルやPowerShellで ssh-keygen コマンドを実行 ssh-keygen -t ed25519 ※保存先はデフォルトでOK。パスフレーズもなしでOK • 作成された ~/.ssh/id_ed25519.pub を開き中身をコピー • UbuntuサーバにターミナルからSSH接続します。 • VSCode を開き、左下の緑色のアイコン（><）をクリック→「Remote-SSH Connetct to Host…」→「Configure SSH Hosts…」 →「/Users/ユーザー名/.ssh/config」 • 以下の内容を追記 • 左下の緑色のアイコンから「Remote-SSH Connetct to Host…」で<接続先名>を選択 • 「ファイル」→「フォルダーを開く」から任意のフォルダを選択 sudo su - isucon #isuconユーザーへ切り替え mkdir .ssh chmod 700 .ssh vim ~/.ssh/authorized_keys # 先程作成した~/.ssh/id_ed25519.pub の内容をauthorized_keysにコピペ # 改行して各人それぞれのキーを保存してください 保存:wq chmod 600 .ssh/authorized_keys Host <接続先名> #ここが接続先名として保存されます HostName ec2-xx-xx-xx-xx.ap-northeast-1.compute.amazonaws.com User isucon IdentityFile ~/.ssh/id_ed25519
53. 2日目用のHINT ネタバレ注意！ 見たくない人は見ないで！
54. Performance Hint • CPUやメモリが余っていませんか？ ◦ もっと多くのプロセスを立ち上げて捌ける数が増やせるのでは？ ◦ 今どこで処理がつまっているんでしょうか？ • その処理はアプリを経由する必要がありますか？ • 全件取得する必要があるのか？呼び出しているアプリ側の実装と比較してみましょう ◦ N+1問題やＳＱＬが悪い場合、負荷自体はDBにかかります。でも見直すべきは要件 に対してアプリ側の実装が悪くないのか？となるので注意。2日目はここから？ • too many open filesとは？ERRORが発生したらぐぐってみましょう。 ルーター nginx アプリ(PHP) MySQL データ: BLOB/ Text / Image 静的ファイル: css/js/image
55. Performance Hint • プリペアードステートメントを多用していませんか？プラスに働くケースとそうでないケ ースがあります。SLOW QUERYを解析してみましょう。 • MySQLに正しくINDEXが付与されていますか？EXPLAINで確認しましょう • N+1問題（ループ処理で都度SQL実行している）はありませんか？キャッシュを検討しま しょう • 外部コマンドの呼び出しは遅い事があります。 • SLOW Queryやログの出力も負荷がかかっています。不要なログ出力は止めましょう • memcachedへのアクセスもN＋１問題になってしまうケースもあります。 • PHPにはpreloadやJITコンパイラというものがあります • nginx junitが速いらしい？
56. 参考資料 • github: private-isu • 書籍：達人が教えるWebパフォーマンスチューニング • private-isuをdockerでセットアップした時のメモ（Dockerで試してみたい人向け） • 「PHP-FPM」から「NGINX Unit」に乗り換えるだけで約8倍も応答速度が改善