おそらくはそれさえも平凡な日々

Kayacのエンジニア3人 @fujiwara @sugyan @songmu の3人でチームfujiwara組を結成し、結果優勝することができました。

実際は周りの認識通り、@fujiwaraさんに優勝させてもらったようなもので、@sugyanと僕は手を動かしていただけです。まあ、空気にならずには済んだので、そこは安堵しています。

修正したisuconソースはフォークしてGithubに置きました。プログラムの修正部分のみで、my.cnfの修正なんかはここには反映されていません。

さて、@fujiwaraのコンテストでの動きや、帰宅後のBlogアップまであらゆる仕事が速くてビビるんですけど、詳しくは、#isucon で優勝してきましたを見てもらうとして、

• どういうドタバタがあったのか
• アプリの修正点とか
• @fujiwara的には当たり前ですっ飛ばしてるけど僕には勉強になったこと

みたいなことを書きたいと思います。結果としては圧勝みたいになっていますが、かなり危うい部分や、苦肉の策なんかがあります。

事前作戦会議とか

前日のランチで軽く雑談。

とはいえ話したのは、「リバースプロキシはnginxにするでしょう」「memcachedはどこかで活用するんでしょうね」くらいの話。あんま変なモノは使わず、使い慣れている環境を使いましょう。あとは出たとこ勝負という話。

当日の役割分担

当日の役割分担は自然と決まって、作戦決定とOS・ミドルウェアの設定周りを@fujiwaraが担当して、それに従って@sugyanと僕が手を動かすという感じになりました。

初期設定とか 11:30-

まずはSSH周りの設定。authorized_keysにそれぞれ自分の鍵書き込んだり、hostnameの設定したり。rev(リバースプロキシ)を踏み台にして、他のサーバーに入る方針。

あとは、revにもアプリが入っていたので、そこでgit init。by @sugyan。それをローカルに落としてきて開発ってつもりだったんだけど、最後はサーバー上で開発になってました。

デプロイに関しては、revからappサーバー2台に、rsync -> SSHリモートコマンドでsupervisord再起動 みたいな簡単なシェルを書いた。(簡単なとか言いつつ、結構調べちゃいましたけどね！) by 僕

@fujiwara 組長にhostname等の設定をしてもらっている間に、アプリをざっと眺める。シンプルで綺麗。生DBIでテンプレートもxslate。こりゃPerlモジュールレベルじゃ全然高速化の余地はないなと、自分が空気にならないか心配になる。

PerlはSystem Perl。置き換えても良いかもしれないけど、他にやることはあるでしょう。MySQLが5.5だったのはスゲー意外。4.0とか覚悟してたんだけどw

チャットは社内IRC。チャンネル作ることも考えたけど、普段使っているチャンネルに。そっちのほうが社内の他のエンジニアへの実況になって面白いかな、とも。

最初の計測 12:30-

各サーバーでtop回しながらベンチマークスクリプト走らせる。まずは何はともあれこれ。スコアは800/min程度。

MySQLがネックになっていることが判明したので、今度はクエリログ眺めながらベンチマーク。そこでサイドバーを作るために発行している以下のSQLがネックになっていることが判明。

SELECT a.id, a.title FROM comment c INNER JOIN article a ON c.article = a.id GROUP BY a.id ORDER BY MAX(c.created_at) DESC LIMIT 10

クエリキャッシュを有効にしても焼け石に水で、1200/minくらいに向上したのみ。ただ、クエリキャッシュを適切に有効にしたことは、後々スキーマ変更した後のクエリ効率には貢献したので、もちろん有効な施策ではありました。

アプリ修正開始 13:00-

とりあえず、サイドバーが曲者だなってことで、まだ具体的な方針は決定はしていないものの、サイドバーの生成で上記クエリが走らないように、POST時にサイドバーの配列情報をmemcachedに突っ込んでしまうように先行して@sugyanがプログラムを修正することに。

で、よくよく考えたら、articleにlast_commented_atカラム追加すればjoinの必要なくなるしindexも張れるからかなり速くなるんじゃないか、と @fujiwara が指摘し、そのアプリの修正を僕、DBのAlterやデータ修正を@fujiwaraが担当。

僕と@sugyanがアプリの修正をしている間に、どうせ使うよねってことで、revにnginxとmemcachedを@fujiwaraがさくっとインストール。nginxのmemcachedプラグインも導入。

apacheからnginxにリバースプロキシを差し替えて、ベンチをとったらまさかの500/min。これは@kazeburoの罠で、時々keep-aliveを送りつけるベンチマーククライアントがいて、そのTCP接続が残り続けるのが問題だった。これはkeep-aliveをoffにすることで解決。

静的ファイルもアプリが返していたので、それもnginxでサーブするように変更。

僕の修正部分とnginxの合わせ技でベンチを取ったら20,000/min程度まで改善。@sugyanは大掛かりなコード修正で苦戦中。

このへんで一旦お昼ごはん。

キャッシュ戦略 14:00-

この時点で、DBのボトルネックは解消。次はアプリがネックになっている。フロントでnginxのmemcachedプラグインを使うってのは既定路線でそれを如何に有効に使うか。

データがPOSTされた1秒後にGETされるので、そこで確実に高速にレスポンスを返すためにまずはPOSTされた時点でGETされるであろうコンテンツを生成してキャッシュに乗せてしまおうという戦略。@fujiwara立案。

「GETされるであろうコンテンツの生成」はちょっとめんどくさいから、素早く実装できる方法として、localhostをFurlで叩いて、そのレスポンスボディをキャシュに載せてしまおうという力業。これまた@fujiwara案。このへんの見切り判断の早さがやばい。

その辺の実装を僕が担当。nginx memcachedプラグイン設定を@fujiwara担当。

リバースプロキシのアドレスをHostヘッダに入れてやる必要があるんだけど、FurlのHostヘッダの扱いに難があって、Hostヘッダを二重につけてしまったりしてしまう。あとで@xaicronに確認したところ、やっぱFurlの罠だった。結局LWP::UserAgentを使うことに。

その辺の変更を適用してベンチをとったら30,000/min程度までスコアが改善。ここまではすこぶる順調(のように見えた)。

14:40 (fujiwara) 現在1位

15:21 (fujiwara) 少なくとも惨敗はないなw

迷走時間 15:30-

キャッシュ戦略が有効に働き、ボトルネックがフロントに徐々に移行。「後はフロントの最適化」に専念。...とおもいきや「サイドバーの罠」にかかりここから苦戦することになる。

この時点でデータのキャッシュは上記の通りPOST時だけ。それを、GET時もキャッシュしてしまおうという戦略を@fujiwaraが立案。それを僕が実装。サーバー起動時に全URLにアクセスに行き、事前にキャッシュを温めてしまうウォームアップスクリプトを@fujiwaraが作成。

実装したところスコアはかなり改善したがエラーが頻発！

このへんで@sugyanのサイドバーの配列情報をmemcachedに入れる修正ができたので、マージして当て込んだところ、少しスコアは向上したが誤差の範囲内か。しかし、memcachedにミスヒットするとフェールオーバーしない男らしい作りだったため動作が安定せず、rejectすることに。フェールオーバー周りを改良して当て込む手もあったんだろうけど、残り時間の関係と、他のエラーも出てたので、問題点を絞りたかったってのが大きな理由。

この時点のエラー原因は後から振り返ってみると以下の4本。これが同時に起こったから、原因究明に苦労した。

1. アプリ自体の単純なバグ
2. アクセス増に伴うip_conntrack溢れ
3. アクセス増に伴うnginx->memcachedでのローカルポート枯渇問題
4. サイドバーの罠

3までは割とすぐ解決。@fujiwara がログを見る所が的確すぎて、原因究明が早すぎてビビる。

これで、問題完全解決とおもってベンチを走らせるも、サイドバーエラーが頻発。キャッシュをPOSTのみにするとエラーは起こらない。GETでもキャッシュさせるとエラーでベンチが通らない。

「謎だー」「DBコミットのタイミングかー」「でもオートコミットだよなー」

完全に迷走状態に。

恐るべきはサイドバーの罠 16:30-

いや、謎ではありません。以下を完全に見落としていたのです。

データがPOSTされると他のページのサイドバーも書き換わる

データPOST後の1秒後のGETだけではなく、他のランダムGETの処理でもサイドバーの整合性チェックをしていたのでベンチがコケていたのです。

考えてみればごく当たり前です。

つまりこれまで大丈夫だと思っていた、POSTの時だけキャッシュする戦略でも、GETの取られ方によってはベンチがこける可能性がある。

そもそものキャッシュ戦略が完全ではなかった

この恐るべき事実を突きつけられ、チーム内に衝撃が走ります。もう時間もない。

しかしここで、@fujiwaraの起死回生の一言がチームを救います。

「cacheに秒数付けて調整するしかないな」

それだー！苦肉の策ではありながら、時間内に出来ることはもうそれしか無い、むしろそれだけだったら十分すぎるほど時間に余裕はあります。当たり前の対策を的確なタイミングで言えるその凄さ。

懇親会で@kazeburoさんが講評前に「トップのチームはもっとフロントで捌くようにしてくると思ったけど、@fujiwara組はアプリに結構アクセスがあったのが意外だった」って言ってたって話を聞いた。

結局、上記のようにキャッシュ戦略に穴があったので、定期的にアプリに回してキャッシュを更新させるようにせざるを得なかったってのが理由です。ここはかなり出題者に負けた感があります。

秒数調整 17:00-

とりあえず、POSTのインターバルは1秒だからキャッシュの生存を1秒にしておけばほぼ安全。しかし、それだとキャッシュする意味が少なくなってしまう。他のチームのスコアを考えるともう少し冒険をしないとつらいところ。しかし、本番審査のベンチ時間は1分ではなく3分なので、その分は安全策を取らないといけない。

てことで、キャッシュの寿命を5秒に設定。ここでのベンチスコアは86,000/min! しかし、この時点のトップスコアが88,000/min程度だったので、それは上回れず。

とりあえず、100,000/minの初突破チームの特別賞狙いで、スケベ心を出してキャッシュの寿命を10秒に設定、nginxでのgzip圧縮転送等を試みるも、大して効果は出ず、96,000止まり。計測誤差範囲内。(この辺りの時間帯は各チームがベンチマークを回しまくっていたので、ベンチマークサーバーの負荷の関係か、ベンチマークのばらつきが大きかった。)

10秒でも大して効果なかったので、安全のためキャッシュ秒数を5秒に戻し。ここで、修正は凍結。あとは審査準備。

しかし実はここで僕がgit resetで "--hard"してなかったのでローカルのソースは巻き戻ってなかったというポカミスをしていた...。

願いを込めて再起動 17:30-

OS再起動後の審査スタートだったので、再起動後もちゃんとベンチが通るかどうかの確認。

ここで@fujiwaraの何気ない神の一手が発動。

おもむろに以下のようなテーブルを追加。

CREATE TABLE article_bh (
...
) Engine=blackhole;
CREATE TABLE comment_bh (
...
) Engine=blackhole;

そして、以下のSQLがOS再起動後に実行されるように設定。

INSERT INTO article_bh FROM (SELECT * FROM artcile);
INSERT INTO comment_bh FROM (SELECT * FROM comment);

うおお、なんてお手軽ウォームアップ。これでDBの内容をOSのメモリキャシュに載せるわけですね。

「memoryストレージ」みたいなことも話には出てたんだけど、まずは正攻法という哲学。

何度かベンチ回してスコア出るので大丈夫そうかな、と一安心

17:53 (songmu) 1位奪還中。後は本番勝負。

しかし間際でまさかのベンチFail。

最後の修正 17:57-

やっぱ5秒でも厳しいか、ってことで3秒に変更しようとする。しかし実は先程の記述のとおり、git上は5秒に戻してたけど、ソース上は10秒のままだったというオチ。なので、5秒に変更。

ソースを一行というか一文字変更するだけなんだけど、めちゃくちゃ焦って緊張した。ここでsyntax errorとか出したら死刑ものなので。

審査中 18:00-

周りの中間スコアを見ると、完走さえ出来れば上位には入れそうな感じだったので、なんとかベンチを完走して欲しいと願っておりました。1分完走率が8割だと、3分完走率は5分5分になってしまう。もっと成功率は高かったけど100％ではなかったので、やはり心配でした。

あとはプチ反省会。

• "/"はPOSTされるタイミングで更新されるわけだからキャッシュに乗せておけばよかった
• @sugyanのサイドバーのキャッシュはフェールオーバーをやっていれば、使えたかも
• そもそも、サイドバーの更新タイミングの違いの罠に気付くのが遅すぎた。それに早く気づいていたら違う手も打てた

審査結果発表 18:30-

先に発表された準優勝のスコアが70,000万/3minとそこまで高くないスコアだったので、内心「これはうちは審査完走できなかったのかも...」とドキドキでした。

無事に完走を遂げたらしく、270,000 over/min のスコアで優勝できました。

振り返って

ホント素晴らしいイベントでした。@fujiwara組長の仕事ぶりを目の前で見られたのは本当に大きな経験になりました。

懇親会での会話もめちゃくちゃ盛り上がりました。トークイベントとはまた違って、全員が同じ事をやっているので、話が弾む弾む。

話を聞くと、言いだしっぺの @tagomorisさんが、やりたいなーみたいなことを言い出したら、どんどん話が進んで、トロフィーまで準備されるという。エンジニアドリブンであれだけのイベントをあれだけのリソースを使って開催できるのはマジすごいと思いました。見習いたい。

あと、@tagomorisさんと自転車の話ができてよかったです。今度走りに行きましょう。