この記事はLayerXテックアドカレ2024の24日目の記事です。
でも ISUCON の自慢がしたいので今回は LayerX の話はしません。
ISUCON14に「都営三田線東急目黒線直通急行日吉行」で参加し、4位になりました。
ISUCON7 から 0gajun, agatan と参加し続けていますが、久々に結果が出たぞ！！！
近年は上位争いしつつの失格が多かったのでホッとしています。
- ISUCON11 予選2位 / 本戦失格（スコア3位相当）
- ISUCON12 予選落ち
- ISUCON13 本戦失格（スコア3位相当）
とはいえここまでくると入賞・優勝も狙えそうなのでやっぱ悔しい…！
今年の問題については ISUCON14 問題の解説と講評 : ISUCON公式Blog を見ていただくと雰囲気がわかると思います。
ざっくりいうと人に椅子を配車（配椅子？）するライドシェア（ライドチェア）サービスです。
以下、自分たちのチームが何をしたかをかんたんに振り返ります。
やったこと
分担は 0gajun がインフラ, agatan と自分がアプリケーション改善を主に担当。
言語は例年通りGoを選択。
最序盤
- 1137: 初期スコア
- 599: いつものセットアップ
- 0gajun が鍵の配置やログ周りなどを一瞬でやってくれる
- その隙に agatan, izumin でマニュアルやコードを眺める
- 3282: インデックス追加 (izumin)
- コード読みがてら CREATE TABLE に必要なインデックスを書き足していく
- これやってるうちに初回ベンチが終わり、案の定 MySQL がボトルネックになっていたので何も考えずにインデックス反映
- 3742:
ownerGetChairsのハチャメチャ集計クエリをちょっとだけ改善 (izumin)- 無駄に全椅子を見てたので、そのオーナーが持つ椅子だけに絞った
- （本質的な改善を考えるのが面倒だったので、初手最速で出せる改善だけ突っ込んだ）
ここはいつもの動きを例年通りにやっている。
最初のベンチの段階で RDB に負荷が集中していることがわかれば、とりあえず自明なインデックス追加を最速でやってしまって次のボトルネックに向き合えるようにしている。
あとは、インデックス追加後のベンチ実行結果を見ると明らかに異常激重クエリがあったので軽くだけ改善を入れた。
序盤
- 4169: マッチングインターバルを短縮 (0gajun)
- 4981: 1回のマッチングリクエストで複数の rides を処理するように (agatan)
- 5578: notification のリクエスト間隔を 30ms -> 100ms に伸ばす（izumin）
- notification のリクエストを受けすぎて MySQL が爆発しそうだったので、おもむろに頻度を下げた
- 10221: DBを別インスタンスに逃がす (0gajun)
- （ここで12:20ぐらい）
椅子とユーザがちゃんとマッチングされないと負荷を改善してもスコアが上がらないことを察し始め、そのあたりを agatan が改善。
自分はアクセスログ・スロークエリログを見つつ負荷を下げる活動を進める。
また、これは当面は明らかに DB に負荷が集中し続けるであろうということで、0gajun がサクッと別 DB に逃がしてくれた。
中盤
- 11068:
getCharStatusの N+1 クエリ解消 (izumin) - ?????: chair の総移動距離を DB にキャッシュし、
ownerGetChairsのクエリに利用 (agatan)-
ownerGetChairsのクエリが引き続き激重だったので、本質的な改善として投入
-
- 21372: マッチング改善 (agatan)
- ランダムだったのをやめて、空いてる chair のうち最も近いものを選ぶようにする
- ついでに SELECT の N+1 も解消して負荷も下がった
- 23894:
interpolateParams=true(0gajun) - 30936: 「ride が通知まで含めて完全に終了したこと」を DB に記録し、それをマッチング処理のクエリ改善に利用 + 通知のリクエスト間隔を 100ms -> 300ms に伸ばす（全員）
- マッチング改善でめっちゃ重い SELECT があったので、それを簡単にするための対応
- この改善プラス通知間隔調整でスコアがかなり改善した
- （これなんで2つ同時にやったんだっけ…）
- （これを進める途中で agatan 離脱）
引き続きマッチング周りを agatan, 負荷を izumin で分担しつつ進める。
ride_statuses が様々なクエリに絡んでおり、かつこの状態遷移が重要なロジックでありキャッシュを挟みたいポイントでもあったので、この更新を関数に切り出すなどのリファクタをしたりもした。これ意外と重要だったのでは？
15:00にマッチングの大きな改善が入ってスコアが大きく伸びた。
途中15:30頃に agatan が離脱するも、残してくれたコードを投入したらさらに伸びる。
上位に入り調子に乗る様子。
終盤
- 32003: アクセストークンのオンメモリキャッシュ (0gajun)
- とにかく MySQL への負荷を下げたくてやった
- 39027: 通知をまとめて返し、通知間隔を 300ms -> 1000ms に (izumin)
- 43685: getNearbyChairs の N+1 クエリ解消 (0gajun, izumin)
- 48615: お片付けして終わり
agatan が抜けたかわりにインフラ担当の 0gajun がめっちゃコードを書いて改善が進む。
SSE(Server Side Events) を使った通知改善は「Pub/Sub っぽくデータ更新があったら通知送信」を進めていたが、どうしてもバグが取れず諦めていた。
とはいえ通知取得リクエストによる負荷の大きさが無視できなかったので、代わりに1回の通知リクエストで溜まっている通知を stream で全部返すようにすることで、少ないクエリで多くの通知を返せるようにした。
これでスコアがもうちょい伸びた。
リーダーボード凍結時2位でドキドキしている様子。このあと結局まくられる。
その後もちくちく改善を進めたが最後はスコアが伸び悩み、結果4位フィニッシュ。
喜ぶべきか悔しがるべきかわからなくなっている様子。
ふりかえり
単純に目に見える非効率なコードを改善するだけではスコアは伸びず、プロダクト仕様を理解したうえで改善する必要がある…と、いままでの ISUCON とは一味違った印象で、でも納得感があり非常に楽しい問題でした。
自分たちは alp や mysqldumpslow の出力を見ながらチームみんなで議論しつつ動いていくスタイルですが、今年はそれがうまくいった結果スムーズにマッチングアルゴリズムの改善などを進めることができました。
一方で改善入れた結果バグってそれを直すのに手間取り時間を浪費したところもあり、今年はそれが反省ポイント。
通知改善が chair 側にしか入ってなかったり、インスタンス2台しか使えてなかったり、chair の特性や地域などには気づきつつ改善はできなかったり… いやー 悔しい！
おまけ: 小道具
今年は新兵器として「SQLに呼び出し元ファイルと関数名をコメントする」ようなパッケージを事前に用意し、アプリケーションに組み込みました。
近年の ISUCON はコードを全部読むのが大変な量になってきているので、クエリから問題があるコードを見つけやすくしておくだけでかなり楽になりました。
# mysqldumpslow 内にファイル名・行数・関数名が記録されている様子
Count: 16669 Time=0.00s (18s) Lock=0.00s (0s) Rows=0.1 (1465), isucon[isucon]@ip-192-168-0-11.ap-northeast-1.compute.internal
/* /home/isucon/webapp/go/app_handlers.go:６５８ appGetNotification */ SELECT * FROM ride_statuses WHERE ride_id = 'S' AND app_sent_at IS NULL ORDER BY created_at ASC LIMIT N
Count: 14594 Time=0.00s (17s) Lock=0.00s (0s) Rows=0.1 (1484), isucon[isucon]@ip-192-168-0-11.ap-northeast-1.compute.internal
/* /home/isucon/webapp/go/chair_handlers.go:２４１ chairGetNotification */ SELECT * FROM ride_statuses WHERE ride_id = 'S' AND chair_sent_at IS NULL ORDER BY created_at ASC LIMIT N
Go の database/sql/driver.Driver をラップする新たな Driver を作り、その中で SQL の先頭にコメントを追記するような実装になってます。単純！
func (c *wrappedConn) QueryContext(ctx context.Context, query string, args []driver.NamedValue) (driver.Rows, error) {
queryWithCallerInfo := c.addCallerInfo(query)
if queryerCtx, ok := c.Conn.(driver.QueryerContext); ok {
return queryerCtx.QueryContext(ctx, queryWithCallerInfo, args)
}
return nil, driver.ErrSkip
}
func (c *wrappedConn) addCallerInfo(query string) string {
var file string
var line int
var pc uintptr
// ...
comment := fmt.Sprintf("/* %s:%s %s */ ", file, toFullWidthNumber(line), shortFuncName)
return comment + query
}
mysqldumpslow が半角数字をプレースホルダに置き換えちゃうので、その対策に全角数字で出力しているのがチャームポイントです。
おわり
今年も非常に楽しい問題でした！運営の皆様おつかれさまでした&ありがとうございました！
来年こそ勝つぞ！
Discussion