ISUCON4予選で土曜日の暫定二位でした #isucon

ISUCON4 オンライン予選一日目の結果発表 : ISUCON公式Blog

ISUCON4 予選に参加して私のチームの『チームフリー素材』が土曜日で暫定二位でした

チームメンバーは会社の先輩になる @walf443 さんと @edvakf さんの計 3 人で出場しました
私以外の 2 人は去年の本戦にも出場していますが，そのチームに一人欠員が出たため未経験の私が入った感じです

それでチーム名は色々混乱を産んだようで申し訳ありません…

チーム名の由来としては

@catatsuy さんはうちのチームのフリー素材部分をたんとうしています。
— よしみ@ご注文はpostgresですか? (@walf443) September 27, 2014

とのことです

というわけでとりあえずやったことをまとめておきます

やりながら定まっていった全体的な方針としては

『アプリケーションではなくベンチマークツールに CPU を割けるようにする』

という方針で最適化を行いました

ISUCON4 本選出場の一部基準変更についての詳細 : ISUCON公式Blog

上の記事のように土曜日は --workload にバグがあり高いスコアを取りやすい状態でしたが，私のチームはこれがバグという認識はなく調整すべきパラメータの一つだと思いどこまで上げられるかの検証にも時間を割きました
バグといっても --workload を上げれば並列数は上がるのでアプリケーションへの負荷が高くなりますし，ベンチマークを取るのにも時間がかかるようになるのでただ上げれば勝てるという感じでもなかったと思います

また後日に benchmarker-v2 でスコアを測ったところ workload 16 で 44194 でした
benchmarker-v2 で調整していたわけではないですがこの数字なのでまあそこそこかなと思います

開発準備

私のチームは事前に何回か一緒に練習をしながら作戦を決めていたので最初にやることはある程度決まっていました当日もこの連携がうまく行っていたので焦ること無く進めることが出来ました

今回は Go を使ってやることを事前に決めていたので Go を選択しました

そして当日はプライベートリポジトリで GitHub 上にリポジトリを置いて開発を始めました

edvakf/isu4q

その後に @walf443 さんが Mac 上で開発環境を整えることができるのかを検証して開発環境を整え方を全員に伝えました

これも事前に決めていたもので Go はミドルウェアが Mac 上で動けば Mac でも問題なく開発できることが過去の ISUCON の課題から分かっていたのでまず Mac での開発環境構築ができるか検証することになっていました

またこの間に /home/isucon の権限の問題で isucon ユーザーに ssh 出来なくなっていたのでその辺を修正を @edvakf さんがやっていました

その間に私は事前に決めてあった方法で Nginx のアクセスログからどのルーティングに時間を使っているのか調査をするために Nginx の設定変更と計測結果を Slack に貼りました

Ruby - ltsv access log summary tool - Qiita

これを使ってアクセスが多いルーティングと時間がかかっているルーティングを調べます
ここから遅いと分かったルーティングの処理を潰していきます

その間に @edvakf さんがベンチマークを回してその出力を Slack に投稿するシェルスクリプトを作ってくれていたので以後はこのシェルスクリプトを使ってスコアを計測していました

その後に Nginx と Go を UNIX ドメインソケット経由で通信できるようにソースコードを変更して Nginx の設定も変更しました
その際に flag を使ってポート番号を指定した場合は tcp で起動するようにして手元での開発に問題が出ないようにしました martini での書き換えはやったことがなかったのですが，意外とすんなりいけました

その頃には手元での開発に成功していたので私の手元でも開発できるようにしました

事前の調査で Go のプロファイリングツールでは MySQL などの接続待ちなどがうまく出てきてくれないことが分かっていたので walf443/stopwatch を仕込んで時間のかかるクエリなどを調査できるようにしました

ここまでの流れは事前に決めてあった流れをやっていた感じです

ここまでを 11 時までに終わらせました

開発とチューニング

そこからは遅いと分かったルーティングにある遅い SQL を何とかするために pt-query-digest を使ってスロークエリを調べました

そして INDEX を貼り，my.cnf に innodb_flush_log_at_trx_commit を 0 にしたり innodb_buffer_pool_size を 1g にしたりしました

しかしこの辺りで静的ファイル配信時に cannot assign requested のようなエラーが benchmarker で出るようになりました

Nginx のエラーではないことを確認してからローカルポートの枯渇ということに気付いて sysctl.conf をいじって今後必要そうな設定をしていきました

net.core.somaxconn = 1024
net.core.rmem_max = 8388608
net.core.wmem_max = 6553600
net.ipv4.tcp_rmem = 4096 87380 8388608
net.ipv4.tcp_wmem = 4096 65536 6553600
net.ipv4.tcp_fin_timeout = 5
net.ipv4.ip_local_port_range = 1024 65535

今回の benchmarker では 127.0.0.1/8 のネットワークから様々な IP アドレスを用意して接続してくるために並列数を上げるとすぐにローカルポートが枯渇してしまいます

この辺で 13 時が過ぎていましたが --workload が 2 でスコアが 21102 というところでした

これでエラーも出なくなったので --workload をどこまで増やせるのかというのを試していきました
それで 16 で 34474 までコードの変更なく伸びることを確認したので後半にこの値をいじることを決めました

またアプリケーションも変更して IP の Failure Count など SQL を引いている処理を goCache で持って SQL を実行しないようにしました
この辺の変更で当初は CPU をかなり使っていた MySQL の CPU の使用率を減らすことに成功していました

そして Nginx のログから TOP ページがアクセス数が多いということが分かっていたので Go 側でテンプレートエンジンを通さずに文字列として返すようにしました

この変更が 13:49 に行ったベンチマークで --workload 16 でスコアが 38780 になっていました

その後にも User の Locked を goCache を使って高速にする戦略や初期化時に goCache でキャッシュを持つ戦略で --workload 16 でスコアが 39999 になりました

その後に MySQL の接続を UNIX ドメインソケットでやるのを忘れていたので行ったところまた静的ファイル配信時に cannot assign requested というエラーがまた出るようになりました

そこでまた sysctl.conf をいじってローカルポートを再利用するようにしました

net.ipv4.tcp_tw_reuse = 1
net.ipv4.tcp_tw_recycle = 1

この設定に気付くのに 50 分くらい費やしてしまいましたが，なんとか 16 時に --workload 32 で 42346 のスコアを出しました
ここらへんで --workload がどこまで上げられるか試すことになり試したところ --workload 128 で 45287 になりました
そこで --workload を 256 にしたところスコアは跳ね上がり 70662 になりましたが fail が出てきていたのでこのままではスコアを伸ばせないということが分かりました

そこでエラーがファイルディスクリプタの枯渇だろうということで limits.conf で isucon ユーザーのファイルディスクリプタを増やしました
そうするとエラーが出なくなったので安心しました

この時点で 16:45 になっています

今回の ISUCON は benchmarker に CPU を割いたもの勝ちであることに早い段階から気付いていたので benchmarker 以外に CPU を喰っているものをここから潰していきました

意外だったのは supervisord でこれはアプリケーションのログをファイルに書き込むので CPU を使っていました
martini は MARTINI_ENV=production という環境変数を渡すとログを吐かなくなるらしいですが，そんなことは知らなかったので martini 自体のソースコードを変更してログを吐かないようにした上で go install し直しました

これは本当は Fork して直したかったのですが GitHub の仕様では public なプロジェクトを private なリポジトリに Fork することはできないらしく，この時チームは暫定一位だったのでそのメンバーである私が martini を Fork していじり始めたらレギュレーション的にかなりまずいと思ったので直接いじるという選択をしました

正直 ISUCON のアプリはそんなに大きくないので Go に慣れているなら真っ先に Martini を除くことに時間を使った方がいいかもしれません

これで supervisord の CPU 使用率をほぼ無くすことに成功してさらに負荷をかけられるようになっていきます

そして top を見ていると 4 worker にした Nginx が実質 3 コアしか使っていないことが分かったので 2 worker に変更してコンテキストスイッチを減らしました

そして一度再起動試験をしようということで 17 時過ぎに一度再起動して問題ないかどうか確認しました
特にファイルディスクリプタ周りなどの設定は再起動後にも有効になるのかどうかかなり不安でしたが，特に問題なくベンチマークが通ったのでホッとしました

その後どこまで --workload を上げることができるのか検証していました
私のやった感じでは 300 までなら耐えられそうでしたが，17 時時点で暫定一位だったのでここで無理をして失格になるのも嫌だったので少し --workload を落として 280 で提出しました

今回の ISUCON のルールではある程度 fail していても通ってしまうので fail を気にせず --workload を高くして高いスコアを出すという戦略もありだったような気もしますが，個人的に fail が起こるのは非常に嫌だったので fail が 0 で終了する値に調整して提出しました

最終スコアは 82386 で暫定二位で終了しました