ISUCON6予選敗退しました
ISUCON4、ISUCON5 に引き続き今年も出場しました。 今回は会社の同僚で ramen(@futoase, @kompiro, @foostan) というチームを組んで挑みました。
最終ベンチ結果は 75786 点で、残念ながら決勝には進めませんでしたがいい線まで行けたのでいい気分でした。 ただ手詰まり感はなくまだまだできることは沢山あっただけに、「あれを入れられていれば！」「最初のトラブルがなければ！」という感じで、めちゃめちゃ悔しいので来年またリベンジします。
進め方
大まかには
- 環境整備（Azureのテンプレート展開、GitHubにコードアップロードなど）
- Ruby実装でベンチ回せるようにする（systemd まわり設定変更、ログ周り整備）
- ログを見てボトルネックを探す
- ミドルウェア or アプリケーションに手を入れる -> 3. に戻る
のような流れでやってました。 なるべく憶測でミドルウェアの変更やアプリケーションの修正はやらないように心がけていました。
各修正をするときは普段と同じように、
- PR 出す
- レビューしてもらう
- マージ + デプロイ
のようにやってログが残るようにしました。
あとは各人が何やってるか管理するために、GitHubで最近リリースされた Projects を使ってました。
これのお陰で手詰まり感なく進められたと思います。
やったこと
初回ベンチ結果
スコアは 0
Nginxのログは
で確認して以下のような結果でした(一部抜粋)。
+-------+-------+--------+---------+-------+-------+-------+--------+--------+------------+------------+--------------+------------+--------+--------------------------------------------+ | COUNT | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) | METHOD | URI | +-------+-------+--------+---------+-------+-------+-------+--------+--------+------------+------------+--------------+------------+--------+--------------------------------------------+ | 89 | 1.868 | 15.001 | 620.085 | 6.967 | 1.868 | 6.607 | 14.999 | 2.660 | 40334.000 | 97658.000 | 4618988.000 | 51898.742 | GET | /? | | 300 | 0.001 | 7.362 | 415.725 | 1.386 | 0.001 | 0.574 | 7.208 | 1.831 | 106015.000 | 106015.000 | 31592470.000 | 105308.233 | GET | /css/bootstrap.min.css? | | 151 | 0.001 | 7.279 | 207.954 | 1.377 | 0.001 | 0.566 | 7.150 | 1.827 | 28631.000 | 28631.000 | 4266019.000 | 28251.781 | GET | /js/bootstrap.min.js? | | 151 | 0.001 | 7.280 | 207.929 | 1.377 | 0.000 | 0.565 | 7.152 | 1.827 | 86351.000 | 86351.000 | 12866299.000 | 85207.278 | GET | /js/jquery.min.js? | | 151 | 0.001 | 7.363 | 207.895 | 1.377 | 0.000 | 0.564 | 7.150 | 1.828 | 16849.000 | 16849.000 | 2510501.000 | 16625.834 | GET | /css/bootstrap-responsive.min.css? | | 150 | 0.001 | 7.280 | 207.768 | 1.385 | 0.001 | 0.574 | 7.149 | 1.830 | 1092.000 | 1092.000 | 163800.000 | 1092.000 | GET | /favicon.ico? | | 151 | 0.001 | 7.279 | 207.447 | 1.374 | 0.000 | 0.565 | 7.149 | 1.827 | 93.000 | 93.000 | 13857.000 | 91.768 | GET | /img/star.gif? | | 108 | 0.002 | 3.005 | 167.237 | 1.548 | 0.002 | 1.453 | 3.000 | 1.190 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /login? | | 51 | 0.057 | 3.001 | 77.722 | 1.524 | 0.057 | 0.733 | 3.001 | 1.248 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /keyword? | | 77 | 0.002 | 3.001 | 74.842 | 0.972 | 0.002 | 0.446 | 3.001 | 1.002 | 0.000 | 15.000 | 930.000 | 12.078 | POST | /stars?keyword=xxx&user=xxx | | 6 | 6.288 | 12.375 | 52.078 | 8.680 | 6.288 | 7.498 | 11.426 | 2.380 | 48060.000 | 98688.000 | 371377.000 | 61896.167 | GET | /?page=xxx | | 4 | 1.149 | 4.965 | 11.376 | 2.844 | 1.149 | 1.617 | 3.645 | 1.543 | 2905.000 | 2905.000 | 11620.000 | 2905.000 | GET | /keyword/トイズ? | | 2 | 2.984 | 7.202 | 10.186 | 5.093 | 2.984 | 2.984 | 2.984 | 2.109 | 9770.000 | 9772.000 | 19542.000 | 9771.000 | GET | /keyword/135 (バンド)? | | 4 | 1.123 | 3.662 | 9.942 | 2.486 | 1.123 | 2.403 | 2.754 | 0.911 | 9596.000 | 9596.000 | 38384.000 | 9596.000 | GET | /keyword/菅山かおる? | | 4 | 1.336 | 3.694 | 9.679 | 2.420 | 1.336 | 1.627 | 3.022 | 0.973 | 3572.000 | 3578.000 | 14300.000 | 3575.000 | GET | /keyword/南蟹谷村? |
- GET /
- アセット系
- POST /login
- POST /keyword
- POST /stars
- GET /keyword
あたり目立っていたので、上の方から手分けして見ていきました。
アセット系どうにかする
とりあえずさくっとできるので Nginx で静的ファイル関連の設定(gzip、キャッシュ、try_filesなど)入れました。 で、ベンチ回してみて alp にかけてみたら、下記のようになったのでOK。
+-------+-------+--------+---------+-------+-------+-------+--------+--------+-----------+-----------+------------+-----------+--------+----------------------------------------------+ | COUNT | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) | METHOD | URI | +-------+-------+--------+---------+-------+-------+-------+--------+--------+-----------+-----------+------------+-----------+--------+----------------------------------------------+ | 41 | 2.510 | 13.175 | 335.050 | 8.172 | 2.510 | 7.506 | 13.034 | 2.780 | 13319.000 | 26088.000 | 684031.000 | 16683.683 | GET | /? | ~~ 省略 ~~ | 162 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 17089.000 | 34178.000 | 210.975 | GET | /css/bootstrap.min.css? | | 81 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 1092.000 | 1092.000 | 13.481 | GET | /favicon.ico? | | 81 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 7580.000 | 7580.000 | 93.580 | GET | /js/bootstrap.min.js? | | 81 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 4010.000 | 4010.000 | 49.506 | GET | /css/bootstrap-responsive.min.css? | | 81 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 124.000 | 124.000 | 1.531 | GET | /img/star.gif? | | 81 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 30083.000 | 30083.000 | 371.395 | GET | /js/jquery.min.js? | +-------+-------+--------+---------+-------+-------+-------+--------+--------+-----------+-----------+------------+-----------+--------+----------------------------------------------+
ちなみにスコアは 0 のままです。
スコア0の原因を探る
アプリの改修は2人におまかせして、とりあえずスコア0の原因を探ってました。
Nginxのログを見たらPOSTリクエストに対して 499 がやたら出ててなんだろこれ、って思って詳しく見たら、request_time みたら 2.9 ~ 3 秒ぐらいになっていて、upstream_response_time が空白になってました。
あーそうだと思ってレギュレーション見たら、POSTリクエストは3秒以内に返さないと強制的に切られることになっていて、スコアの計算式みたらPOSTリクエストが失敗したときの減点が大きく設定されていたので、スコア0になってるんだなってことがわかりました。
ちなみに 15:00ぐらいまでずっとスコア0 でまじで生きてる心地しなかったです。 alp の結果見て確かに速くなっていることは実感しつつも、ベンチちゃんと通っているかどうかがずっと不安でした。
htmlify 高速化
htmlify が遅いことは明らかでここをとにかく速くしようとしてました。 初期のコードは下記のとおり。
def htmlify(content) keywords = db.xquery(%| select * from entry order by character_length(keyword) desc |) pattern = keywords.map {|k| Regexp.escape(k[:keyword]) }.join('|') kw2hash = {} hashed_content = content.gsub(/(#{pattern})/) {|m| matched_keyword = $1 "isuda_#{Digest::SHA1.hexdigest(matched_keyword)}".tap do |hash| kw2hash[matched_keyword] = hash end } escaped_content = Rack::Utils.escape_html(hashed_content) kw2hash.each do |(keyword, hash)| keyword_url = url("/keyword/#{Rack::Utils.escape_path(keyword)}") anchor = '<a href="%s">%s</a>' % [keyword_url, Rack::Utils.escape_html(keyword)] escaped_content.gsub!(hash, anchor) end escaped_content.gsub(/\n/, "<br />\n") end
愚直にコメントアウトしつつどこがどれだけ時間かかっているか見てみて、
keywords = db.xquery(%| select * from entry order by character_length(keyword) desc |)
と
hashed_content = content.gsub(/(#{pattern})/) {|m|
がボトルネックになってました。
クエリ改修
keywords 取ってくるクエリは、確認したら keyword しか使ってなかったので
keywords = db.xquery(%| select keyword from entry order by character_length(keyword) desc |)
にしたら、1秒ぐらい速くなってスコアが4桁ぐらい出るようになって、ちょっとホッとしました(やっとここからかと)。
全キャッシュ
正規表現部分、速くする方法が全く思いつかなかったのでとりあえず htmlify 全部キャッシュしてみるかと思って、
受け取った content からハッシュ値計算して、それをキーにして、escaped_content を redis に突っ込むようにしました。
これで劇的にスコアが伸びて4万ぐらいまで行きました。 ただこの方法だとキーワード更新されたときに意図しないレスポンスを返してしまうので、適宜キャッシュをクリアする必要がありました。 が、時間間に合わずその対応はいれられず。
ulimit 変更
各人の修正いれつつスコアが伸びて来たところで、Too many open files のエラーが頻発してスコアが再び0になりました。
あー ulimit 変更しなきゃねって思って、/etc/security/limits.conf の設定変更しても結果は変わらず。
結局プロセスの ulimit 変更しないとだめで Nginx の設定で worker_rlimit_nofile を追加して解決しました。
最終結果
スコアは前述したとおり 75786。 alp の結果は
+-------+-------+-------+---------+-------+-------+-------+-------+--------+-----------+-----------+--------------+-----------+--------+--------------------------------------------------------------------------------+ | COUNT | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) | METHOD | URI | +-------+-------+-------+---------+-------+-------+-------+-------+--------+-----------+-----------+--------------+-----------+--------+--------------------------------------------------------------------------------+ | 4908 | 0.009 | 3.396 | 864.290 | 0.176 | 0.031 | 0.103 | 1.051 | 0.213 | 5389.000 | 34605.000 | 75946956.000 | 15474.115 | GET | /? | | 1386 | 0.028 | 2.485 | 254.207 | 0.183 | 0.040 | 0.141 | 0.810 | 0.153 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /keyword? | | 2803 | 0.000 | 2.504 | 248.836 | 0.089 | 0.006 | 0.065 | 0.420 | 0.108 | 0.000 | 0.000 | 0.000 | 0.000 | POST | /login? | | 1033 | 0.008 | 2.526 | 143.528 | 0.139 | 0.032 | 0.103 | 0.610 | 0.135 | 6911.000 | 43855.000 | 19112584.000 | 18502.017 | GET | /?page=xxx | | 241 | 0.001 | 0.692 | 20.419 | 0.085 | 0.001 | 0.066 | 0.300 | 0.074 | 0.000 | 0.000 | 0.000 | 0.000 | GET | /logout? | | 7634 | 0.001 | 0.092 | 11.982 | 0.002 | 0.000 | 0.001 | 0.009 | 0.002 | 0.000 | 15.000 | 104100.000 | 13.636 | POST | /stars?keyword=xxx&user=xxx | | 1 | 3.842 | 3.842 | 3.842 | 3.842 | 3.842 | 3.842 | 3.842 | 0.000 | 19631.000 | 19631.000 | 19631.000 | 19631.000 | GET | /keyword/郵便番号? | | 1 | 3.461 | 3.461 | 3.461 | 3.461 | 3.461 | 3.461 | 3.461 | 0.000 | 6358.000 | 6358.000 | 6358.000 | 6358.000 | GET | /keyword/東富山駅? | | 6 | 0.058 | 2.456 | 2.966 | 0.494 | 0.058 | 0.084 | 0.154 | 0.878 | 2453.000 | 2473.000 | 14742.000 | 2457.000 | GET | /keyword/小天温泉? | | 2 | 0.097 | 2.753 | 2.850 | 1.425 | 0.097 | 0.097 | 0.097 | 1.328 | 17256.000 | 17259.000 | 34515.000 | 17257.500 | GET | /keyword/浦和駅? | | 6 | 0.003 | 2.173 | 2.813 | 0.469 | 0.003 | 0.079 | 0.293 | 0.769 | 8581.000 | 8628.000 | 51540.000 | 8590.000 | GET | /keyword/ORANGE (戯曲)? | | 2 | 0.086 | 2.502 | 2.588 | 1.294 | 0.086 | 0.086 | 0.086 | 1.208 | 1618.000 | 1618.000 | 3236.000 | 1618.000 | GET | /keyword/松平乗寛? | | 1 | 2.404 | 2.404 | 2.404 | 2.404 | 2.404 | 2.404 | 2.404 | 0.000 | 12995.000 | 12995.000 | 12995.000 | 12995.000 | GET | /keyword/リック・ドム? | | 8 | 0.057 | 1.081 | 2.085 | 0.261 | 0.057 | 0.111 | 0.329 | 0.323 | 11340.000 | 11384.000 | 90813.000 | 11351.625 | GET | /keyword/人間国宝? | | 1 | 2.049 | 2.049 | 2.049 | 2.049 | 2.049 | 2.049 | 2.049 | 0.000 | 6958.000 | 6958.000 | 6958.000 | 6958.000 | GET | /keyword/北条貞顕? | | 1 | 2.033 | 2.033 | 2.033 | 2.033 | 2.033 | 2.033 | 2.033 | 0.000 | 11379.000 | 11379.000 | 11379.000 | 11379.000 | GET | /keyword/漢和辞典? | | 1 | 1.831 | 1.831 | 1.831 | 1.831 | 1.831 | 1.831 | 1.831 | 0.000 | 12027.000 | 12027.000 | 12027.000 | 12027.000 | GET | /keyword/播但線? | | 1 | 1.762 | 1.762 | 1.762 | 1.762 | 1.762 | 1.762 | 1.762 | 0.000 | 11179.000 | 11179.000 | 11179.000 | 11179.000 | GET | /keyword/東急バス淡島営業所? | | 1 | 1.732 | 1.732 | 1.732 | 1.732 | 1.732 | 1.732 | 1.732 | 0.000 | 10711.000 | 10711.000 | 10711.000 | 10711.000 | GET | /keyword/貴族院 (日本)? | | 1 | 1.722 | 1.722 | 1.722 | 1.722 | 1.722 | 1.722 | 1.722 | 0.000 | 8874.000 | 8874.000 | 8874.000 | 8874.000 | GET | /keyword/モンケ? | ~~ 省略 ~~ | 1 | 0.004 | 0.004 | 0.004 | 0.004 | 0.004 | 0.004 | 0.004 | 0.000 | 2641.000 | 2641.000 | 2641.000 | 2641.000 | GET | /keyword/マヘンドラ・ビール・ビクラム・シャハ? | | 17794 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 17089.000 | 102534.000 | 5.762 | GET | /css/bootstrap.min.css? | | 8897 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 1092.000 | 3276.000 | 0.368 | GET | /favicon.ico? | | 8897 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 124.000 | 372.000 | 0.042 | GET | /img/star.gif? | | 8897 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 7580.000 | 22740.000 | 2.556 | GET | /js/bootstrap.min.js? | | 8897 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 4010.000 | 12030.000 | 1.352 | GET | /css/bootstrap-responsive.min.css? | | 8897 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 30083.000 | 90249.000 | 10.144 | GET | /js/jquery.min.js? | +-------+-------+-------+---------+-------+-------+-------+-------+--------+-----------+-----------+--------------+-----------+--------+--------------------------------------------------------------------------------+
といった具合で avg が
- GET /: 6.98秒 -> 0.18秒
- アセット系 1~2秒 -> 0.00秒
- POST /login: 1.55秒 -> 0.10秒
- POST /keyword: 1.52秒 -> 0.18秒
- POST /stars: 0.97秒 -> 0.00秒
- GET /keyword: 1~9秒 -> 0.1 ~ 3.84秒
かなり改善されました。 まだ GET /keyword のどこかがボトルネックになってますね。
その他やったこと
上で挙げたこと以外に
- isuda と isutar の統合
- istarからisudaへの不要なHTTPアクセス排除
- クエリ改善
- DB設定見直し
とかやってました。
反省点とか
GitHubのProjectsの使い勝手が良くて次にやるべきこととか確認するのに役立ってよかったけど、一つ一つのタスク消化するのに時間かかり過ぎたなって印象でした。 個人的にはコード見る時間が全然足りなくて、結局すべては把握できずに終わりました。 あとから見返すとあきらかなN+1とかあって、まだまだできること沢山あったなって感じでした。
ログ見つつボトルネックのところを潰していくって戦略は有効だったので良かったですね。
次回は予選突破するぞ！
最後に
今年のISUCONも楽しませて頂きました！ 運営の皆様、ありがとうございました 🙏🙏🙏
