ISUCON11予選でチームウー馬場ーイー2 として参加し、本選進出を決めました

TL;DR

ISUCON11予選にチームウー馬場ーイー2 として出場しました。上位25チームに残り本選進出が決まりました。やったね。最終スコアは389509で8位、予選中のベストスコアは394682でした。本選もがんばるぞ！

毎年素晴らしいコンテストを開催してくださる運営様には感謝しかありません。本当にありがとうございます！！１

体制

あいこん	なまえ	やくわり
	matsuu	バリバリ実装する前衛
	netmarkjp	司令塔
	ishikawa84g	~~SELinux~~AppArmorとマニュアルやコードやDiscordを見るセキュリティ＆情報官

3人がそれぞれ別々の場所にいたのでリモート接続しながら挑みました。画面共有は VDO.ninjaの Remote Screenshare into OBS で生成されたURLを直接相互参照しました。遅延なく解像度も高くて最高。音声と文字チャットはDiscordを使ってます。ISUCON公式のコミュニケーションツールもDiscordなのでツールを統一できて便利。

使用したツールなど

tmux
vim 我らがエディタ
top リソース使用状況確認
dstat リソース使用状況確認
MySQLTuner MySQLパラメータ確認
kataribe アクセスログ解析
slowquery2tsv MySQLスロークエリー解析用に用意したが今回使えず
pt-query-digest MySQLスロークエリー解析

方針

サーバ上で直接vimでソースコードを変更するスタイル
- 手元での再現環境構築や外部からのデプロイは行わない
- sshrc で環境がかぶらないようにしてメンバーごとにvim/ssh環境を分離
実装言語はGoを選択
負荷テスト中は top と dstat -tlamp を目視確認
負荷テスト後にアクセス解析
- nginxのログをkataribeで解析して /result/kataribe.log に出力
- mysqltuner.plを実行して /result/mysqltuner.log に出力
- MySQLはスロークエリーを出力せずパフォーマンススキーマを有効にしてslowquery2tsvでTSV化して /result/slowquery.tsv に出力
  - ただslowquery2tsvはMariaDBへの対応ができておらず
  - 急遽使い慣れたpt-query-digestに差し替えてスロークエリーを /result/slowquery.log に出力
/ で git init
- /etc と /home と解析結果を含む /result をまるごとコミット(必要に応じて.gitignoreで除外)
- git add / して git commit
- GitHubのプライベートリポジトリに git push

今回スロークエリー解析用に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で応答

ベンチマーク結果

ベストスコア

f:id:tmatsuu:20210822133617p:plain

あくまでベストスコアであって実際には上下してます。

全スコア

f:id:tmatsuu:20210822134154p:plain

回数多いかな。どうでしょう。

やったこと

「時間スコア概要」でまとめていきます。

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です。

Gマイナー志向

とくに意味はありません