Open19

private-isu での素振り

ISUCON
kotapjpkotapjp

最初のスコアの確認

/home/isucon/private_isu.git/benchmarker/bin/benchmarker -u /home/isucon/private_isu.git/benchmarker/userdata -t http://XX

{"pass":true,"score":1016,"success":879,"fail":0,"messages":[]}

まずは計測をしてみる

mac からベンチマーカー

$ ab -c 1 -t 30 http://XX

競技用インスタンスでtopで計測
MySQLが90％になっていることを確認

MySQLの調査をする

MySQL でスロークエリを把握できるようにする

設定をする

競技用インスタンスで

sudo vim /etc/mysql/mysql.conf.d/mysqld.cnf

負荷をかける

$ ab -c 1 -t 30 http://XX

スロークエリログを確認

sudo mysqldumpslow  /var/log/mysql/mysql-slow.log

Reading mysql slow query log from /var/log/mysql/mysql-slow.log
Count: 714  Time=0.03s (20s)  Lock=0.00s (0s)  Rows=1.9 (1326), isuconp[isuconp]@localhost
  SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N

Count: 34  Time=0.01s (0s)  Lock=0.00s (0s)  Rows=10008.0 (340272), isuconp[isuconp]@localhost
  SELECT `id`, `user_id`, `body`, `created_at`, `mime` FROM `posts` ORDER BY `created_at` DESC

Count: 714  Time=0.01s (7s)  Lock=0.00s (0s)  Rows=1.0 (714), isuconp[isuconp]@localhost
  SELECT COUNT(*) AS `count` FROM `comments` WHERE `post_id` = N

Count: 1  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), isuconp[isuconp]@localhost
  SET NAMES utf8mb4

Count: 2040  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=1.0 (2040), isuconp[isuconp]@localhost
  SELECT * FROM `users` WHERE `id` = N

Count: 6732  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=4852.4 (32666112), isuconp[isuconp]@localhost
  #

Count: 3264  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
  administrator command: Close stmt

Count: 3468  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), 0users@0hosts
  administrator command: Prepare

MySQL に入って事情確認

mysql -uisuconp -pisuconp isuconp
use isuconp

mysql> show create table comments;
+----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Table    | Create Table                                                                                                                                                                                                                                                                                                            |
+----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| comments | CREATE TABLE `comments` (
  `id` int NOT NULL AUTO_INCREMENT,
  `post_id` int NOT NULL,
  `user_id` int NOT NULL,
  `comment` text NOT NULL,
  `created_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=100025 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci |
+----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

index は特になし

mysql> EXPLAIN SELECT * FROM `comments` WHERE `post_id` = 9995 ORDER BY `created_at`
DESC LIMIT 3;
+----+-------------+----------+------------+------+---------------+------+---------+------+-------+----------+-----------------------------+
| id | select_type | table    | partitions | type | possible_keys | key  | key_len | ref  | rows  | filtered | Extra                       |
+----+-------------+----------+------------+------+---------------+------+---------+------+-------+----------+-----------------------------+
|  1 | SIMPLE      | comments | NULL       | ALL  | NULL          | NULL | NULL    | NULL | 99666 |    10.00 | Using where; Using filesort |
+----+-------------+----------+------------+------+---------------+------+---------+------+-------+----------+-----------------------------+
1 row in set, 1 warning (0.00 sec)

ためしのEXPEXPLAIN

key がなくて大量の行の読み込み

INDEX を貼る

mysql> ALTER TABLE comments ADD INDEX post_id_idx(post_id);
Query OK, 0 rows affected (0.54 sec)
Records: 0  Duplicates: 0  Warnings: 0

EXPLAIN

おー劇的な変化

チューニングの成果確認

ログの削除

sudo rm /var/log/mysql/mysql-slow.log
sudo mysqladmin flush-logs

これをしないと結果が混ざってしまうらしい

ベンチマーカーインスタンスより実行
結果

{"pass":true,"score":12093,"success":10232,"fail":0,"messages":[]}

1016→12093

初手感想

ほー、こんなかんじでやっていくのか
スコアが劇的に上がったり、すごく読み込みが早くなるのはいいね
基本的には計測→実行→計測 というような流れか
今日はここまででインスタンスを終了しておく

kotapjpkotapjp

再起動

IPやセキュリティグループなどの再設定

IPが変わっているのでセキュリティグループなどを再設定しました
また私は環境を変えたのでSSHなどのセキュリティグループの許可アドレスも追加しました
SGのdescription は日本語でかけなかった

kotapjpkotapjp

アクセスログを集計する

そもそもなぜアクセスログを集計する手続きが必要なのか？

各URLのレスポンスタイムはWeb サービスの性能を測る重要な指標。
ボトルネックの発見のため、どのURIにアクセスが多いのか、処理に時間がかかっているURIや返却するサイズが大きいURIはどこか、などを把握して解消に繋げられるため。
ISUCONの基本はボトルネックの発見→解消→効果測定のサイクルだと思っている。その発見のプロセス。

nginx のログの形式

combined という形

172.31.18.32 - - [24/Nov/2024:00:01:21 +0900] "GET /image/10242.jpg HTTP/1.1" 200 106929 "-" "benchmarker"

この形式はWeb サービスが出力するログの形式としては一般的だが、処理や人間の目で見るのには不便→JSON形式で出るようにしよう！

アクセスログをJSON 形式で出力する

EC2 インスタンスで行っている場合はココ

 sudo vim /etc/nginx/nginx.conf

http {} 内のLogging Settings のコメントの下に追加

        ##
        # Logging Settings
        ##

        ### 追加 ####
        # ログファイルのフォーマットをjson形式に設定
         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",'
                                '"respons_time":"$upstream_response_time"'
                                '}';

        # access.logにjson形式で出力
        access_log /var/log/nginx/access.log json;
        ##############


$ sudo nginx -t
nginx: the configuration file /etc/nginx/nginx.conf syntax is ok
nginx: configuration file /etc/nginx/nginx.conf test is successful

設定ファイルに異常がないか確認する。OK！

nginx のリロード

sudo systemctl reload nginx
kotapjpkotapjp

alp のインストール

システムのアーキテクチャ確認

uname -m

インストール

適切なalpバイナリをダウンロード
• x86_64 の場合: alp_linux_amd64
• aarch64 の場合: alp_linux_arm64

sudo wget https://github.com/tkuchiki/alp/releases/download/v1.0.21/alp_linux_amd64.zip
sudo unzip alp_linux_amd64.zip
sudo install ./alp /usr/local/bin

確認

$ alp --version
1.0.21
kotapjpkotapjp

手元からabコマンドを用いてベンチマーク

ab -c 1 -t 30 http://XXX/

$ cat /var/log/nginx/access.log
cat: /var/log/nginx/access.log: No such file or directory

あれ、アクセスログがないぞ。
どこかでなにか間違えたか

→
sudo systemctl reload nginx を忘れていた再度実行してJSONログを確認

sudo cat /var/log/nginx/access.log

:
{"time":"2024-11-24T00:51:01+09:00","host":"175.177.46.114","port":"52080","method":"GET","uri":"/image/10261.png","status":"200","body_bytes":"882711","referer":"http://35.74.1.249/posts/10261","ua":"Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/131.0.0.0 Safari/537.36","request_time":"0.170","respons_time":"0.002"}

OK

alp で確認

sudo cat /var/log/nginx/access.log | alp json

こんなかんじなのねー。

kotapjpkotapjp

アクセスログのローテション

ローテート…アクセスログをファイルシステム上で別名に変更すること

アクセスログの保存場所は同じ場所であるので複数回の試行結果を同じファイルにまとめてしまうと適切に処理することができない。

ローテーションのスクリプトを作成

cat << 'EOF' > rotate.sh
#!/bin/sh
mv /var/log/nginx/access.log /var/log/nginx/access.log.$(date +%Y%m%d-%H%M%S)
nginx -s reopen
EOF
chmod +x rotate.sh

これを都度実行する

bash rotate.sh

コマンド化しても良いかもしれない
自動でやって欲しいけどなー

kotapjpkotapjp

ここまでやってみた感想

データ（計測結果）を起点にリーンに開発していく印象
ただしデータの計測方法が最初の状態では整っていない部分があるのでそこの地盤固めを最初にする必要がある


https://media.human-dc.com/3484/ より引用

kotapjpkotapjp

スロークエリを解析するツールを導入する

install

pt-query-digest
https://isucon-workshop.trap.show/text/chapter-3/1-SlowQueryLog.html

mkdir ~/tools
cd ~/tools
wget https://github.com/percona/percona-toolkit/archive/refs/tags/v3.6.0.tar.gz
tar zxvf v3.6.0.tar.gz
./percona-toolkit-3.6.0/bin/pt-query-digest --version
sudo install ./percona-toolkit-3.6.0/bin/pt-query-digest /usr/local/bin
pt-query-digest --version

実行

sudo pt-query-digest  /var/log/mysql/mysql-slow.log

最初、まあまあ時間かかるとおもったらパスが違っただけだった

こんな感じで出るけどちょっとわかりにくい

ファイル出力しておく

sudo pt-query-digest  /var/log/mysql/mysql-slow.log | tee digest_$(date +%Y%m%d%H%M).txt
kotapjpkotapjp

ファイルの見方

「全体的な統計」
「ランキング」
「各クエリの詳細」

パフォーマンスチューニングの文脈で、まず注目するのがランキング

この結果は負荷与える前だったのでSHOW DATABASES が１位だった

kotapjpkotapjp

負荷後の結果

とんでもなく時間がかかっているクエリを発見

kotapjpkotapjp

## クエリの特定

このクエリ。
どう処理していくか。

概要を見ていく
このクエリは1302回実行されて、合計で39秒かかっている。
Lock time は他のスレッドの影響を受けている可能性はない。
1249万行返すために、2498万行の処理をしている。
とにかく実行回数が多い

post テーブルについて調査してみる

mysql> SHOW CREATE TABLE posts;
+-------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Table | Create Table                                                                                                                                                                                                                                                                                                                                           |
+-------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| posts | CREATE TABLE `posts` (
 `id` int NOT NULL AUTO_INCREMENT,
 `user_id` int NOT NULL,
 `mime` varchar(64) NOT NULL,
 `imgdata` mediumblob NOT NULL,
 `body` text NOT NULL,
 `created_at` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP,
 PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=10383 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci |
+-------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

問題なし

これがN+1問題のヒントだと気がつく

DB設計的に問題がなさそうに見えるが、実行数が多くスロー判定されるクエリはアプリケーション側で悪い設計になっている可能性がある。

実際のコード部分を見てみる

func getIndex(w http.ResponseWriter, r *http.Request) {
	me := getSessionUser(r)

	results := []Post{}

	err := db.Select(&results, "SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC")
	if err != nil {
		log.Print(err)
		return
	}

	posts, err := makePosts(results, getCSRFToken(r), false)
:

これが該当の箇所。
アプリケーション側からアプローチする場合もあれば、スロークエリからアプローチする場合もある。
どちらにせよ計測が必要

どう直す？

本では以下の３点が紹介されていた

  • キャッシュを使う方法
  • 別クエリでプリロードする方法
  • SQLクエリのJOINを使う方法

どの方法が最適化かは、web サービスの運用の状況によって異なる

kotapjpkotapjp

vscode ssh 接続

config の設定

Host private-isucon
  HostName xxx.ap-northeast-1.compute.amazonaws.com
  IdentityFile /Users/XXX/private-isu-key.pem
  User ubuntu
kotapjpkotapjp

やべVSCODEから編集するための方法がわからん
SSHのときにsu で入れたら良いんだけど

kotapjpkotapjp

N+1の解消するように修正

	err := db.Select(&results,
		"SELECT posts.id, posts.user_id, posts.body, posts.mime, posts.created_at FROM posts"+
			" JOIN users ON users.id = posts.user_id"+
			" WHERE users.del_flg = 0"+
			" ORDER BY posts.created_at DESC LIMIT 20")

再起動

sudo systemctl reload nginx

計測

36766→