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

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

View Slide

本ハンズオンの目的
本を読んでも分かった気になっちゃう。
手を動かして経験してみよう！
学ぶこと
● パフォーマンス改善の進め方
● パフォーマンス改善の方法
○ nginx
○ MySQL
○ Linux(Ubuntu)
※ApacheやPostgreSQLに知識の流用は可能

View Slide

アジェンダ
１日目
● 各種環境ログイン
● 座学①：モニタリング
● モニタリング準備（ハンズオン）
○ 各種ツールの説明
○ 各種インストール手順等
● 座学②：パフォーマンス改善
● パフォーマンス改善（ハンズオン）
○ 計測してみる
○ 改善してみる
○ ベンチマークサーバ使ってみる
● 付録：その他改善まとめ
２日目
● ハンズオン（１時間）
○ 各自private-isuの改善を行う
● 結果発表（１５分）
○ 全チームのスコアを計測！
● 感想（１５分）

View Slide

準備作業
ハンズオンで利用する環境へのログイン方法について説明します。
お手元のターミナルソフトにて、鍵認証方式にてハンズオン環境にSSH接続してください。
以下、”RLogin”ツールでログインする場合の例
エントリー名：任意
プロトコル：ssh
ホスト名(ｻｰﾊﾞIPｱﾄﾞﾚｽ) ：別途提示
ログインユーザ名：ubuntu
[SSH認証鍵]をクリックして、
別途配布するキーペアファイルを選択。

View Slide

ログインできたら
無事にログインできたら、自分の環境情報を少し確認してみましょう。
# 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

View Slide

座学①：モニタリング

View Slide

モニタリングとは。
とりあえず細かいことは置いといて「なんか、リソース状況とか見るんでしょ？」
→ では、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

View Slide

実際に負荷かけてみる①
なんとなく正常な状態なのは分かるけど、実際に負荷をかけたらどうなるのか。（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
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

View Slide

実際に負荷かけてみる②
負荷をかけた際のモニタリングツール実行結果の変化が確認できたと思います。
この他にも、以下のようなツールを利用する事で様々なリソース状況を確認できます。
❏ 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

View Slide

リアルタイムな負荷状況は確認できたけど。
システム運用上、手動でのリアルタイムな確認だけでは不十分です。
╺ Webサービスのレスポンスが遅かったので原因を調査してほしい
- 何がボトルネックだったのか原因追及が必要（CPU・Mem・Disk I/Oなど）
- リソースではなく、ミドルウェアやアプリの設定パラメータが要因かも
╺ 新機能リリース後にパフォーマンスがどう変化したか確認したい
- 時系列でのパフォーマンスの推移をウォッチ
こういった場合に備えて、様々な種類のリソース情報を定期的に取得・蓄積しておく事が重要となります。
モニタリングツールの導入（P.31～）
● メトリクスを自動で収集し保存
● 保存したメトリクスをWebブラウザ等で時系列順に表示
● メトリクスが特定の閾値に達すると通知を行う
メトリクス＝その時の状態を定量的に示した値

View Slide

モニタリングツール
OSSのツールとしては、Nagios・Zabbix・Prometheus・・・などがある。
以下はZabbixの場合です
● WEBモニタリング機能含めたオールインワンパッケージ
○ 他ではグラフィカル機能が脆弱なので、Grafanaなど外部ソフトと連携させるケースがほとんど
○ オールインワンタイプならではの弊害も
● 監視クライアントには、Zabbixエージェントを実装。（SNMPなども利用可能）
管理者
監視サーバ
監視対象
Zabbix-Server
WEB＋PHP
Database
監視リク
エスト
アラート通知
各種設定、
閲覧
監視データ保存
Zabbix-Agent
SNMP
収集データ
送付
シンプルチェック
監視実行

View Slide

改めて、モニタリングの意義。
◀引用元：https://www.cybertrust.co.jp/zabbix/about-zabbix.html
適切なモニタリングを実施する事で、以下のような事が可能となる（はず）。
● 「通常とは異なる状態」を検知して修正に着手 ---> パフォーマンス改善
● キャパシティプランニング（システム増強の判断材料）
● コスト最適化（スペック過不足修正）※リソースは有限。お金かかる。

View Slide

座学① まとめ
メトリクス
の収集
蓄積
異常状態をリアル
タイムで検知
傾向分析
リソース最適化インフラコスト
最適化
キャパシティ
プランニング
ボトルネックの
追跡・調査
復旧対応
システム改修
ハンズオンのテーマ

View Slide

座学②：パフォーマンス改善

View Slide

そのまえに
この資料はハンズオン参加者全員に配ります。
なので、メモは不要です。
後で見返したり、ハンズオン２日目の時の参考資料にしてください。
実務的な事を言えば、パフォーマンス改善の目標や目的も大事ですが、今回はそういった話は
一旦除外します。
パフォーマンス改善を実体験してもらうのが趣旨です。

View Slide

パフォーマンス改善のフロー
よくみる水道管で説明する。
通信網
データ
ベース
パフォーマンス改善の基本はボトルネックとなって
いる場所を改修することです。
図はWebの処理の流れの一部を簡略的に現したもの
です。この例だと、データベースをチューニングし
ても水の流れる量は変わりません。なので、パフォ
ーマンス改善の流れは
● 計測する（遅い場所を見つける）
● チューニングする（改修する）
● 計測する（効果測定する）
この繰り返し作業になります。
ボトルネック以外は触らないでください
アプリ

View Slide

Webサービスの構造理解
● 構造を理解しないと改善方法は見えてきませんが、
最初は荒い解像度での理解で問題なし
● 計測して問題を見つけていく中で高い解像度で理
解を深めていけば良い
「DBのこのQueryが遅い！」とわかったなら、なぜ遅いのか
を調べて理解すれば良い。
図でいうなら、DBの裏にはDiskがあるが、Diskは１回のアク
セスで何byte持ってこれるのか？秒間のIO速度は？なんて事
は今は気にしなくて良い。
（そして、そんな事は忘れてもよい）
図：引用元「達人が教えるWebパフォーマンスチューニング」

View Slide

ハンズオンの範囲
● サーバのスペックを上げたり、台数増やすとかは
範囲外です。
● 簡単にでもOSのチューニングも部分的にいきた
いが、付録に記載程度に留める事になるかも
● nginx、PHP、MySQLのチューニングがメイン
となります
図：引用元「達人が教えるWebパフォーマンスチューニング」

View Slide

private-isu
チューニング開始

View Slide

今からやる事
パフォーマンス改善の準備及びフローを体験する
● WebAppサーバにて計測の準備
○ ログフォーマットの変更やPHPに変更 etc.
● BenchMarkerサーバにログインして計測する
○ BenchMarkerの実行
● WebAppサーバに入って遅い原因を調査・修正
○ ログを確認、設定の変更 etc.
これを繰り返す

View Slide

web server login
● AWSにsshでログインしてください
# ssh [email protected] -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です
📄みんなログイン出来るまで待って下さい

View Slide

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でやりたいチームはこちら

View Slide

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でやりたいチームはこちら

View Slide

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;

View Slide

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;

View Slide

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

View Slide

web server monitoring
● bench markerを走らせるので、監視状態にしましょう
#負荷を監視
$ top
top - 19:09:05 up 1:08, 1 user, load average: 0.00, 0.00, 0.00
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%暇してる状態ですね！

View Slide

benchmarker server login & execute
● benchmarkerを実行し、現在の状態を計測してみましょう
# benchmarkerのサーバにログイン
$ ssh [email protected] -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)

View Slide

● bench marker中の負荷状況を見てみましょう
# 負荷を監視
$ top
top - 19:32:48 up 1:32, 1 user, load average: 0.54, 0.12, 0.04
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がボトルネックになっている

View Slide

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とかでも解析できるけ
ど、ツールがあると便利

View Slide

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が遅い（一番改善の余地がでかい）
📄画像取得や投稿も時間はかかっているが一番
遅い場所を攻めるのが定石

View Slide

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
SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = 'S'
SELECT * FROM `comments` WHERE `post_id` = 'S' ORDER BY `created_at` DESC
💡コメント一覧の取得が実行回
数が多く時間がかかっている
❓理由は明確ではない
📄2.8行返すのに3650行もスキャンしているの
は何か臭う

View Slide

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

View Slide

● 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>

View Slide

● pt-query-digestによる解析
# Profile
# Rank Query ID Response time Calls R/Call V/M It
# ==== ============================== ============== ===== ====== ===== ==
# 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がない！

View Slide

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:オプティマイザの実行計画

View Slide

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
📄INDEXが使われており、スキャンされた行
数も5行、Extra無し

View Slide

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の退避をする事
で比較が可能！

View Slide

2日目に対する Hint

View Slide

● 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
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がボトルネックになっている

View Slide

MySQL log analytics
# バイナリーデータがだらっと出るのでファイル出力
$ 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
📄スキャン数と返却数は問題なさそう

View Slide

MySQL log analytics
# 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
# 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が重い様子

View Slide

MySQL log analytics
# 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 ìsuconp` LIKE 'posts'¥G
# SHOW CREATE TABLE ìsuconp`.`posts`¥G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT ìd`, ùser_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC¥G
📄スキャン数と返却数に違和感はない
📄EXPLAINをみてみるべき

View Slide

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
📄INDEXが使われていない
📄フルスキャンされている

View Slide

MySQL log analytics
🚫マネしてはいけません！
# 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
📄INDEXが使われていない
📄フルスキャンされている
📄何も改善していない

View Slide

MySQL log analytics
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
📄強制的にINDEX使う事は出来る
（速くなってるかはわからない）

View Slide

MySQL log analytics
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
📄強制的にINDEX使う事は出来る
📄0.00secなので、速くなってるかはわからない）
📄オプティマイザ的にはオススメしないやり方
📄別の回避策を探しましょう
※全行取得する必要あるの？

View Slide

次はどうする？

View Slide

パフォーマンス改善のフロー（再び）
よくみる水道管で説明する。
通信網
データ
ベース
パフォーマンス改善の基本はボトルネックとなって
いる場所を改修することです。
図はWebの処理の流れの一部を簡略的に現したもの
です。この例だと、データベースをチューニングし
ても水の流れる量は変わりません。なので、パフォ
ーマンス改善の流れは
● 計測する（遅い場所を見つける）
● チューニングする（改修する）
● 計測する（効果測定する）
この繰り返し作業になります。
ボトルネック以外は触らないでください
アプリ

View Slide

1日目終了
お疲れ様でした！

View Slide

appendix

View Slide

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

View Slide

2日目用のHINT
ネタバレ注意！
見たくない人は見ないで！

View Slide

Performance Hint
● CPUやメモリが余っていませんか？
○ もっと多くのプロセスを立ち上げて捌ける数が増やせるのでは？
○ 今どこで処理がつまっているんでしょうか？
● その処理はアプリを経由する必要がありますか？
● 全件取得する必要があるのか？呼び出しているアプリ側の実装と比較してみましょう
○ N+1問題やＳＱＬが悪い場合、負荷自体はDBにかかります。でも見直すべきは要件
に対してアプリ側の実装が悪くないのか？となるので注意。2日目はここから？
● too many open filesとは？ERRORが発生したらぐぐってみましょう。
ルーター nginx アプリ(PHP) MySQL データ: BLOB/ Text / Image
静的ファイル: css/js/image

View Slide

Performance Hint
● プリペアードステートメントを多用していませんか？プラスに働くケースとそうでないケ
ースがあります。SLOW QUERYを解析してみましょう。
● MySQLに正しくINDEXが付与されていますか？EXPLAINで確認しましょう
● N+1問題（ループ処理で都度SQL実行している）はありませんか？キャッシュを検討しま
しょう
● 外部コマンドの呼び出しは遅い事があります。
● SLOW Queryやログの出力も負荷がかかっています。不要なログ出力は止めましょう
● memcachedへのアクセスもN＋１問題になってしまうケースもあります。
● PHPにはpreloadやJITコンパイラというものがあります
● nginx junitが速いらしい？

View Slide

参考資料
● github: private-isu
● 書籍：達人が教えるWebパフォーマンスチューニング
● private-isuをdockerでセットアップした時のメモ（Dockerで試してみたい人向け）
● 「PHP-FPM」から「NGINX Unit」に乗り換えるだけで約8倍も応答速度が改善

View Slide

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

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

前田啓佑

More Decks by 前田啓佑

Other Decks in Programming

Featured

Transcript