アプリケーションエンジニアがISUCON7の予選を解いてみた その1
私は普段アプリケーションエンジニアとして働いていますが、ISUCONいつも楽しそうだなーと思って見ています。今年こそは参加したいと思い､まずは過去問 としてISUCON7の予選を解いてみようと思い立ちました。
はじめに
このポストはその際の作業ログ的な立ち位置です。私のようにアプリケーションエンジニアだけどISUCON参加してみたいという方の参考になるよう、問題を解くにあたって参考にした情報などなるべく残すようにしてみました。
またはじめにきちんと開示しておくと、ISUCON7 の予選問題を解くにあたってすでに様々な方のブログポストを読んでいます。そのため、ある程度この問題のどこにボトルネックがあるのか事前に把握しています。
ただ、なるべく "ボトルネックがどこにあるか知らなかったとしてもどうやってそこにたどり着けるのか" を意識して作業したつもりです。どなたかの参考になれば幸いです。
基本的には以下2つのブログポストを参考にしつつ、必要に応じて他のブログポストの内容も参照しながら作業を進めていきたいと思います。
環境構築
インスタンス立てるのも面倒臭いので,今回はこちらを使ってローカルでISUCONの環境を構築したいと思います。
一点注意として、私の環境では make up するとMySQLの起動に失敗しました。いろいろ調べていくと, 以下のコメントで解決しました。
make attach/app03 でMySQLのコンテナにログインし、sudo find /var/lib/mysql -type f -exec touch {} \; を実行後に make mysql/start で正常にMySQLが起動するようになりました。
マニュアル/レギュレーションの確認
当日のマニュアル/レギュレーションを確認しておきます。
構成
webサーバーが2台 (app01, app02)、dbサーバー1台 (app03) の3台構成。
マシンの調査
スペックの確認
3台とも同じ。2コアでメモリが2GB、スワップが1GB。
isucon@ad67fcd65989:~/isubata$ grep processor /proc/cpuinfo
processor : 0
processor : 1
isucon@ad67fcd65989:~/isubata$ free -m
total used free shared buff/cache available
Mem: 1999 715 324 0 959 1110
Swap: 1023 23 1000
プロセスの確認
各マシンで ps aux を実行して不要なプロセスが動いていないか確認します。見たところ特に殺せそうなプロセスはなかったためOK。
アプリを触ってみる
実際にアプリの挙動を確認してみます。http://0.0.0.0:8081/ もしくは http://0.0.0.0:8082/にアクセス。ユーザー登録からチャンネルの作成/確認など、一通り動かしてみると2ちゃんねるっぽい掲示板アプリであることが分かります。
ベンチを回してみる
make bench/start でベンチを走らせ、make bench/score で初期スコアを確認します。4707 でした。
vmstat
ベンチを回すついでにvmstatコマンドでざっくりと各サーバーの状況を取ってみます。
app01 (webサーバー)
isucon@78041320129c:~/isubata$ vmstat 5 procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 6 0 746468 83016 6888 455884 0 5 22 30 73 191 1 1 99 0 0 28 4 753980 78304 7520 423048 217 1670 3874 4363 12624 32418 33 65 1 0 0 41 1 774708 69488 8612 443472 26 4162 20737 6709 9269 29567 35 65 0 0 0 40 0 790140 74176 8316 453092 90 3165 10917 6556 9467 30596 34 65 1 0 0 41 0 792632 70016 8248 459064 279 750 2129 3202 8016 28947 33 67 0 0 0 26 0 803932 72508 6776 439508 110 2345 2260 4744 8687 30186 35 65 0 0 0 24 0 818808 82116 6172 427648 199 3134 3327 5361 9365 31439 33 67 1 0 0 19 0 823032 83068 6224 432720 54 900 1801 4326 9230 30503 32 67 1 0 0 26 0 829024 75868 6056 435336 274 1438 4261 6826 9711 31012 30 69 1 0 0 22 1 845860 63760 4608 383932 76 3418 2433 6184 8591 26687 34 65 1 0 0 29 2 865696 66548 3336 372760 45 4011 13733 7366 9566 28477 33 66 1 0 0
app02 (webサーバー)
isucon@04d632d063c5:~/isubata$ vmstat 5 procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 3 0 891776 66100 6580 415436 0 6 26 33 77 202 1 1 99 0 0 42 0 897920 75572 6752 359200 212 1390 5560 3638 11912 31203 32 66 2 1 0 38 2 911552 66636 6528 382508 134 2843 20476 6693 9116 31291 35 65 0 0 0 43 1 932452 65204 5568 404648 977 4989 31758 7045 9005 29463 34 66 0 0 0 35 0 944052 67480 3860 401556 1368 3538 10998 4876 8665 29767 37 62 1 0 0 21 1 957188 71604 2844 394952 2434 5192 13190 8425 8484 25573 35 64 1 0 0 16 0 967508 63432 2464 373784 2913 5055 16518 8254 9877 28847 38 61 1 0 0 38 3 992032 75700 3208 384320 2010 6612 17517 12240 9687 28078 34 65 1 0 0 18 0 1016568 73004 2944 373776 1539 6094 12325 9526 10215 30227 33 66 1 0 0 37 1 1046720 74952 2964 372864 1672 7278 17936 10458 9980 27964 32 67 1 0 0 41 4 1048212 69116 3504 376356 2367 2147 15011 6727 9275 26972 33 65 1 0 0 3 1 1012940 160008 2900 341724 3034 2638 30088 8505 8272 23301 28 69 2 1 0
app03 (dbサーバー)
isucon@ad3bfb718b03:~/isubata$ vmstat 5 procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu----- r b swpd free buff cache si so bi bo in cs us sy id wa st 4 0 1021260 73564 4584 378820 1 8 33 36 80 211 1 1 99 0 0 39 3 1020040 69852 4920 355000 874 376 1777 4165 9004 19957 17 41 41 1 0 31 1 1030796 79224 6240 308792 1262 3113 22822 8787 9829 27506 36 63 0 0 0 27 4 1048276 66428 4848 336116 610 3962 39084 9162 10046 30640 36 63 0 0 0 36 0 1048528 69956 2412 305464 1106 862 43573 3910 9008 26961 34 66 1 0 0 19 2 1048360 69048 1496 300276 1983 1434 61963 5530 9703 26530 32 67 1 0 0 44 4 1047928 68984 1112 297296 2714 2070 71141 7183 9019 23058 33 65 1 0 0
webサーバー, dbサーバーともにCPU使用率に苦しんでいるようです (特にsystem)。vmstatの各指標の解釈に関しては以下のポストを参照しました。
また、各指標のもう少し細かい解釈などは少し古い本ですが、サーバー/インフラを支える技術の4章 性能効能、チューニングの章も手元に置きながら確認しました。
dbサーバーのボトルネックを特定する
まずはdbサーバーのボトルネックをもう少し詳しく見るため、一旦myprofiler を使って重いクエリを特定します。
myprofilerのインストール
dbサーバに入って以下を実行する。
wget https://github.com/KLab/myprofiler/releases/download/0.2/myprofiler.linux_amd64.tar.gz tar xf myprofiler.linux_amd64.tar.gz sudo mv myprofiler /usr/local/bin/ rm myprofiler.linux_amd64.tar.gz
myprofilerの実行
myprofiler -user=isucon -password=isucon でprofilerを実行した状態でベンチを走らせる。
1539 SELECT name, data FROM image WHERE name = ? 135 SELECT COUNT(*) as cnt FROM message WHERE channel_id = ? 26 SELECT * FROM haveread WHERE user_id = ? AND channel_id = ? 12 SELECT * FROM message WHERE id > ? AND channel_id = ? ORDER BY id DESC LIMIT N 10 SELECT name, display_name, avatar_icon FROM user WHERE id = ? 9 SELECT * FROM user WHERE id = ? 8 INSERT INTO image (name, data) VALUES (?, ?) 4 INSERT INTO message (channel_id, user_id, content, created_at) VALUES (?, ?, ?, NOW()) 4 SELECT * FROM user WHERE name = ? 3 UPDATE user SET avatar_icon = ? WHERE id = ?
SELECT name, data FROM image WHERE name = ? がダントツでヤバそう。imageテーブルの data カラムを見ると画像のバイナリーを直接ぶち込んでいるのも分かる。バイナリーはサイズが大きく、書き込み/読み込みの際にボトルネックになりやすい。ここはサクッと解決できないので今は一旦パス。
また上位2つのクエリに対してそれぞれindexが効いているか確認する。
mysql> show create table image; +-------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ | Table | Create Table | +-------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ | image | CREATE TABLE `image` ( `id` bigint(20) unsigned NOT NULL AUTO_INCREMENT, `name` varchar(191) DEFAULT NULL, `data` longblob, PRIMARY KEY (`id`) ) ENGINE=InnoDB AUTO_INCREMENT=1199 DEFAULT CHARSET=utf8mb4 | +-------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ 1 row in set (0.00 sec) mysql> show create table message; +---------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ | Table | Create Table | +---------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ | message | CREATE TABLE `message` ( `id` bigint(20) NOT NULL AUTO_INCREMENT, `channel_id` bigint(20) DEFAULT NULL, `user_id` bigint(20) DEFAULT NULL, `content` text, `created_at` datetime NOT NULL, PRIMARY KEY (`id`) ) ENGINE=InnoDB AUTO_INCREMENT=12386 DEFAULT CHARSET=utf8mb4 | +---------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ 1 row in set (0.00 sec)
imageテーブルのnameとmessageテーブルのchannel_idは共にindexがはられていないようなのでここで対応しておきます。
mysql> ALTER TABLE image ADD INDEX index_image_on_name(name); Query OK, 0 rows affected (0.05 sec) Records: 0 Duplicates: 0 Warnings: 0 mysql> show create table image; +-------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ | Table | Create Table | +-------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ | image | CREATE TABLE `image` ( `id` bigint(20) unsigned NOT NULL AUTO_INCREMENT, `name` varchar(191) DEFAULT NULL, `data` longblob, PRIMARY KEY (`id`), KEY `index_image_on_name` (`name`) ) ENGINE=InnoDB AUTO_INCREMENT=1199 DEFAULT CHARSET=utf8mb4 | +-------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ 1 row in set (0.00 sec) mysql> ALTER TABLE message ADD INDEX index_message_on_channel_id(channel_id); Query OK, 0 rows affected (0.03 sec) Records: 0 Duplicates: 0 Warnings: 0 mysql> show create table message; +---------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ | Table | Create Table | +---------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ | message | CREATE TABLE `message` ( `id` bigint(20) NOT NULL AUTO_INCREMENT, `channel_id` bigint(20) DEFAULT NULL, `user_id` bigint(20) DEFAULT NULL, `content` text, `created_at` datetime NOT NULL, PRIMARY KEY (`id`), KEY `index_message_on_channel_id` (`channel_id`) ) ENGINE=InnoDB AUTO_INCREMENT=12386 DEFAULT CHARSET=utf8mb4 | +---------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+ 1 row in set (0.00 sec)
ここまででbenchを回すとscoreは 16331 でした。
webサーバーのボトルネックを特定する
webサーバーも同様にどこがボトルネックになっているのかもう少し詳しく見ておきます。こちらはnet/http/pprofを利用します。
net/http/pprofの準備
こちらを参考にwebサーバーにpprofを仕込みます。
Install pprof. · ryotarai/isucon7q@76ec7ec · GitHub
終わったら, make app/start/go アプリの再ビルドと再起動を忘れずに。
net/http/pprofの実行
今回は以下の方法でpprofの結果をWeb UIで確認したいと思います。このあたりに関しては以下の記事を参考にしました。
http://blog.livedoor.jp/sonots/archives/18193659.html christina04.hatenablog.com
手順は以下の通りです。
1 ベンチを実行する
2 各webサーバーにログインしてpprofを実行する。ホスト側のisucon7-qualify-docker/ がマウントされているので, 各プロファイル結果はホスト側でも確認できるはず。
# @app01 curl -s http://localhost:6060/debug/pprof/profile > web1_cpu.pprof # @app02 curl -s http://localhost:6060/debug/pprof/profile > web2_cpu.pprof
3 手元(ホストのマシン)でプロファイル結果をWEB UIで表示する
# 以下はすべてホストのマシン go get -u github.com/google/pprof pprof -http=localhost:8080 web1_cpu.pprof # or web2_cpu.pprof
以下のような画面が立ち上がるはず
このままだとちょっと直感的に分かりづらいので view > Flame GraphからFlame Graphを表示します。Flame Graphの読み方に関しては以下のポストを参照しました。
Flame Graphはこんな感じになるはず。
負荷の大きい順に
main.getIcon (23.56%, 1.88s)main.fetchUnread (10.53%, 0.84s)main.getMessage (7.52%, 0.60s)main.getHistory (6.89%, 0.55s)
getIcon は err := db.QueryRow("SELECT name, data FROM image WHERE name = ?", c.Param("file_name")).Scan(&name, &data) を実行している。
先程のimageテーブルにアクセスしているので、バイナリーを直接ぶち込んでいるのがパフォーマンスネックになっていそう。ここはやはり次の改善ポイントとして取り組んで間違いなさそう。
fetchUnread はざっと見た感じ for _, chID := range channels でチャネルごとにループを回してqueryを発行しているように見えるので恐らくN+1が発生していそう。
あとの2つに関しては上の2つが解消してからもう少し詳しく見てみる。
一旦長くなったのでその1はここまで。その2ではimageテーブルのバイナリーぶち込み問題を解決したいと思います。
