あいつの日誌β

働きながら旅しています。

ISUCON4 予選に参加して身の程を教えて頂きました

ISUCON

感想

第4回目にして初参加しました。

まあ知っていたつもりでしたが、思い知りましたね。

身の程っていうやつを。

参加した理由

実はインフラ周りの知識に自信ないので興味ありましたが躊躇していました。

ただ第3回に参加した人達のブログを読んでみた印象だと予選だったらインフラの知識がない自分でも十分楽しめる内容だと感じました。

というわけで自分の能力値を知る為に参加する事にしました。

参加する前に準備した事

推測するな、計測せよっていう話なので一応 nginx のログを ltsv に出力してそのログをパースして各リクエストにかかった合計時間、平均時間、回数を集計するスクリプトだけ用意しました。

あと得意言語は Perl と Node.js のどちらかなのですが DB が MongoDB でもない限りPerl を使う事に決めていました。

ちなみに得点は気にせずにとにかく「アプリをよく見て妥当なデータ構造にする」ことを目標にしました。

本番開始

10:00

いきなり AWS のインスタンスの作り方がよくわからない問題。 見本の画面がどこに表示されているかを探しまわる。

10:30

なんとか作業を開始する。 最初から起動しているアプリは Nginx + MySQL + Ruby でした。

前述のスクリプトを使って計測しましたが今回のお題に役立つかどうか微妙な感じでした。ほとんど POST /login に問題があるようです。GET /report は合計で18秒ほどかかっていますがこれ1回しかリクエストされてない模様。

$ make time
sudo cat /var/log/nginx/ap.access.log | perl /home/isucon/webapp/perl/analyze_log.pl
50.4599999999999 POST /login HTTP/1.1 302
18.822 GET /report HTTP/1.1 200
4.262 GET /mypage HTTP/1.1 200
1.29899999999997 GET /stylesheets/bootstrap.min.css HTTP/1.1 200
1.29699999999997 GET /images/isucon-bank.png HTTP/1.1 200
1.28599999999997 GET /stylesheets/bootflat.min.css HTTP/1.1 200
1.25799999999998 GET /stylesheets/isucon-bank.css HTTP/1.1 200
1.13599999999999 GET / HTTP/1.1 200
0.001 GET /mypage HTTP/1.1 302

$ make average
sudo cat /var/log/nginx/ap.access.log | perl /home/isucon/webapp/perl/analyze_log.pl average
18.9505 GET /report HTTP/1.1 200
0.0629177057356607 POST /login HTTP/1.1 302
0.025830303030303 GET /mypage HTTP/1.1 200
0.001 GET /mypage HTTP/1.1 302
0.000810861423220955 GET /stylesheets/bootstrap.min.css HTTP/1.1 200
0.000809612983770269 GET /images/isucon-bank.png HTTP/1.1 200
0.000802746566791493 GET /stylesheets/bootflat.min.css HTTP/1.1 200
0.000788341429562794 GET / HTTP/1.1 200
0.000785268414481882 GET /stylesheets/isucon-bank.css HTTP/1.1 200

このスクリプトは結局あまり使いませんでした...

とりあえず　Ruby から Perl に変更したり Makefile からコマンドを実行できるように色々調整しました。

時間はあっという間に過ぎて行く...

11:00

やっとアプリを見て回る。とりあえず以下の箇所が改善ポイントと認識。 login_log というデータをしつこく fetch しているので今回のポイントはここを改修するものだと理解しました。

  • last_login
  • user_locked
  • ip_banned
  • banned_ips
  • locked_users

そしてクエリが複雑すぎて難儀しました。とりあえず何をやっているかを把握しようと思い、ソースコード内にこの処理は何をやっているのかをコメントを書いてまわる。一回昼食をとり、リフレッシュしてから処理を確認してコメントが正しいかをチェックしようと思いました。

※このやり方は私がよく仕事で使っている時間差による一人コードレビューです。

11:30

お昼休み

12:30

とりあえず状況把握につとめる。 要件と実装方法を確認し改修を行う。

13:00

sub last_login {} を修正開始。最初はこんな感じです。

  • あるユーザーで前回ログインした時間とIPを表示する
  • login_log からそのユーザーがログインに成功した直近2件を取得し最後から2番目のレコードを取得している

以下のように users に直接持たせて login_log を fetch させないようにする。

$self->db->query(
  'UPDATE users SET ' .
  'last_login_at = current_login_at,' .
  'current_login_at = NOW(),' .
  'last_login_ip = current_login_ip,' .
  'current_login_ip = ? ' .
  'where id = ?'
  , $ip, $user_id
);

そして SQL のスキーマを追加します。

alter table users add column current_login_at datetime NOT NULL;
alter table users add column last_login_at datetime NOT NULL;
alter table users add column current_login_ip varchar(255) DEFAULT '';
alter table users add column last_login_ip varchar(255) DEFAULT '';

が、実はこれベンチマークのチェックには引っかかりませんでしたが間違えています。

後一つ足りない作業があります。

今思い起こせばもうこの時点は私は敗北していました(ずいぶん早い)

14:00

私は悩んでいました。以下の処理についてです。

POST / の処理

  • user_locked
  • login_log から最後にログイン成功したレコードを fetch

  • 取得したレコード移行で一定回数以上ログイン失敗しているかを判定

  • ip_banned

  • login_log から最後にログイン成功したレコードを fetch
  • 取得したレコード移行で一定回数以上ログイン失敗しているかを判定

GET /report の処理

  • banned_ips
  • login_log から過去一度もログインに成功しておらず一定回数を超えてログイン失敗している IPs を fetch
  • さらに最後にログインに成功した IPs とその login_log.id 一覧を取得
  • それらを都度 最後にログイン成功してid 以降に作成されたログイン失敗ログが一定件数あるかを調べる
  • これを合わせて banned_ips とする

locked_users も大体一緒の処理

14:30

とりあえず一番目につくのは succeeded というカーディナリティが低い値。とりあえずこれを検索条件に入れなくて済む方法を考える。

1つ目

まず、今回の要件として banned_ips も locked_users も解除される事はない。 なので失敗した回数をどこかに保存しておき、一定値を超えた場合はマッピングテーブルを用意してあげればよい。たぶんこれが最速、作業コスト一番かかる。

failure_counter, banned_ips, locked_users というテーブルを定義する感じ？

2つ目

succeeded　というカーディナリを見なくて済む様に failure_login_log という失敗した時専用のテーブルを用意する。成功したログを見る時に succeeded というフラグを見る必要があるので全レコードを取得する事になるが負荷は抑える事ができ作業コストそんなにかからない。

failuer_login_log というテーブルを追加する

結論

2を選択。2はどこのコードを修正すればいいのか見通しがついているけど1はまだ設計に自信がないし、おそらく時間がかかるだろうからひとまず2を実装。その後で1を検討する

15:00

failure_login_log を追加して login_log に失敗したらログを記述するように追加実装しまいた。これでちょっと負荷が低くなったはず。

正直この時点でちょっと調子に乗ってましたね。

「あれ、俺結構いけるんじゃね？」

とかいい気分でコードかいてましたね。ええ。

「もしかしたらサーバーの設定とかやったら結構ベンチのスピード出るんじゃね？」

とか欲が出てましたね。

でベンチはかったら 7000 ぐらいだったんですよ。

workload を2に上げたら 10000 超えたりとか。

やっぱり数値があがると燃えますよね。

ありのままに僕がつぶやいた発言を書きますとこんな感じです。

「やべーな。これまだまだいけんじゃね？やべーな！」

でもね。なぜか点数が全然反映されてないんですよ。

16:00

原因は banned_ips と locked_users が想定した値と違ってまして、その場合は減点されるどころか点数を送信してくれない仕組みだったようです。

というわけでここから先はもうずっとコードをにらめっこして悩みました。

17:00

原因が分からないままテンパる

「あ、もしかしてアレがコレでナニがソレなんじゃ...」

そして迷宮へ...

17:50

もう何がなんだか分からないので追加した実装をロールバックしてがむしゃらに 送信。もう送信できれば何でもいいです。

試合終了。

惨敗

という訳で結果は惨敗でした。

なお fail している理由は failure_login_log を追加した後。そのテーブルが空っぽのままでした。 初期化スクリプトを実行した段階で loign_log には ban された ip や user が既に存在しているのでデータが不整合のままになっていました。

つまり、こんな感じの処理を初期化スクリプトに入れておけばよかった訳です。

INSERT INTO failure_login_log(log_id, login, user_id, ip) SELECT id, login, user_id, ip FROM login_log  WHERE succeeded=0 ORDER BY id;

最初に last_login のデータをユーザーに持たせた時にチェックに引っかからなかったのはおそらくベンチツールが文字列が表示されているかどうかを確認していて値が妥当かどうかは見てないからかな？

感想

運営の皆様お疲れ様でした。初めて参加させて頂きましたが大変面白かったです。こんなに楽しいなら最初の回から出場しておけば良かったと思うぐらい楽しかったです。

毎日夜遅くまで頑張ってれた感が伝わるクオリティの課題でした。 またやって下さると嬉しいです。ありがとうございました。