ISUCON6に参加して2年連続予選敗退してきました

去年に続いてISUCON6の予選に@tatsuyaoiw・@takady7と3人で参加して、去年に続いて惨敗してきました。

来年こそはという気持ちを込めて、感想ブログです。

@takady7の感想ブログ

使用言語はrubyです。

事前準備

予選のちょうど1週間前の土日に、とりあえず去年の過去問をしっかりやろうと思って準備を始めました。

名誉運営のmatuuさんという方がまさに欲しかったazureのテンプレート を公開されていたのでそのまま使わせていただきました。

テンプレートデプロイしてもなんかできてないくさかったので、READMEを見ながら中でansibleを再実行しつつ、なんかPHPのところでこけるからコメントアウトしつつみたいな感じで、結局半日ぐらいかけて環境構築した気がする・・・

基本はベンチ流しながら top -c を眺めといて誰が一番CPU食ってるか（ほぼmysqlかunicornのどっちか）アタリをつけて、下記のツールを三種の神器としてボトルネックを探して修正していくというのをひたすらやりました。

• nginxのログをサマって重いリクエストを探すkataribe（これもmatuuさん作のツールでした）
• ruby内部で重い関数を探すstackprof
• mysqlの重いクエリを探すmysqldump

他にも、

• 上記のツールを用意する手順書
• ローカルからコマンド一発でサーバーに最新のソースをgitからpullしてデプロイ＆諸々再起動＆ログリフレッシュするシェルスクリプト
• ローカルでの開発環境用Dockerfile

などなど準備しつつ、作った環境を他の二人にも共有して前日まで各々仕事の前後にちょっとずつ修正して、着実に上っていくスコアを見ながら「今年はいけるで！」という自信しかありませんでした。

当日

午前10時にスタート。まずはrubyの初期スコアを見るため、テンプレートをデプロイしてデフォルト言語を確認。perlになってたっぽいので、とりあえずrubyに切り替えてベンチ流したら1187点。（今思えばこの時はisudaを切り替えただけでisutarはperlのまま動いてたかも）

ひとまずデプロイ環境と三種の神器を自分が整備しつつ、他の二人がコードを読んだりアプリを触ったりする分担に。

11時ぐらいにある程度整って、htmlifyが圧倒的に遅いことに気づく。中でもキーワードを Regex.escape してパイプでつなぐっていう処理が重かったようなので、つないだ結果をredisにつめてキーワード(entry)のINSERT/DELETEのタイミングで作り直すっていうのをやった。あとベンチで静的ファイルがタイムアウトしたりしてたのでとりあえずnginxから返すようにしたのを混ぜて3145点。

このスコアをslackに投げたのが12:42分。ここで三種の神器の一つ、mysqlのslow query logが出てないことに気づく。出てないのが気持ち悪かったのでこれやっちゃおうと思って手を付けたのが今回最大のミスやったように思います。

mysqlに入って show variables like 'slow%'; を叩くと、my.cnfの slow_query_log_file は反映されてんのにどうやっても slow_query_log がONにならへん。ログのパスを /var/log/mysql-slow.log とかにしててapparmorさんにブロックされてたのが原因やったんですが、 sudo apt-get purge apparmor するとなぜかmysqlが起動しなくなって泣きそうになる。

どうしようもなくなったのでインスタンス消してテンプレートからデプロイし直すも、なぜかストレージのprovisioningが15分経っても終わらず、さすがにおかしいと思ってやり直したらすんなり通った。

そして、もしかしてapparmor消さんでも /var/log/mysql/ のディレクトリの中にログ出せばいけるんちゃうんと思ったらその通りであっさり解決。多分これで2時間ぐらいロスした上に、その時点でmysql(というかhtmlify以外)は全くボトルネックになってなかったから全然やる必要なかった。これはもうほんまに申し訳ない。

そうこうしてる間に他の二人がhtmlifyとisutar周りを改修して17,000点台ぐらいになってましたが、上位との差はかなり開いててhtmlifyをやっつけんことにはどうにもならん状態は変わらず。ようやく自分もその辺のロジックをなんとかできんもんかと取り掛かり出しました。

ローカルのDocker環境でいじろうとするも、どうやら文字コード問題にぶつかっててredisにsetしてgetすると文字列が変わっちゃってる問題にはまりまともにデバッグできず。macに直でruby入れてやってた二人は特に問題なかったらしいので、早めに諦めてそっちに切り替えた方がよかった。

途中masterブランチでfdのlimitにぶつかったりしてたのでそこらへんはちまちま直しつつ、最高スコアは19,000点台でhtmlifyの解決策が見いだせないまま残り30分。

これもうキャッシュするしかないんちゃうって話しつつ、トップページの10エントリー×7,000キーワードで平均1秒ぐらいかかってるから、INSERT/DELETEの時にキャッシュ作り直したら7,000エントリー×7,000キーワードでPOST全然終わらへんのちゃう？って(なぜか勘違いして)なって、redis化の範囲をちょっと広げるぐらいの修正を着手するもやりきれずにタイムアップ。

反省

KEEP

• 事前準備のデプロイスクリプトはめっちゃよかった。
• 三種の神器の用意やローカル環境など、滑り出しは去年よりかなり向上した（ slow_query_log 以外）。

PROBLEM & TRY

• 何と言ってもapparmorさんの対応をミスった。去年で存在はわかってたから初手で無効にする手順を確立しておけばよかった。
• htmlifyをやっつけるまで余計なことをせずに全員でかかるべきやった。
• ベンチ1回ごとのプロファイルを見るためにデプロイスクリプトで各ログファイルを消してたが、「もっかい今のmasterのログ見たいからデプロイしてベンチ流します」みたいなのが多発してたので、削除せずに退避するように変更する
• tagomorisさんの記事にあったalpがよさそうなのでkataribeの代わりに試してみる

まとめ

htmlifyのキャッシュ処理そのものは冷静に時間取ってやればできたよねっていうのがその後の反省飲みでもあったので、1つのことに没頭しすぎず、定期的に手を止めてこれ今やるべきやっけっていう確認をみんなでしあうのが大事かなあと思いました。時間決めて30分に1回とかやってもよかったかも。

何はともあれ、悔しすぎてこのまま終われないので、来年こそは予選突破できるようにまたしっかり復習しようと思います。