2014/09/29

#isucon 2014にfujiwara組で出場して予選2日目暫定1位を取りました

どうもこんにちは、れもんです。今年もISUCONの季節がやってきましたね。昨年はfujiwaraさんの右腕として出題業をやりまして、今年はそのままfujiwara組として予選に出場しました。

結果は既報の通りですが、ひとまず2日目で暫定1位のスコアを出しています。67782です。では問題の感想とかやったことを振り返っていきます。あ、長いのでマジメに読んだら読むのにたぶん10分くらいかかりますよ。

また、チームメンバーのfujiwara, handlenameのブログも出そろいましたのでそちらも合わせてお読みください。

• #isucon 4に参加して予選2日目暫定1位になりました (@fujiwara)
• #isucon 4にfujiwara組として参加しました (@handlename)

前日まで

金曜日のお昼にチームでランチして分担を確認。fujiwaraさんが「今回は実装が速そうなhandlenameにコードをバリバリ書いてもらう、自分はインフラの調整、れもんさんは…なんかアプリの速くなりそうなところとかを探してhandlenameに実装箇所を指示」という号令をだして分担が決定。

うーんでもなんかそれだとオレ全然手を動かさなくてヒマそうだなぁということで、Twitter担当に立候補しました。

当日 10:00〜 開始早々の爆上げ

10時に開始してfujiwaraさんにインスタンス立てていつものchefを回してもらっている間にgithubへソースコード一式をpushして中身を読み始めました。前日にmirakuiさんの書いたperlということでなんかざわついていましたが、特におかしいようなところもなくまぁ普通にKossy + DBIx::Sunnyだねぇという感じでした。perlの初期スコアは1700くらい。昨年もこのぐらいだったのでこんなもんですね。

一通りソースを読み終わった感想としては、「えっ、アプリの中身これだけ?」というのが正直なところで、エンドポイントが3つ + 最後の検証用の/reportしかなかったので逆にこれでアプリをどう高速化すればいいのか…と戸惑ったというのが正直な所です。早かれ遅かれ他の参加者の人もそうおもったのではないでしょうか。

とりあえず10時半の時点でINDEXが1個もないからまずはINDEXからだねということで、貼るべきインデックスを3個列挙して、fujiwaraさんの準備完了を待ちます。

10:31:37 acidlemon: まずはる必要があるINDEXが
10:31:55 acidlemon: usersの `login`
10:32:10 acidlemon: login_logの`ip`
10:32:53 acidlemon: login_logの`user_id`
10:33:20 acidlemon: ああ
10:33:28 acidlemon: `ip`と`user_id`は
10:33:52 acidlemon: それぞれ(`ip`, `succeeded`)と(`user_id`, `succeeded`) の複合キーでよいな
10:34:33 acidlemon: banned_ipsとlocked_usersはINDEX効いてなくても1分以内におわるだろうからスルー

今回は最初からnginxということで、静的ファイルをnginxから返すため設定もすぐに完了して、こっちもschema.sqlにINDEXの3つ書き込んでせーのでまとめてベンチを取ったら11:20の時点で一気にスコアが10倍になって17000点が出ました。この時点でまだworkloadは1です。

えっ、ちょっと上がりすぎじゃない? となってmysqldumpslowでクエリのボトルネックを探してみると、もうこれ以上クエリをチューニングする必要がない(トータルでDBが1秒も時間食ってない)ことがわかりました。結局今回はDB周りはINDEXの追加のみでクエリやテーブル構造の変更はナシで最後まで行っています。

あとは、静的配信は必須とはいえ各施策の効果を確認するべく静的配信やめてINDEXだけの効果を測定(13000点くらい)したりしたところでこれ以上は基礎的なインフラチューニングは効かないと判断し、さっさとworkloadをあげてCPUを使い切っていくことにしました。workload=3で12時の時点で28000点くらいです。

ここまでに簡単にハマった罠といえば、nginx.confにmime.typesの設定がなくて静的ファイルをnginxで捌いたらCSSがかからなくて真っ白になったくらいです。あとは例によってローカルポートが枯渇しましたが、これはもうISUCONでは頻出なのでいつもの通りに対策を行っています。

12:00〜 あとから効きそうな細かい改善を地道にやる

さてこれでもうアプリ側はどうしようもなくなったので、ここからしばらくスコアが停滞します。細かいところでサーバサイドでファイルに保存しているセッションストアの保存先が/tmpとなっており、これは普通のMagnetic Diskなのでtmpfsの/dev/shmに変更してちょっとだけスコアアップ。ここのところはあとでもうちょっと手が入ります。

とにかくworkloadをあげてもCPUのidleがなくならないため、ここからはアプリの処理をどんどんチマチマと削るしかないねということで、SQL発行をガンガン撲滅する方向で進めました。

まず余計にクエリを飛ばしているところがあるのでそれを削除します。具体的には /mypageでの$self->current_userの呼び出しです。これは基本的に user_idがセッションからとれていれば $userを引く必要はないため削除しました。

今回のお題はユーザがサインアップしないためusersテーブルは不変であり、これをオンメモリに載せないことにはオンメモリ勢を越えて予選通過確定ラインを取ることはできないだろうという判断からなりふり構ってられんということでこれを全部オンメモリに載せました。

具体的にはユーザ名(login)をキーにしてuser_idと生passwordを引けるハッシュをprefork前に作るという感じです。なりふり構わんということでsha256のチェックもはぶいて生passwordの一致だけを見るようにしました。これでログインするときにusersをSELECTしなくなりました。これで大体30000くらいです。

あと、唯一のINSERTであるlogin_logへのINSERTですが、これが1msも食っててログインするたびに1msも食っていては今回の勝負には勝てないということで、少しでも高速化するためにEngineをMyISAMへ変更。こころなしかスコアがちょっとだけ上がりました。

アプリの改善はちょっと詰まってしまい、気分転換にGoのコードを読んだところ、なんとGoはセッションストアがサーバ側のファイルストアじゃなくてmartiniのCookieストア(クライアントストア)を使っていました。なんだそれ出題言語でセッションストアの形式が違うじゃねぇかコノヤロウということでさっそくPlack::Middleware::Session::Cookieに入れ替えをやりました。これもそこそこ効果があり1000点くらいは増えています。

なかなかスコアが安定しなかったですが、ここらへんの変更をやってスコアが37000くらいになりました。このときには既に2位のrapidチームに抜かれており、まだMySQLにアクセスしてるし相手がオンメモリとかだと太刀打ちできないかなぁみたいなムードはちょっとありました。

その頃、fujiwaraさんはというと、ポート枯渇周りの根本的な対策としてkeepaliveの設定をチューニングしたり、ベンチマークワーカーのアクセスパターンの解析をやっていました。ベンチマークとnginxの間をkeepalive有効にしてもポートが枯渇するので、ソースポートを調べたりしたところ、どうやらgoのベンチマーククライアントは1個のgoroutineでトップページから始めて規定の順番でページを辿っていき、最後までいったら接続を破棄して終わり、コネクションの再利用はしていないというような作りになっていると推測できたので、ローカルポートはじゃんじゃん枯渇していくのはしかたないということがわかりました。

このルーチンは高速化すると1サイクルが1秒以内(0.1秒とか)で終わってしまうので、ポートのリサイクルやらエフェメラルポートの範囲を増やすやらnginx-upstream間をkeepaliveするなどの対策をやってポート枯渇問題に手を打っています。また、ベンチマークのアクセスパターンを解析した結果、トップページはreferer付きとrefererなしの2パターンあるということで、refererなしのときだけ静的に返してやる、というのもやりました。

refererなしのときはベンチマークがルーチンの最初にトップページにアクセスするときなので、flashのメッセージはないのでフロントから固定のHTMLを返せます。refererありのときは/loginに失敗して理由がflashされてるときなので、それはそのままアプリで捌きます。ただ、nginxでどうもうまくいかなかったので柔軟にできるvarnishでやろう! ということで15時くらいまでにvarnishに入れ替えました。

15:00〜 そろそろMySQLを捨てるときがきた

さて、15時もすぎたしそろそろデカいアプリの改造をやるならそろそろ決断しなきゃならないですね、ということで、/loginでDBにINSERTするのをやめて代わりにRedisのlistに入れ、最後にreportのタイミングでまとめてINSERTしてから/reportの処理を行うという大改造をやることにしました。usersが既にオンメモリになっていたためこれをやると実質的に負荷走行中はMySQLにアクセスが行かなくなります。

単にlogin_logを入れるだけなら簡単ですが、その他にもIPとユーザIDのBANチェックが必要なため、Redisにそれ用のキーも用意してfailure:user:%d と failure:ip:%s でログインの失敗をincrし、成功したら0をセットしてリセットするという処理をかきました。それぞれのBANチェックではfailureのカウントがthresholdを越えていないかを見るように変更します。

20分くらいでRedisの書き換えがだいたい終わり、15:40にコミットしようとしたときに、cartonのlocalフォルダまわりでMacとLinuxでゴタゴタあったのでいちどlocalを元に戻してgitから外すみたいな作業をした際にうっかりgit checkout .と打ってせっかくRedis対応にしたソースコードを完全に飛ばしてしまいました。

まぁでも1度書いたやつだからあとは脳内写経だよね、16時までに何とかすると宣言して無事16時までにアプリのコードは作業完了しました。ちなみに、2回目書いたときもうっかりgit checkout . localと打ってしまって無慈悲にもろもろの変更をうっかり吹っ飛ばしましたが、2回目はgit checkoutで吹っ飛ばす前に先にgit commitしたので助かりました。ホント落ちつけオレ。

その頃fujiwaraさんとhandlenameは少しでもアプリのCPU時間を削るためにプロファイラを取っていて、いろいろ調べた結果どうやらアプリにはもう高速化できそうな余地がなくてDBアクセスを無くすしかないということがわかり、やはりRedisに逃がす実装をする方向で正解ということの確認ができたところでした。あと、StarmanをStarletにしたらちょっとスコアがあがり、15:40の時点でスコアが40000点に載りました。

さて、アプリのコードは書き終わったものの、初期データには7万件くらいのlogin_logが既にあり、IP-BANとユーザID-BANのための失敗カウントがinit.shのタイミングですべてRedisに用意されていないとベンチマークは通りません。あんまりコードを新規に書く時間はないのでPerlの実装のIP-BANチェック部とユーザIDチェック部をそのままコピペして10600IPアドレスと200000ユーザIDの合計210600回のクエリを回してinit.shでRedisに載せようとしました。

が、ちゃんと計算するとそれを60秒のinit.shの制限時間内に実現するには1秒間に3500クエリほど投げないと行けないのでそれは非常に厳しいです。ということで、初期データから手元で作ったRedisをdumpしてrdbファイルにして、init.shではredis-serverを止めてrdbファイルを初期化用rdbで上書きし、上げなおすということで対応しました。rdbファイル自体は5MBくらいですので、これなら1分以内にinit.shを終わらせるのは余裕です。

16:00〜 Redis実装のデバッグと調整

が、30分で作ったRedis移植がそんなすぐ動くわけもなくゴリゴリとデバッグを開始。実はこの展開、ISUCON2の時にも同じことをやってたんですよ。当時はそもそもWeb業界にきて半年というところでRedisの取り扱いはおろかPerlの取り扱いもままならないということで、大失敗に終わっています。が! さすがにあれから2年経ってるからぼくもそんなしょぼいレベルでとどまっていないので、ここから怒濤のデバッグをやり、実装漏れとバグ修正を16:55までにこなしてスコアが43000くらいになりました。

あとは /reportの調整ですが、/reportの内容をRedisから作ろうとするとそれはもう泥沼になることが見えています。なので、あくまでもRedisの上に作ったlogin_logのリストはDBへの遅延書き込みのためのキャッシュという位置づけにして、/reportが呼ばれたタイミングでRedisからlrangeでそこまでのログを全部取得してINSERTし、リストを空にするという実装にしました。これをやったあとにBANリスト作成のメソッドを呼べば、BANリスト作成のためのSQLなどは全く変更が要らないのでこれで実装時間を節約しています。

17:00〜 いろんな奥の手

まぁRedis作戦が完了しただけで結局はあんまりあがらなかったのですが、まだケチケチして実は上げれる余地はあるだろうと思っていました。そもそもISUCONというのはベンチマークツールをいかに高速に回すかという勝負なのですが、100msかかっていたモノを99msにしてもスコアは1%しかあがらないですが、2msかかっていたモノを1msにすると同じ1msの短縮でもスコア自体は2倍になるんですね。つまり、最後まで打てる手をすべて打ってCPU時間をケチりまくればまだ十数パーセントはあがるだろうと思っていました。

ということで、ぼくはRedisまわりの落穂拾いをしてコードをクリーンアップしつつ、handlenameに幾つか指令をだしていきました。

まず1個目がbase.txの排除です。Perlの実装はbase.txにレイアウトが書いてあってそれをindex.txとmypage.txがそれぞれcascadeして展開するという形になっていました。が、既にアプリが1ms以下のレベルまで高速になっているのでbase.txを展開するコストを省いたほうがよいだろうということで、base.txの中身をindex.txとmypage.txに直接展開してもらいました。これだけでもスコアが50000越えたので、地味に効果があります。

もう1個は、お昼過ぎにネタとして上がってたけど試すの忘れてたやつで、HTMLからCSSの参照の<link>を消して試しにベンチ回してみるというやつでした。この時点ではベンチマークがCPUを180%ほど使っていて、なおかつworkloadとアプリのworker数を上げてもコンテキストスイッチが多すぎてCPUを全部使い切れていないことが判明しており、まぁRedisにしてもあんまりかわらないだろうなという予想はしていました。

だとすると、あとはベンチマーク側がうまいこと高スコアなリクエストを捌いてくれるように静的ファイルの配信を何とか減らす方向にできないかということを試していきます。午後にベンチマークのアクセスパターンをチェックしたときにどうやらHTML読んでそれに含まれるCSSを次に読むというような挙動をしていたので試しにレイアウト崩れ覚悟でCSSを全部はずしてみたところ、スコアが急上昇。

そりゃそうですよね、0.01点しか入らないスコアのリクエストを減らせば1点リクエストがたくさん捌けるようになるのでスコアも上がります。てかそれFAILしないんかいという気もしましたが、まぁベンチマークが通るんだからやるしかない。

どのぐらいこれが効いたかというと、

17:09:50 type:score     success:201030  fail:0  score:43425
  ↓
17:44:38 type:score     success:133840  fail:0  score:68263

という感じで、successの数(すべてのリクエスト数)がガッツリさがってスコアはあがるという結果になっています。

あとは見た目を変えないというアナログなレギュレーションがあり、見た目のレギュレーションは人間がブラウザで確認するものであり、その際にJavascriptがオンの状態を前提にしてよいことを運営チームに確認したのでdocument.writeで<link>を元の場所に追加するということで見た目をそのままに静的なCSS参照を削る形で最終スコアまでいきました。

17:45〜 実はまだ終わっていなかった

これでやることは全部やったので、ひとまずこのスコアを送ろうか〜ということで上述の17:44のスコアを送ったはずだったのですが、どうもポータルに反映されていない。おかしいねー問い合わせようかーと思ったらhandlenameが /report のチェックがコケてfailしていることを見逃していて、一同顔面蒼白。

どうやらworkloadを1にしてもreportが通らないのでrace condition系のバグではなさそうということが17:49にわかり、あーもうこりゃダメだわーってあきらめかけたのですが、handlenameが/reportの遅延INSERTの順番がおかしいと/reportの内容がおかしくなる可能性があることを指摘しました。

ぼくの実装ではlpushで左から入れたものをで取り出して順番にINSERTしていたのですが、実はRedisのlistとか実務でほぼ使わないのでよーわからんという感じでここは割とノリで実装した感じでした。fujiwaraが「lpushで入れたモノをlrangeで0から取り出したらLIFOで出てくる」ということをビシッと指摘したので、よし! ならば逆からリストに入れるようにすればいけるはずだな! もしそれでダメだったらぼくの実装が根本的にダメなのでセップクしようということでlpushをrpushに1文字修正してすぐベンチ回して通るか確認だー! と17:55からworkload=1でテスト走行。

/reportのチェックがいつもよりも長く感じてやきもきしましたが、これが通ったのですぐworkload=7で計測してスコアを送信し、最終スコアの17:57:18 type:score success:132900 fail:0 score:67782を送信しました。

ということで、終了3分前に1位を奪還して予選2日目は終了しました。

18:00〜 AMIの作成

さて、怒濤の駆け込みとなってしまい18時の時点では3人とも変な興奮状態および急激な脱力感に襲われましたが、AMIを作らないと飲みにいけないのでそこはfujiwaraさんにお任せしました。

ココでやらなきゃならないのは再起動レギュレーションの確認です。AMI作ってベンチ走らせて、最後に/reportを叩いて保存しておいて、再起動してもう一度/reportを叩いて同じ内容のJSONが帰ってくることの確認ですね。ぼくの実装ではlogin_logは/reportを叩いたらRedisからMySQLに全部書き出してしまい、レポートはMySQLから作ってるのであんまりその辺でトラブルになるようなことはありませんでした。

あと、BANの情報も保全されている必要がありますが、redis-serverでconfigにsaveする設定をしておけば普通に再起動時にrdbを更新してデータは保全されるのでそこも問題なしでした。まぁ電源断とかされるとさすがにbgsaveが走った後の未書き込みのRedisのデータは飛んでしまいますが、今回はそこまで求められていないので大丈夫でしょう。

ちなみに/reportの結果は複数回実行するとbanned_ipsとlocked_usersのキーの順番が入れ替わることはある(hash-randomizationがあり、キーの順番が常に同じ事までは保証できない)ので、MD5レベルでは一致しないこともありますが、中身のデータが論理的に一致している(各キーの値の配列自体は一致している)ところまでは確認しました。

まだAMIの審査が終わってないのであんまりワッショイワッショイと喜べないですが、ひとまずこのままいけば本戦に進めそうなスコアは残せましたので、その点では一安心です。今年も引き続き運営をしている941さん、出題のクックパッドさん、楽しい時間をありがとうございました。