ISUCON13 お疲れ様でした！ 今年も「都営三田線東急目黒線直通急行日吉行」というチームで参加しました。 チーム編成は 7 年連続(?)同じメンバーで、0gajun と izumin の 3 人チームでした。
最終スコア 227,377 点からの fail という猛烈に悔しい結果に終わりました…！！ ISUCON11は本戦出場からの本戦で3位相当スコアを取りながらfailしたのですが、今回も全く同じで3位相当のスコアを取りながらまたしてもfailしてしまいました…
実はISUCON12予選もギリギリ本戦行けるかどうか微妙なラインで結局failするという結果に終わっていて、3年連続でfailという残念すぎる結果に… そんなにギリギリをついて攻めたことをしているつもりは無いのですが、なぜかいつもfailしてしまいます。 今回はfailの原因もわかった（後述）し、反省できる内容だったので、しっかり反省を活かしたい。
ISUCON13 受賞チームおよび全チームスコア : ISUCON公式Blog
やったこと
言語は例年どおりのGoを選択しました。（僕個人は業務でGoを使っていないのもあって、generics時代のGoにまともに触れるのは実は初めてだったのですが、普通に無茶苦茶便利でした。） また、今回はDNS周りは正直僕はほとんど触れないまま完走してしまったので、解像度が低いです。
いつもどおり初手で適当にIndexを貼ってまわって、10:23頃に7,282点で暫定一位を取って記念撮影をしました。
そのあとは
- アプリケーションサイド:
- 愚直にN+1を潰す
- statistics 系のエンドポイントを効率化するために、逐次でスコアを計算しDBに書いておく
- iconの配信で304を返せるようにする
- インフラサイド:
- PowerDNSの前段にdnsdistを置いてキャッシュを効かせたりRate Limitをかけたり
というのを進めていきました。 PowerDNS側のMySQLがCPUをもっていってしまうので2台目に分けたり、ある程度最適化してもアプリケーション側のMySQLがボトルネックになっていることが明らかになってきたので3台目にわけたり、というのも並行して進めていきました。
前半、13:00ごろまではなにをやっても負荷が上がりきらず8000点位をウロウロしていたのですが、 dnsdist がはいったあたりでようやく1つ壁を超えて、32,588点まで伸びました。（14:19ごろ）
DNS側がうまくさばけていないことで、ベンチマーカーがあまりリクエストを送ってくれていなかったのか、このへんは @0gajun による DNS 周りの調整でガンガンスコアが伸びていきました。 Rate Limit を調整して 77,601 点までいったのが 15:24 ごろ。
そろそろ構成を Fix しようということで、
- 1台目: nginx + PowerDNS + app (weight = 3)
- 2台目: MySQL (PowerDNS) + app (weight = 5)
- 3台目: MySQL (app)
構成に移行し、115,353 点。（15:47ごろ）
ログを切ったり、残った N+1 を潰したりという細かい改善を進めていってじわじわスコアを伸ばしました。
もう限界そうだなぁとなってきたタイミングで、キャッシュを入れることを検討し始めました。 livestream は作成されたら二度と更新されないし、user も icon の更新以外はなかったので、キャッシュしやすく、かつどちらも comment や reaction 系のエンドポイントの中でも構築する必要があるオブジェクトだったため、キャッシュの効果も大きいだろう、と考えました。
2台構成だったので、
- オンメモリにデータを持ちつつ、RDBにはちゃんとデータを書き込む。キャッシュミスが起きればRDBからデータを取得してオンメモリに乗せる。
- Redisに載せる。
の2パターンで、izuminと僕で分担しつつ実装を進めました。 このあたりがうまくハマって、最終的には 227,377 点まで伸びました。（17:30ごろ）
我々のチームの最終盤の alp のログと MySQL の slow query log はこんな感じでした。
+--------+-----+-------+-------+-----+-----+--------+---------------------------------------------+-------+-------+---------+-------+-------+-------+-------+--------+-----------+------------+---------------+-----------+
| COUNT | 1XX | 2XX | 3XX | 4XX | 5XX | METHOD | URI | MIN | MAX | SUM | AVG | P90 | P95 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) |
+--------+-----+-------+-------+-----+-----+--------+---------------------------------------------+-------+-------+---------+-------+-------+-------+-------+--------+-----------+------------+---------------+-----------+
| 108135 | 0 | 10028 | 98102 | 5 | 0 | GET | /api/user/[\w\d]+/icon | 0.004 | 0.064 | 122.808 | 0.001 | 0.004 | 0.004 | 0.008 | 0.002 | 0.000 | 103167.000 | 77882124.000 | 720.230 |
| 11290 | 0 | 11286 | 0 | 4 | 0 | POST | /api/livestream/\d+/livecomment$ | 0.004 | 0.232 | 101.548 | 0.009 | 0.016 | 0.020 | 0.028 | 0.007 | 0.000 | 1767.000 | 17303791.000 | 1532.665 |
| 1043 | 0 | 1040 | 0 | 2 | 1 | POST | /api/register | 0.004 | 0.256 | 85.464 | 0.082 | 0.112 | 0.124 | 0.156 | 0.022 | 0.000 | 482.000 | 447785.000 | 429.324 |
| 10826 | 0 | 10826 | 0 | 0 | 0 | GET | /api/livestream/\d+/reaction | 0.004 | 0.096 | 82.436 | 0.008 | 0.012 | 0.016 | 0.028 | 0.006 | 3.000 | 161885.000 | 223926384.000 | 20684.129 |
| 10795 | 0 | 10795 | 0 | 0 | 0 | GET | /api/livestream/\d+/livecomment$ | 0.004 | 0.088 | 76.152 | 0.007 | 0.012 | 0.016 | 0.024 | 0.005 | 5.000 | 171215.000 | 249985236.000 | 23157.502 |
| 9864 | 0 | 9864 | 0 | 0 | 0 | POST | /api/livestream/\d+/reaction | 0.004 | 0.224 | 70.476 | 0.007 | 0.012 | 0.016 | 0.024 | 0.006 | 1331.000 | 1611.000 | 14461030.000 | 1466.041 |
| 5453 | 0 | 5453 | 0 | 0 | 0 | GET | /api/livestream/search | 0.004 | 0.084 | 59.760 | 0.011 | 0.016 | 0.024 | 0.036 | 0.007 | 40453.000 | 156745.000 | 267346886.000 | 49027.487 |
| 1285 | 0 | 1275 | 0 | 10 | 0 | POST | /api/livestream/reservation | 0.008 | 0.248 | 36.760 | 0.029 | 0.040 | 0.044 | 0.056 | 0.012 | 57.000 | 1091.000 | 1215036.000 | 945.553 |
| 7033 | 0 | 7032 | 0 | 1 | 0 | GET | /api/livestream/\d+/report | 0.000 | 0.032 | 31.296 | 0.004 | 0.008 | 0.012 | 0.016 | 0.003 | 0.000 | 3977.000 | 208899.000 | 29.703 |
| 3434 | 0 | 3434 | 0 | 0 | 0 | POST | /api/livestream/\d+/moderate | 0.004 | 0.208 | 21.532 | 0.006 | 0.012 | 0.012 | 0.020 | 0.006 | 18.000 | 18.000 | 61812.000 | 18.000 |
| 5251 | 0 | 5251 | 0 | 0 | 0 | GET | /api/livestream/\d+/ngwords | 0.004 | 0.028 | 20.828 | 0.004 | 0.008 | 0.008 | 0.016 | 0.003 | 5.000 | 1460.000 | 1254619.000 | 238.930 |
| 1162 | 0 | 1119 | 0 | 0 | 43 | POST | /api/icon | 0.004 | 0.240 | 18.012 | 0.016 | 0.024 | 0.032 | 0.052 | 0.011 | 9.000 | 149.000 | 18771.000 | 16.154 |
| 2213 | 0 | 2212 | 0 | 1 | 0 | GET | /api/livestream | 0.000 | 0.028 | 9.036 | 0.004 | 0.008 | 0.008 | 0.016 | 0.003 | 0.000 | 19075.000 | 5623652.000 | 2541.189 |
| 1360 | 0 | 1359 | 0 | 1 | 0 | GET | /api/tag | 0.004 | 0.036 | 5.668 | 0.004 | 0.008 | 0.008 | 0.016 | 0.003 | 0.000 | 3402.000 | 4623318.000 | 3399.499 |
| 1048 | 0 | 1046 | 0 | 2 | 0 | POST | /api/login | 0.004 | 0.020 | 5.116 | 0.005 | 0.008 | 0.012 | 0.016 | 0.003 | 0.000 | 59.000 | 118.000 | 0.113 |
| 1 | 0 | 1 | 0 | 0 | 0 | POST | /api/initialize | 4.608 | 4.608 | 4.608 | 4.608 | 4.608 | 4.608 | 4.608 | 0.000 | 22.000 | 22.000 | 22.000 | 22.000 |
| 96 | 0 | 96 | 0 | 0 | 0 | GET | /api/livestream/\d+/statistics | 0.008 | 0.080 | 4.340 | 0.045 | 0.064 | 0.072 | 0.080 | 0.014 | 79.000 | 84.000 | 7921.000 | 82.510 |
| 945 | 0 | 945 | 0 | 0 | 0 | POST | /api/livestream/\d+/enter | 0.004 | 0.172 | 3.904 | 0.004 | 0.008 | 0.008 | 0.016 | 0.008 | 0.000 | 0.000 | 0.000 | 0.000 |
| 936 | 0 | 936 | 0 | 0 | 0 | DELETE | /api/livestream/\d+/exit | 0.000 | 0.024 | 3.696 | 0.004 | 0.008 | 0.012 | 0.016 | 0.003 | 0.000 | 0.000 | 0.000 | 0.000 |
| 96 | 0 | 96 | 0 | 0 | 0 | GET | /api/user/[\w\d]+/statistics | 0.008 | 0.080 | 2.780 | 0.029 | 0.048 | 0.052 | 0.080 | 0.013 | 108.000 | 142.000 | 11569.000 | 120.510 |
| 62 | 0 | 60 | 0 | 2 | 0 | POST | /api/livestream/\d+/livecomment/\d+/report$ | 0.004 | 0.024 | 0.528 | 0.009 | 0.012 | 0.016 | 0.024 | 0.004 | 52.000 | 2148.000 | 120814.000 | 1948.613 |
| 94 | 0 | 94 | 0 | 0 | 0 | GET | /api/user/[\w\d]+/livestream | 0.008 | 0.012 | 0.488 | 0.005 | 0.008 | 0.012 | 0.012 | 0.003 | 949.000 | 19068.000 | 581533.000 | 6186.521 |
| 95 | 0 | 95 | 0 | 0 | 0 | GET | /api/user/[\w\d]+/theme | 0.004 | 0.012 | 0.392 | 0.004 | 0.008 | 0.012 | 0.012 | 0.003 | 29.000 | 29.000 | 2755.000 | 29.000 |
| 3 | 0 | 3 | 0 | 0 | 0 | GET | /api/user/me | 0.004 | 0.004 | 0.008 | 0.003 | 0.004 | 0.004 | 0.004 | 0.002 | 195.000 | 207.000 | 609.000 | 203.000 |
| 1 | 0 | 1 | 0 | 0 | 0 | GET | /api/user/test | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 195.000 | 195.000 | 195.000 | 195.000 |
| 1 | 0 | 1 | 0 | 0 | 0 | GET | /api/livestream/\d+$ | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 1091.000 | 1091.000 | 1091.000 | 1091.000 |
| 1 | 0 | 1 | 0 | 0 | 0 | GET | /api/payment | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | 16.000 | 16.000 | 16.000 | 16.000 |
+--------+-----+-------+-------+-----+-----+--------+---------------------------------------------+-------+-------+---------+-------+-------+-------+-------+--------+-----------+------------+---------------+-----------+Count: 1283 Time=0.02s (19s) Lock=0.00s (0s) Rows=10.1 (12972), isucon[isucon]@2hosts
SELECT * FROM reservation_slots WHERE start_at >= N AND end_at <= N FOR UPDATE
Count: 74228 Time=0.00s (8s) Lock=0.00s (0s) Rows=0.0 (0), isucon[isucon]@2hosts
COMMIT
Count: 1162 Time=0.01s (6s) Lock=0.00s (0s) Rows=0.0 (0), isucon[isucon]@2hosts
INSERT INTO icons (user_id, image, sha256) VALUES (N, _binary'S', 'S')
Count: 31976 Time=0.00s (4s) Lock=0.00s (0s) Rows=1.0 (31976), isucon[isucon]@2hosts
SELECT * FROM livestreams WHERE id IN (N)
Count: 3514 Time=0.00s (3s) Lock=0.00s (0s) Rows=50.0 (175700), isucon[isucon]@2hosts
SELECT user_id, sha256 FROM icons WHERE user_id IN (N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N)
Count: 96 Time=0.04s (3s) Lock=0.00s (0s) Rows=1.0 (96), isucon[isucon]@2hosts
SELECT rank_
FROM (
SELECT id, RANK() OVER (ORDER BY score DESC) AS rank_
FROM livestreams
) AS ranked_users
WHERE id = N
Count: 3514 Time=0.00s (3s) Lock=0.00s (0s) Rows=50.0 (175700), isucon[isucon]@2hosts
SELECT * FROM themes WHERE user_id IN (N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N, N)
Count: 11287 Time=0.00s (2s) Lock=0.00s (0s) Rows=0.0 (0), isucon[isucon]@2hosts
INSERT INTO livecomments (user_id, livestream_id, comment, tip, created_at) VALUES (N, N, 'S', N, N)
Count: 9851 Time=0.00s (2s) Lock=0.00s (0s) Rows=16.1 (158932), isucon[isucon]@2hosts
SELECT * FROM livecomments WHERE livestream_id = N ORDER BY created_at DESC
Count: 9883 Time=0.00s (2s) Lock=0.00s (0s) Rows=15.1 (149160), isucon[isucon]@2hosts
SELECT * FROM reactions WHERE livestream_id = N ORDER BY created_at DESC
...最終盤にきても CPU が 7 割くらいしか使い切れず、なにがボトルネックなのかいまいち分からなかったので、「スコアは上がらないけど速くなっている/負荷が下がっている」みたいな変更を最終盤にガンガン取り込んだのですが、そのなかの一つが fail の原因でした…
fail の原因
さきほどの slow query を見ると、一番上が reservation_slots のロックを取るクエリになっています。 これが遅いせいで CPU を使い切れていない / リクエスト速度が上がり切っていないのでは？と考え、このロックを最小化する変更をいれようとしました。 ref
処理としては、
-
- reservation_slots を SELECT FOR UPDATE で抑える
-
- 枠が空いていれば、reservation_slots の残枠を減らす
-
- livestream を INSERT する
-
- livestream_tags を INSERT する
-
- 作った livestream を JSON で返すために、関連データも合わせて DB から取得する
ということを1トランザクションの中で行っている部分です。
ここで、少なくとも 5 は transaction をコミットしたあとにやっても問題ないはず、ということで、5 を transaction の外に出す変更をすでに入れていました。 追加で最終盤にもうちょっと攻めようとして、3, 4も transaction の外に出すというのをやりました。（17:42ごろ） 3, 4は（アプリケーションレイヤでは）失敗し得ない処理なので、transaction の外に出しても問題ないはずだと考えました。 実際これをやってもベンチは通っていて、スコアは微増しました。（223,455 → 226.609）
しかし、ここで僕がトランザクションの分け方をミスっていて、3 と 4 を atomic にすることに失敗していました。 livestream はあるのに livestream_tags がない、という状況が瞬間的に発生しており、その刹那を観測されると正しくないデータが返ってしまう状態になっていました。
さらに悪いことに、livestreamをオンメモリでキャッシュしていたので、この状態が発生すると、livestream_tags がない状態の livestream がキャッシュに乗ってしまい、その後のリクエストにも影響を与えてしまう、という状態になっていました。 livestreamには更新系がない、というのも災いして、キャッシュをinvalidateするコードを書きそびれており、 3, 4の間に別のリクエストのせいでキャッシュが暖まってしまう可能性を考慮していませんでした。
今思えばスコア的には大したゲインもないわりに攻めすぎたのですが、あのときは NaruseJun チームの異常なスコアにビビっていたのもあり、勝つためにはもっと攻めなければという意識になっていました。 もっと余裕のあるスコアを取れていれば、このあたりの攻めはしなかったかもしれませんが、今回は終了1時間前の時点で拮抗していたし、実際蓋を開けてみれば 220,000 点あたりが割と詰まっていたので、攻めないという判断は難しかったなぁとも思います。
まとめ
というわけで ISUCON13 は僕のミスによる fail で終わってしまいました。申し訳ない…
もともと負け惜しみいっぱいの感情でこのブログを書いていたのですが、昨日出題チームのrepositoryが公開され、(ref) failの理由が判明してしまったので、シンプルに負けたなという気持ちです。 くやしい！！！！！！！ そろそろ勝ちたい！！！！！
出題に関しても、ボリュームたっぷりで、とっつきやすいところから攻めていけるようになっていて、とても楽しかったです。 インフラ的な面白さもぐっと増していて、いい勉強にもなりました！（まだ正直インフラまわりの変更は理解できていないので、ふりかえりして勉強したい） 運営の皆様、楽しいイベントありがとうございました！