こんばんは、kyontanです。
前回再起動試験で落ちたのでチーム「再起動非対応」で参加しました。ベストスコアは4410点でした。再起動試験までたどり着けなかった……悔しい……
チーム「再起動非対応」は同期3人 (自分 @kyontan, @hogashi, @h-otter) での参加でした。学生は2人いたはずですがエントリーをミスったので学生は1人ということになっています。
使用した言語
私はRubyが一番得意だと思っていますが、非同期処理が書きやすいとか型が着いていると嬉しい、みたいなことはあり今回もGo言語です。
でも今回はN+1潰すときの型マッピングで無駄に時間を溶かしてしまったので、Rubyの方が良かったかもしれない……つらい……
開始前の準備
Prometheus/Grafana等のサーバの設定を @h-otter にお願いしました。前回のコードを読み返しつつ、何をしたかを思い出すなどした。
時間がなくて完全に忘れてしまいましたが、せめて練習はやっておくべきでしたね…
あと、 Alibaba Cloud の UI が色々不思議な感じで良かったですね。
本番
完全に正解していますが、今回はマイクロサービス問だということに気が付いたのは開始してからだいぶ経ってからでした。
開始30分前、チームメイトとの雑談「今日は何がでるかなー」「フリマアプリかオークションかそういうやつでしょ」「マイクロサービスとかね」「わかる〜」 #isucon
— きょんたん (@sukukyon) September 8, 2019
今回できたことが異常に少ない気がする。kataribeのログを眺めつつ、チームでやったことは以下のことです。比較的時系列だけどそうでない部分もあるかも。
- 開始スコアは 2310
- 10:30 メモリ多いな〜って思っていたら2, 3台目のインスタンスタイプを間違えていたことに気がつく。インスタンス立て直し
- コードは既にリポジトリへ追加していたのでチームメイトはルール/コードリーディングを進める
- 10:50ごろ: 作業開始
- 11:30ごろ?: MySQL 5.7 を 8.0 へ (@h-otter)
- スコア変化なし
- 11:45 DBにインデックスを張る(@kyontan)
- 多分間違えていて、これらにインデックスを貼りましたがあまり効いていなかったようにみえました
- BigQuery の触りすぎでRDBのインデックスの挙動をほぼ忘れたのも敗北ポイント
|
1 2 3 4 5 6 7 8 9 10 |
config (name) items (created_at, id) items (id) items (buyer_id) items (seller_id) shippings (transaction_evidence_id) transaction_evidences (id) transaction_evidences (item_id) users (account_name) users (id) |
- 12:20: カテゴリをオンメモリへ (@hogas, @h-otter)
- 2510点ぐらい
- 12:30: http2 対応, 静的ファイルをキャッシュ, アップロードされた画像を nginx で返すなど
- スコア変化なし
- 13:30: config もキャッシュするように
- 14:00: 新着商品には発売中の商品だけを返すようにする (@hogas)
- 14:45 – 16:00:
GET /users/transactions.jsonの N+1 を潰す (@kyontan)- 3500点ぐらい
- なぜか色々ハマって2時間半ぐらい溶かしていた。これは敗北ポイント
- 多分ここらへんでMySQLがサチらなくなっていた気がする
- CPUがサチっていたことに気が付いていたが原因が分からず (pprofをなぜ見なかったのか……)
- 15:30:
UserSimpleが持つ情報は全てオンメモリでキャッシュする- ユーザの存在チェックだけするような部分 (権限チェック) も基本的にこれで対応できるのでそうした
- 4210点
- ここからスコア上がらず……
- 16:00: 同じクエリを何度か叩いているエンドポイントがあったので潰す (@hogas, @kyontan)
- 16:00ごろ: transactions 以外詰まってないしCPUに余裕があるので campaign (負荷レベル)を弄ったところ外部APIで 403エラー {“error”:”IP address is not allowed”} が連発しだす
- 主に
GET /users/transactions.jsonでの外部 shipment サービスへのリクエストで連発 外部APIへの403はアプリケーション的には500を返す仕様だったので、これが連発してベンチマーカが途中終了し完走しない- 403は関係ないことが判明しました (追記あり)
- ログを分析したところ、13時ごろにも同じエラーで落ちた回があったため一概に campaign が原因ではなく、外部API の HTTP 502 のハンドリングを適切に行わなかったことや他のエラー等が原因と推測
- ここらへんで手詰まりに
- 主に
- 17:00: 明らかに不要な
SELECT FOR UPDATEを削除 (4箇所+ぐらい)- これかこれの次辺りで4410点。これがベストスコア
- 17:10: 外部APIを叩く部分で exponential backoff を実装 (@h-otter)
- 変化なし
/ 403 が連発する
- 変化なし
- 17:30: 外部APIをリクエストするエンドポイントだけ2台へ分散する
403 の連発は解決せず、なぜ……
- 18:10: 最終スコア0点 (failed) で終了
色々施策を打つもスコアの変化要因が今ひとつ分からず頭が回っていなかったですね。
特に外部API が undocumented な 403 を返す (しかもメッセージは 「許可されていないIPアドレス」) というのは全然分かりませんでした。
マイクロサービス問題なら単一IPから連続でアクセスすると弾くようになっているのかな、などと思い、後半で外部APIへリクエストをするエンドポイントだけ複数台へ分散するなどしていましたが全く解決せず泥沼へ。
これベンチマーカと外部API側に問題あるのでは? みたいな気持ちになりつつ、マイクロサービス問だしちゃんとbackoffとか実行すればいけるでしょ! と思っていましたが、意図したエラーだったのかは未だに分からず……
他の方の感想を見た限りでは、ポータルサイトへ登録されていないIPからのアクセスは弾かれるみたいですが、これについてはUI上で正しく登録されていることを確認したので問題なさそうでした。
11:00 ごろにインスタンスを立ち上げ直してIPを再登録したのがポータルサイトの何らかのエッジケースを踏んだのでは? などと勝手に邪推しています。謎ですね。 (次節へ考察を追加)
そのほか、 campaign の値を変えると何が変わるのか (POST系アクセスが増える?)、みたいなことも終了後にログを分析してようやくなんとなく傾向がわかり悔しい気持ちに。
外部API の undocumented なエラーについて (2019/9/10に追記)
これだけが原因でなかったとはいえ、これはこれで気になるので追記。別にルールとは関係なさそうでしたね
終了後にポータルサイトで実行時刻とログが見られるようになり(ありがとうございます)、ISUCON9 予選問題の解説と講評 : ISUCON公式Blog でベンチマーカや外部APIのソースコードが公開されたので、サーバのログを照らし合わせて考えてみた。
以下だらだらとソースコードを追っていますが、ベンチマーク時にアプリ側が403とは関係ないエラー(もしくは完走)によりベンチマーカが終了し、直後に他チーム向けに起動されたAPIサーバへ接続してしまったために生じたエラーではないか、という予想です。
今回の外部APIサーバの1つである shipment などを見てみると、このあたり(bench/server/shipment.go#L211-L216)で allowedIPs や withIPRestriction といった単語が。定義元(bench/server/server.go#L54-L85)を見ると文字通りIPアドレス制限を掛けている。外部からの攻撃や参加者の手元から叩かれるのを防ぐためかな。
この allowedIPs はそもそもどこから来るかと言うと、この外部APIを立ち上げてくるベンチマーカを起動するワーカ (bench-worker) がプロセスの引数として渡している (cmd/bench-worker/main.go#L215-L235)ことが分かる。
これを見ると、どうもベンチマークの実行ごとに、そのチーム向けの外部APIサーバが起動しており、他チームからのアクセスなどを拒否するようになっているようだした。
(てっきり常設の外部APIサーバがあり、アクセスごとにIPアドレスの許可不許可を確認しているんだと思っていた。)
ベンチマークそのものは実行できているわけだからIPが間違っているはずはないし、一体どこで何が食い違ってしまったのか……と思い見てみるが別におかしそうなところはなく。
アプリ側でおかしな変更を加えてしまったのではないかと、コミットログと照らし合わせつつ最初にエラーが出た時刻からログを照らし合わせてみたがそのような部分はなさそう。
どういったタイミングでエラーが……? と改めて見てみたところ、どうも常にベンチマークの終了時刻ごろに403エラーを連発していることが判明し……
推測としては、他の原因に起因するエラー(Too many open files, 結果の不整合, 外部APIの502エラーを正しくハンドリングしないことによる500エラーの連発など……)でベンチマークが終了し、他のチームに対するベンチマークが開始した際に 403 が返ってくるのではないか? と
(運営側が用意した各ホストの bench-worker はベンチマーク要求を定期的に確認してはベンチマーカ(兼外部API)を立ち上げており、ベンチマークが終了すると次のベンチマーク要求を確認する仕様になっていました。 (cmd/bench-worker/main.go#L308-L323)
ベンチマーク要求がある限り次のベンチマーク処理はほぼ即座に開始するため、アプリ側が若干遅延して次のチーム向けのAPIを叩いてしまうことも考えられます。
(bench-worker は定期的にベンチマーク要求を確認しています(cmd/bench-worker/main.go#L309) デフォルト値は3秒になっていますが、これがより大きい値に設定されていても、その値よりベンチマーク実行時間の方が長ければ待ち時間なく次のベンチマーク実行へ入ります)
待ち時間なく次のチーム向けのAPIサーバが起動していたためにこのような不可解な状況になっていたのか……と納得するなど。ベンチマーカの構成を明らかにするのは運営側に利点がなかったのかと思いますが、説明があると良かったですね。
感想
終わってみれば途中重大な気付き (「外部APIのレスポンスキャッシュできるじゃん」「ユーザの嗜好に合わせて商品出し分けたら?」など) があり、見逃しの多い回でした。
bcrypt の件は全く気づいておらず。前回は初手でやった(があまり意味がなかった) pprof を今回なぜ見なかったのか……
短い時間で追い詰められている環境の中でどれだけ集中できる / 気付けるか、というのが重要になると改めて感じました。
コンテストとしては今回も設定が面白く、運営の手の込みようが分かり、かつ短期間で取り組みがいのあるとても良い問題でした。
運営の皆様、大変お疲れさまでした。
