isuconに行って平凡な記録を残してきた

もう先週のことになりますが、去る8月27日にid:pekeqさんに誘われてisuconに行って平凡な記録を残してきました。
参加者はpekeqさんとrshさんと無職で暇な奴ということで私

準備編

rshさんがノリノリで高速なKVSを実装するということになった。memcachedはsocketで接続して読み書きするが、この独自KVSはshmでデータを保持する。仕組み上ホストを跨いだデータの共有が出来ないが同一ホスト内での単純なKVSとしてはこれ以上に高速な仕組みはなかなか無いだろうという見込み。
アプリはperlで記述されているとのことなので、XSで読み書きできるところまでを当日までに実装してgithubに置いておくことに。これでレギュレーションで指定された外部で公開されているアプリの利用ということになるだろうということになった。
実際、rshさんの事前の計測では同一ホストで動くmemcachedよりはXS経由でも10倍程度高速なものが完成した。急造品であるため異なるデータサイズへの対応がmemcachedよりも柔軟ではないことや、原理的にホスト間でのデータ同期が問題になるが、そこはフロントのプロキシで分離することでなんとかしようということになった。
おおまかな作業分担は、私がフロントのプロキシ、rshさんが例のKVS、pekeqさんがSQLとそれ以外。

当日編

当日は奇跡的に全員遅刻もせず会場入り
pekeqさんがisuconということでhttp://www.nhk.or.jp/kids/program/miitsuketa.html:NHKの幼児向け番組のイスのキャラ「コッシー」のおもちゃを持ち込む。「これなら投げつけても大丈夫なはずだ…」お子さんが入る家庭でないとそのネタは分からないよ!

前半戦

競技の開始と同時に各人がざっと構成を把握。
私の担当部分はApacheのmod_proxyを使った単純な構成と判明。設定の書き方もApacheとしてはかなり整理された記述で移植が楽そうであると判断した。
アプリの本体はコードを読んだ人間が口々に「こんなに短かいのか…」と呟くほどあっさりした記述。現代的なperlによるアプリケーション記法に慣れていないためのカルチャーギャップに動揺が走る。
この初期状態での測定結果は800qps程度
全員が担当パートをざっと把握したところで軽く意識合わせ。私はnginxに変更のうえ、スタティックな画像やcssなどをリバースプロキシに置くところまで作業することに。
私の担当パートであるリバースプロキシについてもApacheでの設定が簡素であったのでnginxへの移植はすぐに終った。MySQLの各種パラメータが初期状態のままであったため、更新のディスク反映を遅延させたり、クエリキャッシュを有効にしたり、バッファの量を増やしたり、トランザクションログを大きめにするといった基本的な変更を実施。
この時点で再度ベンチマークを流してみたところ1200qps程度まで上昇。隣りのチームがいきなり20000qpsを越える値を叩き出して、余裕の昼食に出たため衝撃が走る。
SQLはアプリに直書きされているものを全て列挙しても両手で数えられるほど、ほとんどは単純なキーによる検索のみであると即断できる程度のものだった。一つだけ明らかに遅くなりそうなSQLはpekeqさんは目視で発見。
記事とコメントがそれぞれ違うテーブルで保持されているのだが、このSQLは最近コメントが付いた順で記事の最新数件のタイトルを取得するというもの。コメントがつくたびに記事が上に上がってくる、スレッドフロート型の掲示板を想像するといいだろうか。
記事と対応するコメントを内部結合し、記事のidで集約、そのうち付けられた最新のコメントをMAX()で出しその降順で出力するというものだった。
これはすぐに非正規化による高速化が可能であると結論されたので、最新のコメント日付と記事のidを保持するだけのテーブルを作ってコメントが付けられると同時にそちらにも書くようにした。同じ記事への書き込みによって日付のみが更新される場合もあるのでMySQLの拡張構文'insert on duplicate key update'を使うことで簡単に書けた。
ここまでのチューニング結果を測定してみたところ21000qpsほど。一瞬ではあったが暫定2位に踊り出た

後半戦

前半は比較的順調だったのだが、後半はいろいろと酷かった。
例のキャッシュシステムの機構を色々な場所に入れてキャッシュをしてみるが一向に速くならない。データベースもリバースプロキシも最初の段階で当初想定していた変更を出し切ってしまっていたのであとは微妙なパラメータを変更する程度。
変更する都度、主催側が用意したベンチマークを走らせるのだが1分間という測定時間内に完全に作業を止めてまでそちらに専念しなかったこともあって、測定中に他のパートが設定変更したことによるfailや結果への影響が排除できなかったためどの変更がどれだけ効果があったのか(あるいは無かったのか)が判然としないまま、暗中模索が続いてしまった。
SQLの変更については別テーブル方式から記事テーブル自体にコメント時刻を持たせ、それを更新する方式に変更した。ただし、パフォーマンスはさほど変化せず。
最後にはアプリケーションがレンダリングした結果自体をキャッシュに入れることで高速に返すよう改修を実施していたのだが、それもベンチマーク側での内容チェックを抜けることが出来ず最後にはロールバックして終了。
会場のメインモニターには各チームの途中結果が表示されていたのだが、それを見る限りfujiwara組とシーサーが頭ひとつ抜けた80000qps越え。それ以降チューニングに成功したチームが70000qpsから30000qpsぐらいで第二集団を形成するといった具合。我々は第二集団の最後尾ぐらい

結果

正式には開催側から発表があると思いますが、最終結果は7位でテストが完走したチームの中では下から数えた方が速い程度

懇親会

1位と2位のチームに終了後に話を聞く機会があったのですが、1位のfujiwara組がかなりアグレッシブなキャッシュ戦略と絶妙なチューニングによって高性能とテスト完走のいずれも勝ち取ったのに対して、2位のいんふらえんじにあーは比較的正攻法のコードの最適化を重視した結果手堅い結果を残したようだった。もちろんSELinuxは有効状態で(ｷﾘｯ
最終結果ではfailだったが、シーサーもかなり高速な暫定結果を残しており恐らく手法としてはfujiwara組と近いものであったのではないかと推測される。

反省

いや、もう反省点だらけの結果であった。
ベンチマークは主催側で用意されているからと測定ツールは用意しなかったのだが、やはり1分間かかる測定できっちりと意味のある結果を測定できなかったため色々と裏目に出てしまった。仮に自前の測定ツールを作ったところで例のkeepaliveや内容チェックの罠を再現しないまま適当なテストをしてしまい逆にあさっての方向へ改修をしてしまう可能性もあった。事実、ウォームアップ用のスクリプトを使って簡易的にレスポンスを測っているときにはどんどん結果が良くなっていたので気を良くしてコスい変更をいろいろとしてしまった。そして、それが裏目裏目に出た結果、自己最高記録さえも上回れない最終結果となってしまった。
作業のやり方という点では、普段一緒に仕事をしているわけではない3名だったため、作業の進め方も意識を合わせられなかった。ホワイトボードとはいわなくとも、紙のノート1冊でも有ればそれにタスクリストを作ってチェックしながら進めることができただろう。
skypeチャットなりIRCなりで各人の作業を小まめに共有していれば、ベンチマーク中の作業中断ももっとスムーズにできただろう。
測定の1分間を毎時05分からと決めて、次の測定までに行なう変更を明確にするといったチェックポイントを作ったほうが効率的だっただろう。
あとは、アプリケーションのボトルネック調査を適当にしてしまったこと。10倍速いキャッシュもキャッシュがネックになっている局面に正しく投入しないと効果が無いということだ。今回の測定内容からするとキャッシュを効果的に入れることがかなり難しく、それを突破できたかが勝敗の別れ目になった感がある。Livedoor社内での事前実施で好成績を残した方の手法はコンテンツの性質に応じて適切な粒度でキャッシュをし、その有効期間を管理するというものだった。
後知恵ではあるが、リバースプロキシでのSSIもmemcachedの利用も競技中に検討しないではなかったのだが、アプリへ手を入れる工数を考えると採用に踏み切れなかった。この辺は普段からperlで手を動かしている人との差が顕著に出てしまったと考える

最後に

isuconという非常に刺激的な場を提供くださったLivedoorの皆様には大変感謝しております。機材や場所といったリソースはもちろん、競技用のコードの準備といった人的リソースは多大なものであったと想像致します。