ISUCONの対策本を一通り読んでみてprivate-isuで実践しながらチューニングの流れなどにも慣れてきたのでまとめます。
私と同じような初学者の方や関心がある方々の一助になれば幸いです。
対策本はこちら↓
事前準備
各インスタンスの立ち上げ
EC2で競技用インスタンスとベンチマーカーインスタンスを立ち上げます。
各インスタンスのリージョンやAMIなどの設定はgithubのページに記載の通りです。
ベンチーマーカーインスタンスは競技用インスタンスに対して負荷リクエストを送信し、リクエストを受けた競技用インスタンスでログやリソースの状態を解析しながらボトルネックを見つけて潰すのがチューニングの流れです。
alpのインストール
競技用インスタンスにログ解析ツールであるalpをインストールします。
$ wget https://github.com/tkuchiki/alp/releases/download/v0.3.1/alp_linux_amd64.zip
$ unzip alp_linux_amd64.zip
$ install ./alp /usr/local/bin
$ vi /etc/nginx/nginx.conf
nginx.confのhttpに以下の内容を追記し、設定を反映するためnginxをリロードします。
http{
log_format ltsv "time:$time_local"
"\thost:$remote_addr"
"\tforwardedfor:$http_x_forwarded_for"
"\treq:$request"
"\tmethod:$request_method"
"\turi:$request_uri"
"\tstatus:$status"
"\tsize:$body_bytes_sent"
"\treferer:$http_referer"
"\tua:$http_user_agent"
"\treqtime:$request_time"
"\truntime:$upstream_http_x_runtime"
"\tapptime:$upstream_response_time"
"\tcache:$upstream_http_x_cache"
"\tvhost:$host";
access_log /var/log/nginx/access.log ltsv;
}
$ systemctl restart nginx
スロークエリログの有効化
競技用インスタンスでスロークエリログを有効にします。
$ cd /etc/mysql/mysql.conf.d
$ vi mysqld.cnf
mysqld.cnf に以下を追記します。
slow_query_log = 1
slow_query_log_file = '/var/log/mysql/mysql-slow.log'
long_query_time = 0
slow_query_log
スロークエリログを有効にする
slow_query_log_file
スロークエリログの出力先ファイル名
long_query_time
指定した秒数以上かかったクエリをログに出力する
上記の設定だとlong_query_timeが0なので、すべてのクエリログが出力されます。
実運用時はlong_query_timeには０より大きい値を設定するのが一般的ですが、チューニング時においては１回の実行が速いクエリでもそれらが大量に発行されているケースを想定して拾う必要があるためすべてのクエリを出力します。
mysqld.cnf の編集が完了したら、設定を反映するためにリロードします。
$ systemctl restart nginx
実践
初期状態の確認
ベンチマーカーインスタンスにssh接続して競技用インスタンスに対して負荷試験を実行します。
$ cd /home/isucon/private_isu.git/benchmarker
$ ./bin/benchmarker -u ./userdata -t http://{競技用インスタンスのパブリックIP}
ベンチマークの実行結果は以下のように返ってきました。
この時点でのスコアは693点で、一部のリクエストはタイムアウトしています。
{"pass":true,"score":693,"success":631,"fail":2,"messages":["リクエストがタイムアウトしました (POST /login)"]}
ボトルネックの調査
リソースの使用状況から探る
ベンチマーカーインスタンスからのベンチマーク実行時、競技用インスタンス側のリソース状況をtopコマンドで監視します。
競技用インスタンス（ベンチマーク実行前）
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
1 root 20 0 167628 13056 8448 S 0.0 0.3 0:07.75 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
競技用インスタンス（ベンチマーク実行時）
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
45096 mysql 20 0 1786464 448772 37248 S 97.0 11.4 0:20.83 mysqld
43429 isucon 20 0 228800 81228 10240 S 3.3 2.1 0:07.13 ruby
1 root 20 0 167628 13056 8448 S 0.0 0.3 0:07.75 systemd
ベンチマーク実行前と実行時を比較するとmysqlのプロセスがCPUを100％近く使用しています。
DBアクセスがボトルネックになっていそうです。
アクセスログから探る
alpを用いて、アクセスログのうちレスポンスの合計値が長い順に並び替えて出力します。
$ alp --sum -r -f /var/log/nginx/access.log
+-------+-------+-------+----------+-------+-------+-------+-------+--------+-------------+-------------+---------------+-------------+--------+---------------------------------+
| COUNT | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) | METHOD | URI |
+-------+-------+-------+----------+-------+-------+-------+-------+--------+-------------+-------------+---------------+-------------+--------+---------------------------------+
| 2871 | 0.056 | 9.084 | 1306.873 | 0.455 | 0.068 | 0.140 | 5.416 | 1.009 | 2510.000 | 32273.000 | 10269774.000 | 3577.072 | GET | / |
| 1447 | 0.000 | 7.896 | 508.274 | 0.351 | 0.000 | 0.088 | 5.924 | 1.042 | 43.000 | 43.000 | 62221.000 | 43.000 | GET | /favicon.ico |
| 2112 | 0.004 | 5.924 | 458.291 | 0.217 | 0.004 | 0.080 | 3.556 | 0.607 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /login |
| 1448 | 0.000 | 6.076 | 358.002 | 0.247 | 0.000 | 0.080 | 4.736 | 0.748 | 1915.000 | 1915.000 | 2772920.000 | 1915.000 | GET | /js/timeago.min.js |
| 1447 | 0.000 | 5.988 | 266.128 | 0.184 | 0.000 | 0.080 | 2.436 | 0.470 | 1549.000 | 1549.000 | 2241403.000 | 1549.000 | GET | /css/style.css |
| 1448 | 0.000 | 5.968 | 248.367 | 0.172 | 0.000 | 0.076 | 2.444 | 0.487 | 1824.000 | 1824.000 | 2641152.000 | 1824.000 | GET | /js/main.js |
| 671 | 0.004 | 4.808 | 145.003 | 0.216 | 0.000 | 0.104 | 3.012 | 0.495 | 0.000 | 0.000 | 0.000 | 0.000 | POST | / |
faviconやjs、cssなどの静的ファイルの取得のレスポンスが上位に来ており、ボトルネックとなっていそうです。
これらのボトルネックの解消に向けて本書で紹介していたチューニング例の一部を実際に試しながらスコアが上がっていくか確認します。
インデックスの設定
競技用インスタンスでmysqldumpslowでスロークエリを出力します。
$ mysqldumpslow /var/log/mysql/mysql-slow.log
Reading mysql slow query log from /var/log/mysql/mysql-slow.log
Count: 26 Time=0.04s (1s) Lock=0.00s (0s) Rows=8.2 (212), isuconp[isuconp]@localhost
SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC
Count: 1314 Time=0.04s (51s) Lock=0.00s (0s) Rows=2.6 (3475), isuconp[isuconp]@localhost
SELECT * FROM `comments` WHERE `post_id` = N ORDER BY `created_at` DESC LIMIT N
Count: 1 Time=0.03s (0s) Lock=0.00s (0s) Rows=0.0 (0), isuconp[isuconp]@localhost
DELETE FROM posts WHERE id > N
Count: 2 Time=0.02s (0s) Lock=0.00s (0s) Rows=9984.0 (19968), isuconp[isuconp]@localhost
SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `created_at` <= 'S' ORDER BY `created_at` DESC
Count: 52 Time=0.01s (0s) Lock=0.00s (0s) Rows=10003.0 (520155), isuconp[isuconp]@localhost
SELECT `id`, `user_id`, `body`, `created_at`, `mime` FROM `posts` ORDER BY `created_at` DESC
１本の実行時間が長い順にクエリログが吐き出されます。
上位２本のスロークエリを見るとcommentsテーブルからのpost_id指定での取得に時間がかかっています。
mysqlに接続してcommentsテーブルから適当なpost_idを指定して取得するクエリを投げてEXPLAINしてみます。
結果をみるとtypeがALLでrowsが96611もあるので約10万行あるcommentsテーブルをフルスキャンしています。
ここを解消すればスロークエリは減りそうです。
mysql> EXPLAIN SELECT * FROM `comments` WHERE `post_id` = 9413;
+----+-------------+----------+------------+------+---------------+------+---------+------+-------+----------+-------------+
| id | select_type | table | partitions | type | possible_keys | key | key_len | ref | rows | filtered | Extra |
+----+-------------+----------+------------+------+---------------+------+---------+------+-------+----------+-------------+
| 1 | SIMPLE | comments | NULL | ALL | NULL | NULL | NULL | NULL | 96611 | 10.00 | Using where |
+----+-------------+----------+------------+------+---------------+------+---------+------+-------+----------+-------------+
commentsテーブルのインデックスを定義から確認します。
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=100078 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci |
+----------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
テーブルにはプライマリキー以外のインデックスが貼られていません。検索キーのpost_idにインデックスを貼ることでスロークエリは改善しそうです。
mysql> ALTER TABLE comments ADD INDEX post_id_idx (post_id, created_at DESC);
Query OK, 0 rows affected (0.48 sec)
Records: 0 Duplicates: 0 Warnings: 0
インデックスを貼ったら試しに先ほど流したクエリを実行してみます。
typeがrefでインデックスが効いており、rowsの行数も大幅に改善されました。
mysql> EXPLAIN SELECT * FROM `comments` WHERE `post_id` = 9413;
+----+-------------+----------+------------+------+---------------+-------------+---------+-------+------+----------+-------+
| id | select_type | table | partitions | type | possible_keys | key | key_len | ref | rows | filtered | Extra |
+----+-------------+----------+------------+------+---------------+-------------+---------+-------+------+----------+-------+
| 1 | SIMPLE | comments | NULL | ref | post_id_idx | post_id_idx | 4 | const | 12 | 100.00 | NULL |
+----+-------------+----------+------------+------+---------------+-------------+---------+-------+------+----------+-------+
この状態で再度ベンチマークを実行するとタイムアウトは無くなり、スコアも初期の600点台中盤から8000点まで上がりました。
{"pass":true,"score":8776,"success":7493,"fail":0,"messages":[]}
静的ファイルをWEBサーバーから配信する
faviconやjs、cssなどの静的ファイルはWEBサーバーから配信することでアプリケーションサーバーへの負荷を軽減します。
nginxの設定ファイルを修正します。
$ cd /etc/nginx/sites-available
$ vi isucon.conf
isucon.confを以下のように修正します。
server {
listen 80;
client_max_body_size 10m;
root /home/isucon/private_isu/webapp/public/;
//以下を追記
location ~ ^/(favicon\.ico|css/|js/|img/) {
root /home/isucon/private_isu/webapp/public/;
expires 1d;
}
location /{
proxy_set_header Host $host;
proxy_pass http://localhost:8080;
}
}
この状態でベンチマーカーを実行すると10000点まで上がりました。
{"pass":true,"score":10288,"success":9053,"fail":0,"messages":[]}
所感・意気込み
ISUCONの良いところはWebを支える技術をひととおり学べること
と言いますが本当にその通りで、5年弱開発携わっていますが、ISUCON対策の問題を解く中で新たに得る知見がたくさんあります。
スコアという結果で出るのも分かりやすくて楽しさを見つけられる人は多いと思います。
この記事以降もISUCON対策で実践した内容などは投稿するので、コメントやアドバイスお願いします。
今年のISUCONは申し込みで敗北して、参加できずだったので来年は絶対参加したいところです。
写っている。↓
🎆ISUCON 夏祭り 2023🎆@rosylilly 講師による事前講習・ハンズオン、午後の部もスタートしました👏#isucon #isucon_summer_fes pic.twitter.com/tEoaeaAC0U
— ISUCON公式 (@isucon_official) August 26, 2023