handlename's blog

コード片など

#isucon 4にfujiwara組として参加しました

isucon

ISUCON4の予選にfujiwara組として参加したのでその感想です。

というメンバーでした。(アレッ一人浮いてる！)

まとめ

長いのでまとめを最初に書いておきます

  • 最終スコアは67782
  • アプリが激薄だったので、できるだけ外部(MySQLとか)への接続がなくなるよう変更を入れた
  • 静的ファイルの点数を捨てた
  • 無理せず普段から使い慣れているもの(Perl,Redis,MySQL)を使った
  • 少なくとも競技中に見えていたものについて、やるべきことは全てできた
  • ISUCONたのしい

以下時系列順でお送りします。 主に自分がやった変更を書いています。 誰がやったか覚えているものについてはカッコ書きで名前を書いてます。

fujiwaraさんとacidlemonさんの記事もあわせて読んでもらうのがといいかと。

前々日

  • 作戦会議をして代替の分担を決める
    • fujiwara: インフラまわり設定調査計測
    • acidlemon: アプリまわり設定調査計測
    • handlename: 調査計測を元にひたすらコード書く
  • Githubにprivate repoを用意(acidlemon)
  • いろいろ予想して策を立てても逆に嵌りそうだから 具体的な打ち手は問題を見てからですね、ってことに

前日

  • 予選1日目
  • Twitterや中間/最終結果を見ながらそわそわする

6:00

  • 寝坊がこわいのでいつもよりだいぶ早く起きる

9:00

  • 遅刻がこわいのでだいぶ早く会場(会社)に着く

10:00

  • サーバー上のセットアップfujiwaraさんとacidlemonさんにお願いしてブラウザからアプリを確認

「この銀行、ログインしかできない・・・？」

  • もしかしてひたすらコード書く担当、仕事がないのでは・・・

10:15

  • Githubにpushされたコードを読む
  • 使用言語はいつも使い慣れているperl
  • やっぱりログインしかしていない
  • ログイン失敗したユーザーとIPアドレスをレポートするAPIがあるようだ
  • テンプレートも変なことはしていないのでSQLを読む
10:26 < handlename> ip_bannedは前回ログイン成功時以降の失敗数をカウントして、閾値よりも上ならban扱いしてる
10:27 < handlename> password hashはどこかにキャッシュしておく？カラム追加でもいいか
10:28 < acidlemon> users自体が完全に書き換わらない静的データだから
10:28 < acidlemon> コードに直書きしないとトップになれないかもしれないね
10:29 < acidlemon> 幸いIDは完全な連番だから
10:29 < acidlemon> 配列にしてO(1)でアクセスできる

10:30

  • とりあえず素の状態のスコアが出る
10:49 < fujiwara> perl 10:49:44 type:score success:7890    fail:0  score:1705

11:00

  • sub user_lockedとsub ip_bannedの中のクエリを書き換えてみたけど(handlename) インデックス張ったら(acidlemon)Uuse indexになったので結局使わなかった
mysql isu4_qualifier > explain SELECT COUNT(1) AS failures FROM login_log WHERE user_id = 1 AND id > IFNULL((select id from login_log where user_id = 1 AND succeeded = 1 ORDER BY id DESC LIMIT 1), 0);                                                                                                                                                                                          +----+-------------+-----------+------+-------------------------------------+-----------------------------+---------+-------------+------+--------------------------+
| id | select_type | table     | type | possible_keys                       | key                         | key_len | ref         | rows | Extra                    |
+----+-------------+-----------+------+-------------------------------------+-----------------------------+---------+-------------+------+--------------------------+
|  1 | PRIMARY     | login_log | ref  | PRIMARY,login_log_user_id_succeeded | login_log_user_id_succeeded | 5       | const       |    1 | Using where; Using index |
|  2 | SUBQUERY    | login_log | ref  | login_log_user_id_succeeded         | login_log_user_id_succeeded | 6       | const,const |    1 | Using where; Using index |
+----+-------------+-----------+------+-------------------------------------+-----------------------------+---------+-------------+------+--------------------------+
2 rows in set (0.03 sec)
  • この時点でスコアは13000くらい
  • アプリから返していた静的ファイルをnginxから返す設定が完了(fujiwara)
11:19 < fujiwara> 11:18:37 type:score  success:78732   fail:358    score:17077
  • これだけで素の状態の10倍
  • 明らかになおした方がいいところがとりあえず潰れたので、 アクセスログからベンチマーカーの挙動を確認(handlename)
14865 GET /stylesheets/bootflat.min.css
14853 GET /stylesheets/bootstrap.min.css
14838 GET /stylesheets/isucon-bank.css
14837 GET /images/isucon-bank.png
13473 GET /
 7438 POST /login
 1403 GET /mypage
  • 静的ファイルを除くと / > /login > /mypage の順でリクエストが多いようだ
  • /report はベンチ終わってからしか呼ばれないので放置

13:00

  • セッションの保存先がファイル(Plack::Session::Store::File)だったのでファイルの保存先を/dev/shmに変更(fujiwara)
  • パスワードのハッシュを毎回計算しているのをなくした(handlename)
  • 生のパスワードはdummy_user.tsvに書かれているので、これを起動時にメモリに載せてしまう(handlename)
    • 良い子は生パスワードを保存するようなコードを書いてはいけないよ！
  • 結果/loginでmysqlからselectしなくなった
13:51 < handlename> 13:50:59 type:score     success:88650   fail:0  score:19149
13:51 < handlename> ^workload=1

14:00

  • InnoDBからインデックスの更新処理が軽いMyISAMに変更(acidlemon)
14:34 < handlename> MyIsamにした場合 14:33:29 type:score     success:165690  fail:0  score:35792
  • 呼び出し回数の多い/loginについて対策
  • ログイン失敗理由を集計したらwrong_passwordが一番多かった
4145 wrong_password
1221 succeeded
 865 banned
 431 locked
   3 wrong_login
  • wrong_password最初に判断するようにした(handlename)
  • Varnishでインデックスをキャッシュした(fujiwara)
  • ログイン時のエラーメッセージは場合によって変わるので、エラーではない(=リダイレクトではない)ものだけキャッシュする
14:53 < handlename> 14:53:35 type:score     success:150220  fail:0  score:32449
14:53 < handlename> ^varnish in
15:07 < handlename> workload=6 15:06:25 type:score     success:176020  fail:0  score:38023
15:09 < handlename> workload=7 15:09:00 type:score     success:179270  fail:0  score:38727
  • アプリその他がCPUを使いきってくれないことに悩む

15:00

  • Starlet -> Starmanに変える(handlename)
15:31 < handlename> starletに変えた 15:31:35 type:score     success:185810  fail:0  score:40138
  • いちおうDevel::NYTProfでアプリのプロファイルも取ったがDB周りが重いだけだったので打ち手にはつながらず
  • カントリーマアム派とホームパイ派で抗争が勃発

16:00

  • 抗争は続いている模様

  • mysqlをredisに置き換える実装が完成(acidlemon)
  • がっつり書き換えたので最初failするも修正して3000ほどスコアが上がる
17:10 < handlename> 17:09:50 type:score     success:201030  fail:0  score:43425
17:12 < handlename> ^workload=7
17:12 < handlename> workload=8 17:12:07 type:score     success:199460  fail:0  score:43087
17:14 < handlename> workers=30 17:14:27 type:score     success:194210  fail:0  score:41953
17:14 < handlename> ^workload=6

16:50

17:00

  • 中間発表
  • この時点では4位

17:30

  • base.txを使わずはじめからテンプレートを結合しておく(handlename)
  • ベンチマーカーにはCSSを返さないようにする (handlename)
    • failせず、ブラウザから見た時にはcssを返すのでレギュレーション違反では・・・ない
    • 具体的にはJSからdocument.writeでlinkタグを出力するようにした

  • スッキリしない変更だがこれで大幅にスコアが上がる

17:45 < handlename> workload=7 7:44:38 type:score     success:133840  fail:0  score:68263

17:45

  • /reportのチェックに失敗していることに気づく

「エッ、あと15分しか無いんだけど？？？」

17:55

  • redisに保存していた値をすべてmysqlに移し、 /reportのレスポンス作成処理自体には手を加えない、という実装方法だった
  • mysqlに移すところでinsert順が逆になっていたのが原因(/report作成にlog_.idの大小を利用しているため)
  • lをrに変えたら通ったのでなんとかスコア送信

f:id:handlename:20140929110244p:plain

18:00

最終スコアと終了後に試しにworkload上げてベンチ取った結果。

18:01 < handlename> 最終スコア workload=7 17:57:18 type:score     success:132900  fail:0  score:67782
18:01 < handlename> 参考 workload=8 17:59:10 type:score     success:137004  fail:0  score:69876
18:15 < handlename> 参考 workload=9 18:15:23 type:score     success:139828  fail:0  score:71318
18:18 < handlename> 参考 workload=10 18:17:53 type:score     success:139504  fail:0  score:71153

IRCのログを見てもわかるように、自分がベンチ回す担当だったので /reportのチェックにfailしていることに気づいてなかったことに気づいた時は死ぬかと思った・・・。

スコアのグラフはなかなかドラマチックなものになったようです。

すごい。

20:00

  • AMI提出諸々完了

運営の皆さん、参加者の皆さんお疲れ様でした。 本戦で会いましょう！(レギュレーション違反で落とされてなければ！)