ISUCON5の予選を徹底的に復習する

ISUCON5の予選に参加して、圧倒的な差で負けたので、 この悔しさをバネに復習して、自分の力にしたいと思う。

今回のファイトではアプリの修正が特に重要であったように思う。

そこでアプリの修正に焦点を当てて、「こうすればよかった」を追っていき、自分のものとして習得したい。

とはいえ、本番とまったく同じ状況を作ることはできないので、ローカル環境でベンチマークを走らせて、簡易に得点を見ていくことにする。

ISUCON5の予選で使われたアプリのコードとベンチマークのコード、gce用のイメージはすでに公開されているのでこちらを使う。

isucon.net

なお、極力アプリの修正に集中するため、nginx.confやmy.cnfはいじらない。unicornのworker数すらいじらない。 インフラはせいぜいテーブルにインデックスを貼る程度とする。

これは、ISUCON予選本番で、やたらインフラに時間をかけてアプリの修正を怠った自分への戒めである。

なお、全作業コードはこちらで公開している。

github.com

環境準備

まずはdatabaseをdumpしてローカル環境を用意する。

gcpでSSDのインスタンスを選んでmysqldumpを実行する。このとき、gzip圧縮も行うことで、ディスクI/Oを減らす。

mysqldump isucon5q | gzip > isucon5q.sql.gz

磁気ディスクでgzipなしで実行すると、30分以上かかってしまうが、SSD+gzipだと3分ほどで終わる。

これをローカルにコピーしてdatabaseを作っておく。

mysql -u root -e 'create database isucon5q'
mysql -u root isucon5q < isucon5q.sql

これでアプリを動かすことができるようになった。 なお、アプリの言語はRubyとする。

ベンチマーク

さっそくアプリを立ち上げてみても、何がボトルネックなのかわからない。

unicornのログを設定して、レスポンスタイムを記録しておき、ベンチマークを走らせてみる。

https://github.com/ksss/isucon5q-fukusyu/commit/6534e5d614e7dfb73f72388ef3ce4270eb66ab58

ベンチマークのビルドは、ドキュメント通りにやればできた。

アプリ側

RACK_ENV=deployment bundle ex unicorn -c unicorn_config.rb

ベンチマーク側(isucon/isucon5-qualify/bench)

$ jq '.[0]' < ../webapp/script/testsets/testsets.json | gradle run -Pargs="net.isucon.isucon5q.bench.scenario.Isucon5Qualification localhost:8080"

結果

{
  "valid" : true,
  "requests" : 503,
  "elapsed" : 65528,
  "done" : "[{Isucon5InitExecutor},{BootstrapChecker},{Isucon5Load,Isucon5Load,Isucon5Load,Isucon5Load,Isucon5Checker}]",
  "responses" : {
    "success" : 367,
    "redirect" : 135,
    "failure" : 1,
    "error" : 0,
    "exception" : 0
  },
  "violations" : [ ]
}

successは1点、redirectは0.1点なので、初期スコアは大体370点ぐらいだ。

この点数はあくまでローカル環境での実行結果なので、ディスクはSSDだし、CPUも8 coreだ。

なので、これからの比較として見て欲しい。

ベンチマークの結果を見てみる。

いろいろ便利ツールはあるみたいだけど、とりあえず以下でもだいたい分かる。

$ awk '{print $11 " - - " $7}' < unicorn.log | sort -n | tail
0.6953 - - /
0.6960 - - /
0.6987 - - /
0.7006 - - /
0.7077 - - /
0.7130 - - /
0.7184 - - /
0.7193 - - /
0.7223 - - /
0.7265 - - /

なるほど、とにかく/が遅いようだ。

なお、今後も同手法でベンチマークを走らせる。

SQLログを出す

アプリのボトルネックは大体SQLだろうと決めつけ、 どんなSQLが出ているのか知りたいところ。

しかしながらmysql.cnfをいじるのはめんどくさいし、はやい順に並べたり、何本のSQLが流れているのか数えたりしたい。

そこで、mysql2-clientモンキーパッチを作った。

github.com

指定されたSQL、backtrace、実行時間を記録してためておける。これをafterフックへ導入する。

https://github.com/ksss/isucon5q-fukusyu/commit/240e4c9f702a28dcb15e680dc6f527a2c7b1e934

ログにはこう出ていた。

...
SELECT * FROM relations WHERE one = '3657' OR another = '3657' ORDER BY created_at DESC;    0.124001s
path:/  sql:1232    0.435481s
127.0.0.1 - - [12/Oct/2015:15:51:53 +0900] "GET / HTTP/1.1" 200 16637 0.7254

なるほど、全体では0.72s、SQLだけだと0.44s、1232本のSQL、一番遅いSQLまでわかった。

友達チェックを改善

一番遅いSQLは自分の友だち全てをとってくる部分だが、1232本のSQLうち、ほとんどがrelationsへのSELECTだった。 一つ一つは0.0002s程度だが、これが1000本あれば0.2sになる。 最遅SQLも含めて、SQL取得にかかるほとんどrelationsにかかっているようだった。 このrelationsを改善すれば、高速化を期待できそうだ。

問題のSQLを吐いている部分はis_friend?という、自分と相手が友達かどうか調べる部分だ。mysql2-client-general_logではbacktraceもしこんであるので、SQLの発生場所も容易に特定できる。

コードを読むと、なるほど、entriesを1000件とってきて友達じゃないものを弾く部分と、commentsを1000件とってきて友達じゃないものを弾く部分がくさいようだ。

https://github.com/ksss/isucon5q-fukusyu/blob/240e4c9f702a28dcb15e680dc6f527a2c7b1e934/app.rb#L189 https://github.com/ksss/isucon5q-fukusyu/blob/240e4c9f702a28dcb15e680dc6f527a2c7b1e934/app.rb#L197

と、ここで安易にJOINすればいいじゃんと取り組むと、ORを含んだ難しいSQLに悩まされて時間切れになった僕達のチームの二の舞いだ。

明日への教訓: 落ち着け、まわりをみろ、コメントをつけまくってもいい、コードを読め

もう少し落ち着いて周りを見ていると、気になるところが2つ見えてくる。

友達一覧はあとで取得しているところhttps://github.com/ksss/isucon5q-fukusyu/blob/240e4c9f702a28dcb15e680dc6f527a2c7b1e934/app.rb#L205-L211と、 友達を追加しているところhttps://github.com/ksss/isucon5q-fukusyu/blob/240e4c9f702a28dcb15e680dc6f527a2c7b1e934/app.rb#L361だ。

友達一覧をとっているなら、わざわざSQLをつかって友達かどうか調べる必要はない。 また、友達を追加しているところでは、one anotherに交互に自分と相手を追加する仕様になっていることが分かる。つまりは自分の友だちを調べるだけならoneだけを見ればいい。

なお、ベンチマーカーがどこまで見ているのかわからない以上、表示されるデータが変わってはいけない。 しかし、表示されるデータが変わったかどうかを知るすべがない。

ここは簡易に、出力されるHTMLを比較するという泥臭い感じでやってみる。

ただし、ベンチマークが初期値を更新してしまうようなので、ベンチマークを走らせる度にHTMLを更新しなければいけないのが難点。

ログインするアカウントを決め打って、ブラウザのコンソールからHTMLをファイルにコピペすることで比較用のデータを作っておく。

テキストのdiffを見るのには、diffyというgemが便利だった。

https://github.com/ksss/isucon5q-fukusyu/commit/ef65e442e0eedbcc3bb9f42f67a5d57e60697bea

明日への教訓: 不安は積み重なり、正常な判断ができなくなり、崩壊する。不安ならテストしろ。

これでいくらいじっても、htmlが変わったら検知できるようになった。

友達一覧情報を、以降でも流用するように改善してみる。

https://github.com/ksss/isucon5q-fukusyu/commit/26d46912fb5c6ecbf0db81edb61a325e4481ea7e

これでログは、こう変化した。

- SELECT * FROM relations WHERE one = '3657' OR another = '3657' ORDER BY created_at DESC;    0.124001s
- path:/   sql:1232    0.435481s
- 127.0.0.1 - - [12/Oct/2015:15:51:53 +0900] "GET / HTTP/1.1" 200 16637 0.7254
+ SELECT * FROM relations WHERE one = '3657' OR another = '3657' ORDER BY created_at DESC;  0.132749s
+ path:/    sql:82  0.263436s
+ 127.0.0.1 - - [12/Oct/2015:17:14:59 +0900] "GET / HTTP/1.1" 200 16637 0.4542

最遅SQLは変わらず。SQLの本数は1232->82と激減。SQL時間も、目論見通り約0.17s減。トータル時間もSQL発行毎に、オブジェクト化などのオーバーヘッドがあるのであろう、0.17sよりもさらに0.1s多い、0.27s減となった。

ベンチマークスコアは

{
  "valid" : true,
  "requests" : 712,
  "elapsed" : 67053,
  "done" : "[{Isucon5InitExecutor},{BootstrapChecker},{Isucon5Load,Isucon5Load,Isucon5Load,Isucon5Load,Isucon5Checker}]",
  "responses" : {
    "success" : 533,
    "redirect" : 178,
    "failure" : 1,
    "error" : 0,
    "exception" : 0
  },
  "violations" : [ ]
}

550点といったところ。+180点になった。

$ awk '{print $11 " - - " $7}' < unicorn.log | sort -n | tail
0.4582 - - /
0.4623 - - /
0.4657 - - /
0.4686 - - /
0.4696 - - /
0.4743 - - /
0.4748 - - /
0.4806 - - /
0.4920 - - /
0.5393 - - /

ログはこの通り。やはり、/が遅いので、引き続き/を改善していく。

友達一覧を改善

もっとも遅いSQLは以下のとおりで、0.13sもかかっている。

SELECT * FROM relations WHERE one = '3657' OR another = '3657' ORDER BY created_at DESC;

EXPLAINしてみる。

$ mysql -u root isucon5q -e 'EXPLAIN SELECT * FROM relations WHERE one = '3657' OR another = '3657' ORDER BY created_at DESC;'
+----+-------------+-----------+------+---------------+------+---------+------+--------+-----------------------------+
| id | select_type | table     | type | possible_keys | key  | key_len | ref  | rows   | Extra                       |
+----+-------------+-----------+------+---------------+------+---------+------+--------+-----------------------------+
|  1 | SIMPLE      | relations | ALL  | friendship    | NULL | NULL    | NULL | 494134 | Using where; Using filesort |
+----+-------------+-----------+------+---------------+------+---------+------+--------+-----------------------------+

どうみてもフルスキャンだ。

友達一覧を、oneだけの検索にして、oneにインデックスを貼ってみる。

https://github.com/ksss/isucon5q-fukusyu/commit/4995395b8b586f905093fa39732f7afc027242cd

mysql -u root isucon5q -e 'alter table relations add index one(one);'

ログはこうなった。

- SELECT * FROM relations WHERE one = '3657' OR another = '3657' ORDER BY created_at DESC;    0.132749s
- path:/   sql:82  0.263436s
- 127.0.0.1 - - [12/Oct/2015:17:14:59 +0900] "GET / HTTP/1.1" 200 16637 0.4542
+ SELECT user_id, owner_id, DATE(created_at) AS date, MAX(created_at) AS updated
+ FROM footprints
+ WHERE user_id = '3657'
+ GROUP BY user_id, owner_id, DATE(created_at)
+ ORDER BY updated DESC
+ LIMIT 10
+ ; 0.099964s
+ path:/    sql:82  0.132781s
+ 127.0.0.1 - - [12/Oct/2015:19:40:15 +0900] "GET / HTTP/1.1" 200 16638 0.3112

一番遅いSQLが友達一覧の取得から、あしあと一覧の取得に変わり、0.13sから0.10sに変化した。 SQL量は変わらないが、時間は約半分になっている。 全体では0.14s短縮できたようだ。

ベンチマーク結果は

{
  "valid" : true,
  "requests" : 882,
  "elapsed" : 64103,
  "done" : "[{Isucon5InitExecutor},{BootstrapChecker},{Isucon5Load,Isucon5Load,Isucon5Load,Isucon5Load,Isucon5Checker}]",
  "responses" : {
    "success" : 672,
    "redirect" : 209,
    "failure" : 1,
    "error" : 0,
    "exception" : 0
  },
  "violations" : [ ]
}

約690点。+140点となった。

遅いアクセスパスはやはり/なようだ。

$ awk '{print $11 " - - " $7}' < unicorn.log | sort -n | tail
0.3342 - - /
0.3411 - - /
0.3413 - - /
0.3459 - - /
0.3509 - - /
0.3528 - - /
0.3616 - - /
0.3667 - - /
0.3941 - - /
0.4094 - - /

あしあと調整

前回変化した最遅のSQLをEXPLAINで見てみる。

$ mysql -u root isucon5q -e 'EXPLAIN SELECT user_id, owner_id, DATE(created_at) AS date, MAX(created_at) AS updated FROM footprints WHERE user_id = '3657' GROUP BY user_id, owner_id, DATE(created_at) ORDER BY updated DESC LIMIT 10;'
+----+-------------+------------+------+---------------+------+---------+------+--------+----------------------------------------------+
| id | select_type | table      | type | possible_keys | key  | key_len | ref  | rows   | Extra                                        |
+----+-------------+------------+------+---------------+------+---------+------+--------+----------------------------------------------+
|  1 | SIMPLE      | footprints | ALL  | NULL          | NULL | NULL    | NULL | 499597 | Using where; Using temporary; Using filesort |
+----+-------------+------------+------+---------------+------+---------+------+--------+----------------------------------------------+

フルスキャンのようだ。 なれた人ならSQLをみればindexの貼りどころがわかってくるが、今回のISUCONでは磁気ディスクの遅さに悩まされ、むやみにindexをはっていると作業時間のロスになっていた。*1 ここは最小限の作業だけを行う。

mysql -u root isucon5q -e 'alter table footprints add index user_id(user_id);'

これでログはこう変化した。

- SELECT user_id, owner_id, DATE(created_at) AS date, MAX(created_at) AS updated
- FROM footprints
- WHERE user_id = '3657'
- GROUP BY user_id, owner_id, DATE(created_at)
- ORDER BY updated DESC
- LIMIT 10
- ;    0.099964s
- path:/   sql:82  0.132781s
- 127.0.0.1 - - [12/Oct/2015:19:40:15 +0900] "GET / HTTP/1.1" 200 16638 0.3112
+ SELECT * FROM entries ORDER BY created_at DESC LIMIT 1000;    0.011207s
+ path:/    sql:82  0.030177s
+ 127.0.0.1 - - [12/Oct/2015:22:51:01 +0900] "GET / HTTP/1.1" 200 16637 0.2122

最遅SQLが変化し、0.133sから0.011sにまでになった。 SQL量はインデックスを張っただけなので当然変化せず。しかしSQL時間は0.1s短縮されている。 トータルも0.1s減になった。

ベンチマークは約1070点。+380点となった。

{
  "valid" : true,
  "requests" : 1361,
  "elapsed" : 63577,
  "done" : "[{Isucon5InitExecutor},{BootstrapChecker},{Isucon5Load,Isucon5Load,Isucon5Load,Isucon5Load,Isucon5Checker}]",
  "responses" : {
    "success" : 1049,
    "redirect" : 311,
    "failure" : 1,
    "error" : 0,
    "exception" : 0
  },
  "violations" : [ ]
}

遅いのはやはり/であるのは変わらないようだ。

$ awk '{print $11 " - - " $7}' < unicorn.log | sort -n | tail
0.2187 - - /
0.2190 - - /
0.2198 - - /
0.2207 - - /
0.2209 - - /
0.2214 - - /
0.2230 - - /
0.2238 - - /
0.2323 - - /
0.2514 - - /

インデックスが終わったら？

これまでは最遅のSQLをみてindexをはってでスコアを稼いできたが、次の最遅SQLはどうみてもindexで改善しようがない。

序盤はこんな感じでSQLの改善を見ていけばよかったんだと思う。

初歩的なSQLの知識があれば、誰でも解けるような問題だった。コードも大した変更量はない。

この時点にすら自分たちはたどりつけなかったので、やはり落ち着くことが、一番の課題だったと思う。

明日への課題: 大事なことだから何回でも言う。おちつけ。

これからは中盤として、問題も難しくなっていく。

プロファイル

ここいらでプロファイルを取ってみる。

Rubyだとstackprofが有名なようだ。

https://github.com/ksss/isucon5q-fukusyu/commit/b87eba3162b858588b84e3e80c2de9c9ad73997e

これで何度かアクセスしてみてプロファイルを見てみる

$ stackprof /tmp/stackprof/stackprof-wall-*.dump --file app.rb | less

どうもこの辺りが重いようだ。

                                  |   195  |     entries_of_friends = []
 2344   (20.8%) /  2249  (20.0%)  |   196  |     db.query('SELECT * FROM entries ORDER BY created_at DESC LIMIT 1000').each do |entry|
   30    (0.3%) /    30   (0.3%)  |   197  |       next unless friends_map.key?(entry[:user_id])
                                  |   198  |       entry[:title] = entry[:body].split(/\n/).first
                                  |   199  |       entries_of_friends << entry
   16    (0.1%) /    16   (0.1%)  |   200  |       break if entries_of_friends.size >= 10
                                  |   201  |     end
                                  |   202  |
                                  |   203  |     comments_of_friends = []
 3441   (30.6%) /  2836  (25.2%)  |   204  |     db.query('SELECT * FROM comments ORDER BY created_at DESC LIMIT 1000').each do |comment|
   94    (0.8%) /    94   (0.8%)  |   205  |       next unless friends_map.key?(comment[:user_id])
  373    (3.3%) /    60   (0.5%)  |   206  |       entry = db.xquery('SELECT * FROM entries WHERE id = ?', comment[:entry_id]).first
                                  |   207  |       entry[:is_private] = (entry[:private] == 1)
   71    (0.6%) /     7   (0.1%)  |   208  |       next if entry[:is_private] && !permitted?(entry[:user_id])
                                  |   209  |       comments_of_friends << comment
    7    (0.1%) /     7   (0.1%)  |   210  |       break if comments_of_friends.size >= 10
                                  |   211  |     end

これは未だにわからないままの謎現象なのだが、下記コードはunicorn上だと遅い。

Benchmark.realtime{ db.query('SELECT * FROM comments ORDER BY created_at DESC LIMIT 1000').each{ |c| } }

単純なRackアプリを作って計測したところ、 WEBrick 1.3.1では0.011241、 unicorn 4.9.0では0.108689と10倍ほど差があった。

なんだかわからんがとにかく遅い。

unicorn以外の選択肢を持っていればさらなる検証もできたかもしれないが、ここはSQLを工夫することで回避する。

「commentsのデータが多くてオブジェクト生成に時間がかかっているのかな？」と予想を立て、下記コードを計測してみた。

commentsのcommentとcreated_atカラムをのぞいたものと、全て取得する場合だ。

db.query('SELECT id, entry_id, user_id FROM comments ORDER BY created_at DESC LIMIT 1000').each{|c| }
db.query('SELECT * FROM comments ORDER BY created_at DESC LIMIT 1000').each{|c| }

webrick

0.0032s
0.0106s

unicorn

0.0035s
0.1061s

なぜunicornがこれほど差がつくのかまったく謎なのだが、とにかく早くなるようだ。

これは流石に経験則というか、特定の言語の特定のライブラリを組み合わせたときの動作なんて覚えてられないので、ISUCONという場で思いつけたかというとかなり微妙だ。

comments.commentも、せいぜい100文字行かない程度のデータなので、「カラム数×レコード数で時間がかかる」ぐらいのことを覚えるしか無いか。

プロファイル上は、0.21sの30%なので、0.063sぐらいかかっているというあたりを付けて、修正にあたいすると判断するしかなさそうだ。

難しいぞ、ISUCON。

明日への教訓: ISUCON難しい

それではこの現象を利用して、友達チェックやらprivateチェックやらを終えた最大10件だけで再度SQLを投げてcommentを取得するようにコードを書き換える。

https://github.com/ksss/isucon5q-fukusyu/commit/57de06712e3c5adb2d838296cc0a503d2cf5a1ed

- SELECT * FROM entries ORDER BY created_at DESC LIMIT 1000; 0.011207s
- path:/    sql:82  0.030177s
- 127.0.0.1 - - [12/Oct/2015:22:51:01 +0900] "GET / HTTP/1.1" 200 16637 0.2122
+ SELECT * FROM entries ORDER BY created_at DESC LIMIT 1000;    0.012425s
+ path:/    sql:83  0.028977s
+ 127.0.0.1 - - [13/Oct/2015:10:20:44 +0900] "GET / HTTP/1.1" 200 16637 0.1352

SQLを1本増やしたのにもかかわらず、トータルで0.08s減になった。

スコアは約1400点。+330になった。

{
  "valid" : true,
  "requests" : 1774,
  "elapsed" : 63777,
  "done" : "[{Isucon5InitExecutor},{BootstrapChecker},{Isucon5Load,Isucon5Load,Isucon5Load,Isucon5Load,Isucon5Checker}]",
  "responses" : {
    "success" : 1364,
    "redirect" : 409,
    "failure" : 1,
    "error" : 0,
    "exception" : 0
  },
  "violations" : [ ]
}

/の一番遅かったときの速度改善はいまいちか？

$ awk '{print $11 " - - " $7}' < unicorn.log | sort -n | tail
0.2429 - - /
0.2431 - - /
0.2437 - - /
0.2577 - - /
0.2736 - - /
0.2760 - - /
0.2789 - - /
0.2848 - - /
0.2971 - - /
0.3371 - - /

これぐらいにボトルネックがなくなってくると、データ量に気を使う必要があるようだ。

ちなみにcommentsのuser_idにインデックスを貼って、friend_map.keysで検索することでデータ量を抑える方法もありえるが、private対策が思いつかず、結局1000件から減らせなかった。 また、entriesとJOINすると非常に遅くなってしまうなどでこれ以外の改善が思いつかなかった。

このへんも習得してパフォーマンス改善に使おうとするには「経験と勘」みたいなところの積み重ねなのかなあ。

entries改善

                                  |   195  |     entries_of_friends = []
 1427   (63.6%) /  1400  (62.4%)  |   196  |     db.query('SELECT * FROM entries ORDER BY created_at DESC LIMIT 1000').each do |entry|
   12    (0.5%) /    12   (0.5%)  |   197  |       next unless friends_map.key?(entry[:user_id])
                                  |   198  |       entry[:title] = entry[:body].split(/\n/).first
                                  |   199  |       entries_of_friends << entry
    7    (0.3%) /     7   (0.3%)  |   200  |       break if entries_of_friends.size >= 10
                                  |   201  |     end
                                  |   202  |
                                  |   203  |     comments_of_friends = []
                                  |   204  |     comment_ids = []
  123    (5.5%) /    11   (0.5%)  |   205  |     db.query('SELECT id, entry_id, user_id FROM comments ORDER BY created_at DESC LIMIT 1000').each do |comment
|
   13    (0.6%) /    13   (0.6%)  |   206  |       next unless friends_map.key?(comment[:user_id])
   68    (3.0%) /    33   (1.5%)  |   207  |       entry = db.xquery('SELECT * FROM entries WHERE id = ?', comment[:entry_id]).first
                                  |   208  |       entry[:is_private] = (entry[:private] == 1)
    9    (0.4%) /     1   (0.0%)  |   209  |       next if entry[:is_private] && !permitted?(entry[:user_id])
                                  |   210  |       comment_ids << comment[:id]
                                  |   211  |       break if comment_ids.length >= 10
                                  |   212  |     end
   30    (1.3%) /    26   (1.2%)  |   213  |     db.xquery('SELECT * FROM comments WHERE id IN (?) ORDER BY created_at DESC LIMIT 10', comment_ids).each do |comment|
                                  |   214  |       comments_of_friends << comment
                                  |   215  |       break if comments_of_friends.size >= 10
                                  |   216  |     end

commentsの改善によって、ボトルネックがentriesの取得になっているようだ。

このSQLではentries全件をcreated_at順で並べ替え、上から1000件取ってくようだ。

ここの中身はcommentsほど複雑ではないので、friends_map.keysで友達一覧をWHERE INで検索してしまい、10件に絞る。

https://github.com/ksss/isucon5q-fukusyu/commit/3bad2014b299ad6b3281fdad3fd26e933c348038

- SELECT * FROM entries ORDER BY created_at DESC LIMIT 1000; 0.012425s
- path:/    sql:83  0.028977s
- 127.0.0.1 - - [13/Oct/2015:10:20:44 +0900] "GET / HTTP/1.1" 200 16637 0.1352
+ SELECT user_id, owner_id, DATE(created_at) AS date, MAX(created_at) AS updated
+ FROM footprints
+ WHERE user_id = '3657'
+ GROUP BY user_id, owner_id, DATE(created_at)
+ ORDER BY updated DESC
+ LIMIT 10
+ ; 0.002886s
+ path:/    sql:83  0.018291s
+ 127.0.0.1 - - [13/Oct/2015:17:31:10 +0900] "GET / HTTP/1.1" 200 16638 0.0498

トータルで0.05s。さらに0.08s減となった。

スコアは2280点。+880点とかなり上昇した。

{
  "valid" : true,
  "requests" : 2872,
  "elapsed" : 63524,
  "done" : "[{Isucon5InitExecutor},{BootstrapChecker},{Isucon5Load,Isucon5Load,Isucon5Load,Isucon5Load,Isucon5Checker}]",
  "responses" : {
    "success" : 2223,
    "redirect" : 648,
    "failure" : 1,
    "error" : 0,
    "exception" : 0
  },
  "violations" : [ ]
}

遅いパスも/ではなく、/friendsに移行。

$ awk '{print $11 " - - " $7}' < unicorn.log | sort -n | tail
0.1808 - - /friends
0.1808 - - /friends
0.1822 - - /friends
0.1852 - - /friends
0.1871 - - /friends
0.1872 - - /friends
0.1918 - - /friends
0.1924 - - /friends
0.2095 - - /friends
0.2468 - - /friends

では次に/friendsを改善と行きたいところだが、これ以降も似たような手順で改善していけるだろう。

SQL改善が終わればもう後半戦。ここからは未知の領域だが、これまででかなり復習できたんじゃないだろうか。

落ち着いてボトルネックに一つづつ対処していく。経験を積めば、ボトルネックが先読みできて、分担作業ができる。

まとめ

ISUCON5予選の「こうすればよかった」を振り返ってみた。

2本のalterとわずかな実装の修正で/は/friendsよりはやくなった。

もちろん十分に時間をかけて探っていった修正なので、本番では間に合わなかっただろう。

次に似たようなことが起こったとき、対処をおもいつける冷静さと、今回の僅かな経験がいつか役に立つ日が来るかもしれない。

本線突破勢にとっては「これからが予選問題の本番」というような内容だったかもしれないが、

しっかりと基礎を見なおしてから先に進みたいと思う。

明日への教訓をまとめてみよう。

一つ 落ち着け

一つ 不安は積み重なり、正常な判断ができなくなり、崩壊する。不安ならテストしろ。

一つ とにかく落ち着け

一つ ISUCON難い

良い問題をありがとうございました！ISUCON最高でした！

参考資料

出題担当のkamipoさんによる解説。 非常にためになるので、今回の復習と合わせて習得したい。

isucon.net

ベンチマークは紹介されているとおりに動いて素晴らしかった。 リモートマシンに対して行えば、社内でISUCONの復習会みたいなこともできるかもしれない。

isucon.net

*1:SSDインスタンスでインデックスはったイメージだけつかって磁気ディスクインスタンスに載せ換えるというウルトラCを実行したチームもいる。さすがだ。。。