#isucon 6で追いかけていたのは幻だった

ISUCON6の予選に「謎の第三勢力」として参加した。 ISUCON参加は2年ぶり3度め。

結果としては予選落ち・本戦出場ならずだった。

やったこと

アプリ周りを主に見ていたので、それに関して覚えていることを。

アクセスログの集計

ベンチマーク時にどんなリクエストが飛んできているのかを確認。 alpがとても便利だった。

$ sudo tail -n0 -f /var/log/nginx/access.log > bench.$(date +%Y%m%d-%H%M%S).log
$ cat bench.XXXXXX-XXXXXX.log | alp --sum --reverse

こんな結果が得られる https://gist.github.com/handlename/2a9bfb22e9a1c4111aad0957cc3b87be

これを見て、

  • GET /がとにかく遅い
  • GET /kewword/:keywordも遅い
  • POST /keyword/:keyword(entryのdelete)が行われない

などがわかったので以降の施策に活かすことができた。

DBに必要なインデックス追加

tcpdumpでmysqlの通信をダンプしてpt-query-digestで確認。

$ sudo tcpdump -s 65535 -x -nn -q -tttt -i any port 3306 | gzic -c > tcpdump.$(date +%Y%m%d-%H%M%S).cap.gz
$ zcat tcpdump.XXXXXX-XXXXXX.cap.gz | pt-query-digest --type tcpdump --no-report --output slowlog

初期実装ではアプリからmysqlにsocketで接続するようになっていてtcpdumpがとれずちょっとはまった。

isutarをisudaに統合

初期実装では3つのアプリケーションに分かれていた。

  • isuda: 本体。entry本文内のキーワードに対応するentryにリンクを張る
  • isutar: entryにスターを付ける
  • isupam: スパムチェッカー。entryチェック時にスパムかどうかを判定する

nginxのlocationでisutarに該当するものだけ振り分けられており、 isutar内の処理でisudaにHTTPリクエストを送る、という謎構成になっていた。 別アプリになっているメリットが何もなかったのでisutarの処理をisudaに移植。 あわせてnginxのlocation設定も削除。

isupamもisudaからHTTPリクエストを受けるものだったが、 バイナリファイルになっており統合は難しそうだったので手を付けず。

keywordリスト取得の効率化

entryをCHARACTER_LENGTHでソートしていた部分を予めDBに保存。 これだけでスコアが1万点台に乗った。

正規表現パターンの生成を最小限に

entry本文中のキーワードにリンクを張るために、 entryごとにDBからキーワードを全て取得して正規表現パターンをつくって置換する、 という処理を行っていた。

トップページでは10件のentryが表示されていたので、この処理が10回繰り返されていた。 新しいキーワードが登録されない限りは正規表現パターンが変わることはないので、 ループ処理外でパターンをつくるように変更。

生成したパターンをHTTPリクエストを跨いでキャッシュする、ということは行わなかった。 キャッシュして、キーワードが登録されるたびに更新すれば充分だったかも。

HTML生成の高速化

上記の通り、表示のたびに正規表現で置換&HTMLエスケープを行っていたため、 entryのHTML生成処理が一番大きなボトルネックだった。

これを何とかするために生成済みのHTMLをDBにキャッシュすることにした・・・という考えまではよかった。

  1. ベンチマークからキーワードが登録リクエスト
  2. DBから関連するentryを全て取得
  3. 取得したentryのHTMLを再生成
  4. 生成したHTMLをDBに保存
  5. レスポンスを返す

キーワードが登録されるたびに キャッシュを再生成 してしまったのが完全に悪手。 生成は初期実装の通りentry表示のタイミングで行うようにし、 キーワード登録時には キャッシュのクリア のみをするようにすれば充分だった。

「ベンチマーカーのPOSTリクエストには3秒以内にレスポンスを返さなければならない」という制約があり、 これを守ることができずにfailしまくり。 改善しようとした際にもキャッシュクリアではなくキャッシュ生成を速くする方向で頑張ってしまったので 時間をかけた割には効果が得られなかった。

あとから振り返ると無謀な手だというのは明らかだけど、 競技中は余裕が無いのでそれに気づくことができなかった。 落ち着くの大事。

これができたらスコアは10万点弱まで上がっていたんじゃないだろうか。

その他感想

事前の準備大事

前日にチームメンバーで集まって準備と予習をした。

必ず必要になる設定やツールなどをchef cookbook化して競技開始してすぐに反映できるようにし、 cookbook化できないものについては手順メモをつくってすぐに実行できるように準備した。

このchef cookbookを使いつつISUCON5予選の問題(たまたまチームメンバー全員初見だった) を4時間ほどかけて解いて、ググりながら作業した部分などをまとめた。

予選当日はこの準備のお陰で午前中には1万点第後半まで到達することが出きた。 スタートダッシュが決められると精神的に余裕ができるし、他のチームへのプレッシャーにもなる。

幻の5万点を追いかけてしまった

失敗したHTMLキャッシュ実装でベンチマークをかけたときに、 なぜかスコアが5万点第後半まで上がったことがあった。 これを見てやり方が間違っていないと思いこんでしまったのが敗因だったと思っている。 急にスコアが上がったときは再現性があることを確認するために同じ状態でベンチマークを実行するべき。

netdata便利

競技サーバーの状態を確認するためにnetdataを動かしていた。 各種リソースの使用状況をおしゃれに表示してくれるツールで、 競技中はこの画面をでかいテレビに映していた。

準備日の様子 (※写真は準備日の様子)

パッと見わかりやすいしかんたんに入るので便利。 過去のデータを遡ったりすることはできないし再起動したら過去のログは消えてしまうので、 ちゃんと記録を残すのであればMackerelなりNew Relicに投げたほうがよさそう。

運営の皆様、参加者の皆様、お疲れさまでした。 終盤ベンチマークの待ち行列が大変なことになってましたが、 ベンチマークノードが潤沢に用意されていたためかせいぜい2〜3分でベンチ実行されて快適でした。

ISUCONに参加して毎回思うのは、「もっとうまくやれたのにな〜〜〜〜」ということなのですが、 競技中にできないということは(向き不向きの差は多少あれど)それが自分の実力なのでしょう。 がんばろう。

過去の感想とか。

来年もあったら出たい。