概要
この記事では主に自分がISUCONの練習から本番を通して得た知識について書きました！主に達人が教えるWebサイトパフォーマンスチューニング（以下ISUCON本）という書籍から学んだことを抜粋しています。
MySQLのEXPLAINについて
業務ではPostgreSQLを使用していることもあり、ISUCONの練習に取り組むまでMySQLのEXPLAINで出力されるExtraの部分についてあまり理解できていませんでしたが、ISUCON本のおかげでExtraに出力されている意味、その後行うべき調整を一部知ることができました。
ISUCON本に出てくる、インデックスの適応例
最初はインデックスが１つも貼られていない
mysql> EXPLAIN SELECT * FROM `comments` WHERE `post_id` = 10001 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 | 99603 | 10.00 | Using where; Using filesort |
+----+-------------+----------+------------+------+---------------+------+---------+------+-------+----------+-----------------------------+
1 row in set, 1 warning (0.00 sec)
post_idにINDEX付与してみる
mysql> ALTER TABLE comments ADD INDEX post_id_idx(post_id);
mysql> EXPLAIN SELECT * FROM `comments` WHERE `post_id` = 10001 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 | ref | post_id_idx | post_id_idx | 4 | const | 1 | 100.00 | Using filesort |
+----+-------------+----------+------------+------+---------------+-------------+---------+-------+------+----------+----------------+
1 row in set, 1 warning (0.01 sec)
これだけでも読み取る行数の減少（rows）など改善が見られますが、ExtraにはExtra: Using filesortが記載されています。
これはMySQL内部でソート処理が走っていることを表しているので、インデックスをcreated_atを含めた複合インデックスに変更します。
mysql> ALTER TABLE comments ADD INDEX post_id_idx(post_id, created_at);
mysql> EXPLAIN SELECT * FROM `comments` WHERE `post_id` = 10001 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 | ref | post_id_idx | post_id_idx | 4 | const | 1 | 100.00 | Backward index scan |
+----+-------------+----------+------------+------+---------------+-------------+---------+-------+------+----------+---------------------+
1 row in set, 1 warning (0.01 sec)
Extraが変わりExtra: Backward index scanとなっています。これは昇順に並んでいるインデックスを逆向きに読んだことを表しているのでcreated_atを降順にするするようにインデックスを変更します。
mysql> ALTER TABLE comments ADD INDEX post_id_idx(post_id, created_at desc);
mysql> EXPLAIN SELECT * FROM `comments` WHERE `post_id` = 10001 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 | ref | post_id_idx | post_id_idx | 4 | const | 1 | 100.00 | NULL |
+----+-------------+----------+------------+------+---------------+-------------+---------+-------+------+----------+-------+
1 row in set, 1 warning (0.01 sec)
これによりExtraには何も表示されなくなりました。
Extraを見てインデックスを調整していく、ということをこれまで行ったことがなかったのでこうやって見るのか！と大きな学びとなりました。
alp でアクセスログ解析
Nginxのログ出力形式をjsonに変更し、alpコマンドでアクセスログの解析を行いました。
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;
$ alp json --sort sum -r -m "/posts/[0-9]+,/@\w+,/image/\d+" -o count,method,uri,min,avg,max,sum --file access.log
+-------+--------+----------------------+-------+-------+-------+----------+
| COUNT | METHOD | URI | MIN | AVG | MAX | SUM |
+-------+--------+----------------------+-------+-------+-------+----------+
| 8553 | GET | /image/\d+ | 0.001 | 0.157 | 2.506 | 1345.022 |
| 718 | GET | / | 0.175 | 0.965 | 5.842 | 692.765 |
| 169 | GET | /@\w+ | 0.248 | 1.142 | 5.871 | 192.952 |
| 832 | GET | /posts/[0-9]+ | 0.007 | 0.206 | 1.711 | 171.585 |
| 508 | POST | /login | 0.002 | 0.199 | 5.108 | 101.078 |
| 92 | GET | /posts | 0.171 | 0.996 | 4.503 | 91.627 |
| 154 | POST | / | 0.003 | 0.313 | 1.230 | 48.186 |
| 103 | POST | /register | 0.012 | 0.188 | 1.492 | 19.415 |
| 103 | GET | /admin/banned | 0.002 | 0.171 | 2.101 | 17.620 |
| 94 | POST | /comment | 0.009 | 0.161 | 0.823 | 15.152 |
| 104 | GET | /login | 0.003 | 0.142 | 0.904 | 14.743 |
| 52 | GET | /logout | 0.001 | 0.162 | 0.701 | 8.417 |
| 5 | GET | /initialize | 0.061 | 1.195 | 5.303 | 5.976 |
| 998 | GET | /js/timeago.min.js | 0.000 | 0.000 | 0.000 | 0.000 |
| 998 | GET | /js/main.js | 0.000 | 0.000 | 0.000 | 0.000 |
| 998 | GET | /css/style.css | 0.000 | 0.000 | 0.000 | 0.000 |
| 997 | GET | /favicon.ico | 0.000 | 0.000 | 0.000 | 0.000 |
| 1 | GET | /img/ajax-loader.gif | 0.000 | 0.000 | 0.000 | 0.000 |
+-------+--------+----------------------+-------+-------+-------+----------+
dstat でシステムリソースの監視
dstatを以下のオプションを指定して実行し、CPU負荷などの監視を行っていました。
$ dstat -ctm -C 0,1,2,3,total
-----cpu0-usage----------cpu1-usage----------cpu2-usage----------cpu3-usage-------total-cpu-usage-- ----system---- ------memory-usage-----
usr sys idl wai stl:usr sys idl wai stl:usr sys idl wai stl:usr sys idl wai stl:usr sys idl wai stl| time | used free buff cach
9 2 89 0 0: 9 2 88 1 0: 5 2 93 0 0: 4 1 94 0 0: 7 2 91 0 0|16-12 10:06:17| 507M 5811M 44.7M 1423M
96 2 2 0 0: 1 0 99 0 0: 2 6 92 0 0: 0 0 100 0 0: 24 2 74 0 0|16-12 10:06:18| 507M 5801M 44.7M 1432M
96 3 1 0 0: 0 1 99 0 0: 1 4 95 0 0: 0 0 100 0 0: 24 2 74 0 0|16-12 10:06:19| 507M 5796M 44.7M 1438M
上記の例ではcpuコア数が4つだったので-C 0,1,2,3,totalと指定しています。
cpuコア数は以下のコマンドで確認しました。
$ lscpu
Architecture: x86_64
CPU op-mode(s): 32-bit, 64-bit
Byte Order: Little Endian
Address sizes: 46 bits physical, 48 bits virtual
CPU(s): 4 # ←これ
~
New Relic の導入
ISUCONのスポンサーでもあり、導入記事が充実していたことから練習、本番で利用しました。
導入方法の記事をただ実行するだけですぐにデータを確認することができました。
上記に加えて、Rubyのエージェントも導入して利用していました。
こちらも公式の手順ドキュメントを見るだけでつまずくことなく導入できました。
上記までの設定によりCPU利用率の確認、どのAPIで負荷がかかっているかなどをブラウザで確認していました。
終わりに
ISUCONに参加してみて、ボトルネックを見つけて改善することでスコアに反映されるという体験がまずおもしろいと感じました。
ISUCONで行うボトルネック改善などは、個人で勉強するには腰が重いなと感じていたのですが、ISUCONに参加することで「やらなきゃ！」となるので、それにより様々な対策を知れる＆実装できるのはよい機会でした。
なによりISUCONはサーバー、ベンチマーカー、改善余地があるアプリケーションなどを用意してくださることが１番ありがたいなと感じました。
今後は引き続きISUCON本の問題、その他過去問に取り組んで来年に備えたいなと考えています！