ISUCON5出場者の皆様、先週の予選はおつかれさまでした！僕らは予選敗退でした。
僕は「忠で焼酎を飲んでいた人たち」として、 @sugamasao (エントリ「ISUCON5の予選で爆散してきた – すがブロ」) と @ariarijp (エントリ「ISUCON5予選に参加しました – ariarijp’s blog」) の二人と参加しました。二人のエントリと重なる部分もありますが、せっかくですのでエントリを残します。
チーム「忠で焼酎を飲んでいた人たち」です！ #ISUCON pic.twitter.com/Kw7aE8S9h1
— Yuichiro SAITO (@koemu) September 26, 2015
チーム名の「忠」というのは、僕の行きつけの焼酎バー「美酒家 忠」にて、このメンバーで飲んでいたことに由来します。
本エントリは、「事前の話」「当日の話」そして「感想」の3つに分けてお話しします。また、予選中のソースコードは GitHub sugamasao/isucon-2015-yosen-app に保存してあります。
事前の話
メンバーの分担は、 @sugamasao がRubyまわり、 @ariarijp が状況の棚卸し、僕 @koemu はOS〜ミドルウェアの面倒を見ることにしていました。ただ、後半は全員コードを触っていました。
測定ツールは、僕が pt-query-digest, mysqltuner.pl, kataribe (@matsuuさん作 Webサーバログ分析ツール)を用意しました。また、 @sugamasao が peek-rblineprof を使うよう用意してくれました。これらツール群で問題なく分析を進めることができました。
事前準備ですが、 @sugamasao が前回参加時の経験談まとめを作ってくれたおかげで、僕を含めた初参加の2人の作業見通しが立てやすかったのは良かったです。この情報がなければ、前半はもっと手間取っていたかもしれません。
当日の話
さて、当日の状況をざくっと、タイムラインにまとめてみました。一部省略しています。
時刻 点数 内容 ------- ------- ---------------------------------------------------------------------------------- 11:00 開始 (1時間順延) 11:53 210 (FAIL) ほぼ初期状態, スクショ取得, 現状確認 12:43 766 秘伝のタレ投入(mysql, kernel), nginx 1.9.5へ, Unicornプロセスx4 13:16 2188 mysqltuner→チューニング, index作成, Unicornへの通信をsocketに変更 13:37 2032 スタティックファイルはnginxで直接取り扱い 14:06 2106 ログイン失敗ページはスタティック化, nginx gzip on 14:31 2335 DB接続をsocket化 15:14 1974 MySQLのtmpとinnodb logを`/dev/shm`へ, スタティックページ化推進, N+1処理をJOINにまとめた 15:39 1277 トップページのSQLにSQL_CACHEを有効化, N+1の対策推進 15:47 1292 N+1の対策推進 16:41 1640 友人関係は片系統のみ参照, N+1の対策推進 17:21 3119 MySQLテーブルキャッシュサイズ, InnoDB tmp_table_size, query_cache_size変更 17:43 15458 友人関係のデータ元をmemcached変更, トップページ処理にバグ混入(そのためスコアが異常に良い) 18:06 4565 各種バグ修正 18:48 ？ memcachedの接続をsocketに変更, ログOFF, Unicornプロセスx6 18:58 ？ 再起動試験完了 19:00 ？ 終了
特に、後半はプロファイリングの結果をもとに3人がメソッド毎にプログラムを修正することに時間を注ぎました。
さて、今回のISUCON5で僕に残った課題は次の5つです。
- 過度のN+1対策でパフォーマンスが落ちる見切りを付けるのが遅かった
- memcachedのsocket待ち受け設定を忘れる失敗をした
- AppArmorにはまる
- バグによる高スコアをしでかした
- 作業ログがまとめづらかった
1は、トップページの応答秒数が落ち始めているのにも関わらず「SQLのチューニングにまだ工夫ができるのでは」と深追いしすぎたところにありました。 @ariarijp さんに「こえむさん、遅くなってるから元に戻しませんか？」と言われた時に、「ウッ」となって遅れたのはものすごく反省しています。もし、もう少し早く切り上げていたら、友人関係情報とユーザの情報をオンメモりにすることができてスコアもあげられたはずです。
2は、僕のmemcachedの設定の失敗です。リバースプロキシなどの設定では適切にsocketに切り替えることができたのに、慌てていて見落としました。これもスコアに影響するものです。慌てるとろくなことがありません。
3は、MySQLの一時ディレクトリを`/dev/shm`に切り替える際にAppArmorの設定にはまって起動しない問題に遭遇してしまいました。これは知っているか知っていないかの問題だったので、Ubuntuが採用されるとわかっていた段階で事前に確かめておけたと反省しています。
4は、社内のISUCONでもやってしまったのですが、ベンチマークプログラムのチェックをかいくぐるようなバグを出してしまったために、異常な高スコアをたたき出してしまう問題を作ってしまいました。これは、事前に保存していた各画面のスクリーンショットをもとに確認することができました。バグとわかった以上、このまま出すのは自分たちの信義に反するため、直すこととしました。
5は、Slackでcommitログや作業ログをまとめていたのですが、いまいちわかりづらい状況でした。次回以降、スコアの状況も含めて、わかりやすくまとめる工夫を模索する必要がありそうでした。
逆に、できたなーって所は次の3つです。
- 秘伝のタレ投入が初期段階でできた
- ログ解析ツールを問題なく使えた
- チーム一人一人が分担をして結果を出す活動ができた
秘伝のタレ投入タイミングは、YAPC::Asia Tokyo 2015で @kazeburo さんに質問して聞いた話でした。確かに、最初のタイミングで充分でした。ありがとうございました！
感想
本戦出場者のみなさんのエントリを読んでいると、「コードの見切り」と「判断」のタイミングに差があるんだなと痛感しました。自分は慌てたり、所々筋が悪い判断・作業をやっていて、そこで時間をロスしてしまったのは大きな反省点です。普段やっていることしか当日はできないものですね。
そういえば、バグとは言え15000点越えをした時に「俺らにもワンチャンあるで！！！」と3人で盛り上がれただけでも良かったです(笑)。時々、ランキングに顔も出せましたし。一矢報いることはできたと思っております。
問題は、 @tagomoris さんたちの運営担当者入魂の総合力が試される問題でした。単にJOINするだけだととんでもない行数がJOINされたりなど、一筋縄ではいかない難しさがありました。運営の皆様、大変お世話になりました。どうもありがとうございました！
また、自宅で参加していたのですが、うちの相方には昼飯を用意してもらったり、コーヒーを淹れてもらったりと最高のISUCONプレー環境を用意してもらったのには感謝しています。どうもありがとう！
そして、一緒にプレーできた @sugamasao と @ariarijp にはとても感謝しています。素晴らしいチームでした！どうもありがとう〜 🙂
ということで、ブログを書いたので僕のISUCONはこれで終わりです。本戦出場者の皆様、がんばって〜♪