TL;DR
ISUCON11予選にチーム ウー馬場ーイー2 として出場しました。 上位25チームに残り本選進出が決まりました。やったね。 最終スコアは389509で8位、予選中のベストスコアは394682でした。本選もがんばるぞ！
毎年素晴らしいコンテストを開催してくださる運営様には感謝しかありません。本当にありがとうございます！！１
体制
| あいこん | なまえ | やくわり |
|---|---|---|
 |
matsuu | バリバリ実装する前衛 |
 |
netmarkjp | 司令塔 |
 |
ishikawa84g | |
3人がそれぞれ別々の場所にいたのでリモート接続しながら挑みました。
画面共有は VDO.ninjaの Remote Screenshare into OBS で生成されたURLを直接相互参照しました。遅延なく解像度も高くて最高。
音声と文字チャットはDiscordを使ってます。ISUCON公式のコミュニケーションツールもDiscordなのでツールを統一できて便利。
使用したツールなど
- tmux
- vim 我らがエディタ
- top リソース使用状況確認
- dstat リソース使用状況確認
- MySQLTuner MySQLパラメータ確認
- kataribe アクセスログ解析
- slowquery2tsv MySQLスロークエリー解析用に用意したが今回使えず
- pt-query-digest MySQLスロークエリー解析
方針
今回スロークエリー解析用にslowquery2tsvを作成したのですが、その理由は以下のとおりです。
- GitHubのCSV/TSVビューアが優秀なのでこれを使いたかった
- pt-query-digestは大量のスロークエリーが出力された場合に解析が遅いのでPerformanceSchemaを使いたい
- TSVであればless/vimでもおおよそ桁揃えできるので見やすい
slowquery2tsvは次回までに修正しておきたいと思います。
gitは履歴管理と差し戻しが必要になった際の確認用です。パッケージインストールでの /etc 配下更新やアクセス解析結果を含むため git revert の実行は想定してません。割り切り。
/home と /etc を含むことで何をやったかが後から追えるのでブログでまとめやすくなります。
最終構成
当初は1台目のみを使い、ある程度負荷傾向が定まってきてから複数サーバを使うように構成変更しました。 複数サーバに分けることにしたタイミングではDBよりもappのCPU負荷が高かったので、appを2台配置としています。
| サーバ | 構成要素 | 備考 |
|---|---|---|
| 1台目 | nginx + varnish + app(go) | varnishを追加インストール |
| 2台目 | MariaDB | 初期実装のままバージョン変更なし |
| 3台目 | app(go) |
nginxの設定はこんな感じです。
/api/trendはvarnish経由で1台目のappへ/api/isu/*/graphと/api/condition/*はvarnishを経由せず1台目と3台目のappへ- 上記以外の
/api/と/initializeはvarnishを経由せず1台目のappへ - それ以外はすべてnginxで応答
ベンチマーク結果
ベストスコア
あくまでベストスコアであって実際には上下してます。
全スコア
回数多いかな。どうでしょう。
やったこと
「時間 スコア 概要」でまとめていきます。
10:23 2974 初期ベンチ
公式マニュアルに従いインスタンス作成完了が 10:05、SSHでログインが 10:10 でした。
そこから必要なパッケージのインストールや git init などが完了して初回ベンチマークが 10:23 でした。
10:35 1829 パフォーマンススキーマ有効化
集計のためにMariaDBのPerformanceSchemaを有効にして再計測したらスコアが下がりました。まぁそんなもん。
10:42 1683 スロークエリーログ出力に切り替え
MariaDBのPerformanceSchemaは出力結果がMySQL8と異なり手元の集計ツールが正しく動作しなかったので、方針変更してスロークエリーログ出力とpt-query-digestに切り替えました。スコアはさらに下がって1683。まぁそんなもん。
10:51 16664 DB周りチューニング
pt-query-digestでスロークエリーが顕著に出ていたので、この内容を見ながらDB周りの調整を行っています。
# Rank Query ID Response time Calls R/Call V/M # ==== =================================== ============== ===== ====== === # 1 0x8155B89FFD74A9D523D19AC409FD97AF 330.2609 56.9% 2447 0.1350 0.06 SELECT isu_condition # 2 0x931A992E852C61FC6D46141A39DEF4FE 178.2064 30.7% 3393 0.0525 0.06 SELECT isu_condition # 3 0xFFFCA4D67EA0A788813031B8BBC3B329 31.0515 5.3% 7506 0.0041 0.01 COMMIT # 4 0xDA556F9115773A1A99AA0165670CE848 16.7825 2.9% 87951 0.0002 0.00 ADMIN PREPARE # 5 0xB8B32624C3268C0925657C305C0ED778 14.2339 2.5% 69887 0.0002 0.00 INSERT isu_condition # 6 0x9C6C682008AE0D08F3E2A0049B030C70 4.3813 0.8% 141 0.0311 0.03 SELECT isu_condition # 7 0x5F580A12ADA1633C9634298BE5BD9422 1.7119 0.3% 61 0.0281 0.05 SELECT isu_condition # 8 0x1E561CE87F050ED58A7E1A7FBB6C2285 1.0212 0.2% 7023 0.0001 0.00 SELECT isu # 9 0x07890000813C4CC7111FD2D3F3B3B4EB 0.5763 0.1% 87951 0.0000 0.00 ADMIN CLOSE STMT # 10 0x8C2BC651CBBBF3DB41D1CAD61AA0BD68 0.5094 0.1% 1200 0.0004 0.00 SELECT isu
- goのdb接続パラメータに
interpolateParamsを追加 - インデックス追加
- テーブル
isuにINDEX (jia_isu_uuid)を追加 - テーブル
isu_conditionにINDEX (jia_isu_uuid, created_at)を追加- しかしこの
created_atはtimestampの間違いだったと後で気づく
- しかしこの
- テーブル
これによってpt-query-digestの結果は、Response timeが大きく改善しました。
# Rank Query ID Response time Calls R/Call V/M # ==== =================================== ============== ===== ====== === # 1 0x931A992E852C61FC6D46141A39DEF4FE 116.4533 39.7% 13452 0.0087 0.02 SELECT isu_condition # 2 0x9C6C682008AE0D08F3E2A0049B030C70 50.8375 17.3% 2649 0.0192 0.02 SELECT isu_condition # 3 0xFFFCA4D67EA0A788813031B8BBC3B329 42.2897 14.4% 9056 0.0047 0.01 COMMIT # 4 0x8155B89FFD74A9D523D19AC409FD97AF 38.4616 13.1% 4336 0.0089 0.02 SELECT isu_condition # 5 0xB8B32624C3268C0925657C305C0ED778 25.6250 8.7% 75058 0.0003 0.01 INSERT isu_condition # 6 0x5F580A12ADA1633C9634298BE5BD9422 12.4012 4.2% 731 0.0170 0.02 SELECT isu_condition # 7 0x677D4DCDF729CC334DE038E9477B32B3 1.8281 0.6% 232 0.0079 0.01 SELECT isu_condition # 8 0x8C2BC651CBBBF3DB41D1CAD61AA0BD68 1.0356 0.4% 4400 0.0002 0.01 SELECT isu # 9 0x1E561CE87F050ED58A7E1A7FBB6C2285 0.9872 0.3% 7556 0.0001 0.01 SELECT isu # 10 0xADCA4F127A769A45A2D1B74705103105 0.9068 0.3% 11201 0.0001 0.00 SELECT user
ちなみに各テーブルは /initialize が呼ばれるたびに毎回 DROP TABLE が実行されるので、インデックスは ~/webapp/sql/* もしくは /initialize の中で追加する必要がありました。
11:03 18138 nginxチューニング
続いてnginxにチューニングに入ります。
- nginxとapp間で持続的接続が有効化
- /api/と/initialize以外はnginxから直接返す
プログラムをみると /isu/* や /register などはindex.htmlを返していたので、 try_files を使って存在しないファイルはすべて /index.html を返すようにしているのが工夫ポイントです。
upstream app {
server 127.0.0.1:3000;
keepalive 16;
keepalive_requests 10000000;
}
server {
listen 443 ssl http2;
ssl_certificate /etc/nginx/certificates/tls-cert.pem;
ssl_certificate_key /etc/nginx/certificates/tls-key.pem;
location /api/ {
proxy_set_header Host $http_host;
proxy_set_header Connection "";
proxy_http_version 1.1;
proxy_pass http://app;
}
location /initialize {
proxy_set_header Host $http_host;
proxy_set_header Connection "";
proxy_http_version 1.1;
proxy_pass http://app;
}
root /home/isucon/webapp/public;
index index.html;
location / {
try_files $uri /index.html;
expires 86400s;
}
}
11:09 17774 nginxにclient_body_buffer_size追加
/var/log/nginx/error.log を確認すると POST /api/isu で一時ファイルが生成されていることを確認したため、アクセスログに $request_length を出力してサイズを確認しその最大値を少し上回る値を client_body_buffer_size として設定しました。
location ~ ^/api/isu$ {
client_body_buffer_size 128k;
proxy_set_header Host $http_host;
proxy_set_header Connection "";
proxy_http_version 1.1;
proxy_pass http://app;
}
でも今思えば proxy_request_buffering でやるべきだったかもですね。このあたりは後日追試しようと思います。
11:23 17618 bulk insertに変更
kataribeの出力結果を見るとトップは POST /api/condition/* でした。ちなみにkataribeはほとんど Sort By Total しか見てません。
Top 40 Sort By Total Count Total Mean Stddev Min P50.0 P90.0 P95.0 P99.0 Max 2xx 3xx 4xx 5xx TotalBytes MinBytes MeanBytes MaxBytes Request 75487 433.603 0.0057 0.0139 0.000 0.001 0.016 0.035 0.073 0.107 75213 0 274 0 42 0 0 14 POST /api/condition/<uuid> HTTP/2.0
そこで該当の関数を以下のように変更しました
- INSERT前のSELECTが0件以上あるかの確認だったので
SELECT 1 FROM ... LIMIT 1に変更 - INSERTを数珠つなぎにしてbulk insertに変更
結果スコアは下がったものの、Countが増えてMeanは下がってるので負荷軽減に効果があったと判断しokとしています。
Top 40 Sort By Total Count Total Mean Stddev Min P50.0 P90.0 P95.0 P99.0 Max 2xx 3xx 4xx 5xx TotalBytes MinBytes MeanBytes MaxBytes Request 75731 339.605 0.0045 0.0106 0.000 0.001 0.012 0.023 0.055 0.216 75508 0 215 8 0 0 0 0 POST /api/condition/<uuid> HTTP/2.0
11:44 20127 /api/trendの全件取得を1件に
引き続きMariaDBのCPU負荷が高いためpt-query-digestのトップに来ているクエリーを確認したところ /api/trend の中で実行しているクエリーであることを確認しました。
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY timestamp DESC
このクエリーはLIMITが使われていないものの、その後の処理で最初の1件しか使っていないこと、また一部のカラムしか利用していないので以下ようにクエリーを変更しました
SELECT `condition`, timestamp FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY timestamp DESC LIMIT 1
conditionが予約語らしく バッククォートでくくる必要があったのが罠でしたね。 ちなみにN+1は解消してません。1件取得するだけの変更にとどめています。
11:49 37019 インデックスの間違いに気づく
10:51に追加したインデックスの間違いに気づき isu_condition の INDEX (jia_isu_uuid, created_at) を INDEX (jia_isu_uuid, timestamp) に変更しました。
変更前のpt-query-digest
# Rank Query ID Response time Calls R/Call V/M # ==== =================================== ============== ===== ====== === # 1 0x2C2674DBBE2489BF6C83BB0B21790D62 140.3237 32.3% 16026 0.0088 0.02 SELECT isu_condition # 2 0x9C6C682008AE0D08F3E2A0049B030C70 107.6753 24.8% 3357 0.0321 0.02 SELECT isu_condition # 3 0x8155B89FFD74A9D523D19AC409FD97AF 97.9899 22.6% 7478 0.0131 0.02 SELECT isu_condition # 4 0xFFFCA4D67EA0A788813031B8BBC3B329 36.3303 8.4% 9885 0.0037 0.00 COMMIT # 5 0x5F580A12ADA1633C9634298BE5BD9422 27.1060 6.2% 974 0.0278 0.02 SELECT isu_condition # 6 0xB8B32624C3268C0925657C305C0ED778 12.5142 2.9% 7610 0.0016 0.01 INSERT isu_condition # 7 0x677D4DCDF729CC334DE038E9477B32B3 4.6057 1.1% 381 0.0121 0.02 SELECT isu_condition # 8 0xADCA4F127A769A45A2D1B74705103105 1.8215 0.4% 17482 0.0001 0.00 SELECT user # 9 0x8C2BC651CBBBF3DB41D1CAD61AA0BD68 1.4361 0.3% 5154 0.0003 0.00 SELECT isu # 10 0xB5F4855605637317357023AD70B91455 1.3706 0.3% 8824 0.0002 0.00 SELECT isu
変更後のpt-query-digest
# Rank Query ID Response time Calls R/Call V/M # ==== =================================== ============= ===== ====== ==== # 1 0x9C6C682008AE0D08F3E2A0049B030C70 42.6501 29.9% 5344 0.0080 0.01 SELECT isu_condition # 2 0xFFFCA4D67EA0A788813031B8BBC3B329 35.1129 24.6% 13416 0.0026 0.01 COMMIT # 3 0x2C2674DBBE2489BF6C83BB0B21790D62 25.9887 18.2% 45806 0.0006 0.00 SELECT isu_condition # 4 0x5F580A12ADA1633C9634298BE5BD9422 13.6792 9.6% 2282 0.0060 0.01 SELECT isu_condition # 5 0x8155B89FFD74A9D523D19AC409FD97AF 8.8025 6.2% 22660 0.0004 0.00 SELECT isu_condition # 6 0xB8B32624C3268C0925657C305C0ED778 6.4959 4.6% 7621 0.0009 0.00 INSERT isu_condition # 7 0xADCA4F127A769A45A2D1B74705103105 2.3164 1.6% 44119 0.0001 0.00 SELECT user # 8 0xB5F4855605637317357023AD70B91455 1.8257 1.3% 26210 0.0001 0.00 SELECT isu # 9 0x8C2BC651CBBBF3DB41D1CAD61AA0BD68 1.6544 1.2% 14503 0.0001 0.00 SELECT isu # 10 0x88716D544EA925A1EE9114761B982E3E 0.7488 0.5% 7627 0.0001 0.00 SELECT isu
Response timeが大きく改善しましたね。
12:09 44034 Varnishで/api/trendをキャッシュ
マニュアルと実際の動作をにらめっこしたところ、 /api/trend はログイン状況に関わらずコンテンツの出し分けがなくログインチェックもないのでキャッシュで返せることに気づきました。
そこでVarnishをインストールしてキャッシュ応答をするように変更しています。CookieリクエストヘッダーがついているとVarnishはキャッシュを返さないので、Cookieリクエストヘッダーは vcl_recv で削除しています。
nginx
upstream varnish {
server 127.0.0.1:6081;
keepalive 16;
keepalive_requests 10000000;
}
server {
# ...
location ~ ^/api/trend$ {
proxy_set_header Host $http_host;
proxy_set_header Connection "";
proxy_http_version 1.1;
proxy_pass http://varnish;
}
varnish
backend default {
.host = "127.0.0.1";
.port = "3000";
}
sub vcl_recv {
if (req.url ~ "^/api/trend") {
unset req.http.cookie;
}
}
sub vcl_backend_response {
set beresp.ttl = 0.8s;
set beresp.grace = 0.2s;
}
変更前のkataribe
Count Total Mean Stddev Min P50.0 P90.0 P95.0 P99.0 Max 2xx 3xx 4xx 5xx TotalBytes MinBytes MeanBytes MaxBytes Request 637 257.361 0.4040 0.1896 0.003 0.415 0.638 0.713 0.870 0.978 573 0 3 61 2575394 0 4043 4535 GET /api/trend HTTP/2.0
変更後のkataribe
Count Total Mean Stddev Min P50.0 P90.0 P95.0 P99.0 Max 2xx 3xx 4xx 5xx TotalBytes MinBytes MeanBytes MaxBytes Request 864 15.936 0.0184 0.0651 0.000 0.000 0.023 0.158 0.359 0.515 798 0 0 66 3559454 0 4119 4537 GET /api/trend HTTP/2.0
Meanが大きく下がりました。わいわい。
13:39 79819 たくさん修正
だんだん雑になってきました。昼飯を食べながらざっくりやったほうがいいことを調べて、まとめて適用します。
isuにインデックスINDEX (jia_user_id, jia_isu_uuid)を追加- アプリからのDB接続数を引き上げ
db.SetMaxOpenConns(150)db.SetMaxIdleConns(150) /api/trendのレスポンスをVarnishでgzip圧縮POST /api/condition/*は最後のconditionだけ登録だけでいいのでは？と判断してで最後の1件だけ登録、ついでにトランザクション処理を解除- dropProbabilityを0.9から0.6に変更
- innodb周りのチューニングを追加
14:25 74425 iconを静的ファイルに出力してアプリから返す
GET /api/isu/*/icon がkataribeで2位となっているのでDBに格納せずnginxから返すようにしました。このエンドポイントはログイン必須であるため単純に画像を返すとエラーになるのではと判断し、ファイルに書き出したもののnginxからは応答せずアプリから応答しています。
スコアは下がったもののDBの負荷とトラフィック量は減っており、後々効いてくるだろうと判断して差し戻しは行ってません。
14:44 146710 DBを2台目サーバに移す
スコアに直結するような改修がおもいつかなくなってきたこと、またアプリとdbでCPU負荷を食い合う状況になってきたので、2台目サーバのMariaDBを利用するようにしました。それまではずっと1台目サーバだけで進めていました。
15:22 208386 iconをnginxから返すためX-Accel-Redirectレスポンスヘッダーを追加
DBを分離したあともアプリの負荷が高いため、アプリの処理を減らそうと X-Accel-Redirect レスポンスヘッダーを返すことでnginxから静的ファイルを返すように変更しました。またiconは一度登録すると更新されることはないためキャッシュするよう設定しています。
画像の出力は /home/isucon/tmp に生成していたので、そこをinternalで取得できるようにして X-Accel-Redirect でリダイレクトさせています。ついでにexpiresも追加しています。
location /icon {
internal;
alias /home/isucon/tmp;
expires 86400s;
}
location ~ ^/api/isu/.*/icon$ {
proxy_set_header Host $http_host;
proxy_set_header Connection "";
proxy_http_version 1.1;
proxy_pass http://app
expires 86400s;
}
15:31 188370 静的ファイルをgzip圧縮で応答するもスコアが下がる
~/webapp/public/ 配下のファイルについてそういえばgzip圧縮応答していなかったと思い出し、gzip圧縮してnginxの gzip_static で応答したのですがなぜかスコアが下がってしまいました。何度かon/offを切り替えながらベンチを回したもののoffが良さそうなので最終的にはoffとしました。
この原因は何だったんでしょうね。gzip展開でベンチマーカーのCPU負荷が高まるからか？とか思ったんですが真相は不明です。
16:27 66170 graphの改善を試みるもスコアだだ下がる
マニュアルを読むとグラフの確認による加点があるものの、自分たちの環境はすべてWorstになっていることからこれを改善すればスコアが大きく伸びるのではと思ったのですが、改善しきれませんでした。ここは今後の課題となります。
16:49 269411 3台目サーバをapp用に利用する
アプリのCPU負荷が高い状況が続いていたため、ここで3台目サーバをapp用に利用しています。ほぼほぼ上記最終構成と同じ構成になりました。 これによりスコアが大きく改善しました。
17:00 379417 dropProbabilityを差し戻すとスコアが上がる
打つ手が思いつかない中、13:39に0.6に下げていたdropProbabilityを0.9に戻してみたら大きく改善しました。なんでやねん。よくわかりません。
18:18 394682 最終調整
最終調整を行っていました。
- nginxの
worker_connectionsを増やす - nginxの
upstreamにおいてkeepaliveを増やす - MariaDBの
query_cacheを無効にしてみたもののスコアが下がったので差し戻す - MariaDBのスロークエリーログ出力をやめる
- nginxのアクセスログ出力をやめる
- 再起動試験を実施
最終調整の中で記録したベストスコアが 394682 でした。
その後も何度かベンチガチャを回して予選中の最終スコアは18:39に記録した388657です。
