Tag Archives: ISUCON

ISUCON9 予選の参加ログ (チーム: 再起動非対応)

Infrastructure Programming

こんばんは、kyontanです。

前回再起動試験で落ちたのでチーム「再起動非対応」で参加しました。ベストスコアは4410点でした。再起動試験までたどり着けなかった……悔しい……

チーム「再起動非対応」は同期3人 (自分 @kyontan, @hogashi, @h-otter) での参加でした。学生は2人いたはずですがエントリーをミスったので学生は1人ということになっています。

使用した言語

私はRubyが一番得意だと思っていますが、非同期処理が書きやすいとか型が着いていると嬉しい、みたいなことはあり今回もGo言語です。
でも今回はN+1潰すときの型マッピングで無駄に時間を溶かしてしまったので、Rubyの方が良かったかもしれない……つらい……

開始前の準備

Prometheus/Grafana等のサーバの設定を @h-otter にお願いしました。前回のコードを読み返しつつ、何をしたかを思い出すなどした。

時間がなくて完全に忘れてしまいましたが、せめて練習はやっておくべきでしたね…

あと、 Alibaba Cloud の UI が色々不思議な感じで良かったですね。

本番

完全に正解していますが、今回はマイクロサービス問だということに気が付いたのは開始してからだいぶ経ってからでした。

今回できたことが異常に少ない気がする。kataribeのログを眺めつつ、チームでやったことは以下のことです。比較的時系列だけどそうでない部分もあるかも。

  • 開始スコアは 2310
  • 10:30 メモリ多いな〜って思っていたら2, 3台目のインスタンスタイプを間違えていたことに気がつく。インスタンス立て直し
    • コードは既にリポジトリへ追加していたのでチームメイトはルール/コードリーディングを進める
  • 10:50ごろ: 作業開始
  • 11:30ごろ?: MySQL 5.7 を 8.0 へ (@h-otter)
    • スコア変化なし
  • 11:45 DBにインデックスを張る(@kyontan)
    • 多分間違えていて、これらにインデックスを貼りましたがあまり効いていなかったようにみえました
    • BigQuery の触りすぎでRDBのインデックスの挙動をほぼ忘れたのも敗北ポイント

  • 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)で allowedIPswithIPRestriction といった単語が。定義元(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 を今回なぜ見なかったのか……

短い時間で追い詰められている環境の中でどれだけ集中できる / 気付けるか、というのが重要になると改めて感じました。

コンテストとしては今回も設定が面白く、運営の手の込みようが分かり、かつ短期間で取り組みがいのあるとても良い問題でした。
運営の皆様、大変お疲れさまでした。

ISUCON8 予選に参加して再起動試験に落ちました

Infrastructure Programming

おはようございます。名取さなにハマっている kyontan です。

最終スコア

チーム「hhkb」で同期3人 (自分 @kyontan, @hogashi, @h-otter) 2回目の参加で2日目で Go 実装でした。学生枠突破ならずでした、悔しい。というよりは 55,982点で全体4位の点数で落ちました。ちなみに hhkb は h-otter, hogashi, kyontan, :boom: ???? の略です。
スキルセット的には、 @h-otter がインフラ(ミドルウェア含)なんでもできる+Goの経験が一番あるマンで、 @hogashi がアプリケーションなんでもできるマンで、 @kyontan はアプリとインフラとDBを一通り見られるマンみたいな感じでした。

今回は真面目に本戦に行きたかったので前々日に ConoHa で ISUCON7 の予選を解き直して練習しました。具体的には ConoHa の練習用イメージを使って 1GBプラン x3台で予選環境を再現しました。結果、10時間程度で 5,204点から509,190点まで持っていけることが分かり、計測と試行の反復を効率的に行えば ISUCON の予選は突破できるという確信を深めていました。
また、前回は最後の最後でベンチマーカを走行させた結果点数が下がって落ちたので、前回の直後に「泣きの1回はやらない」というスローガンを掲げ、1年越しでそれを達成しました。

ベンチマークの初回走行の結果しばらく1位になった

事前に準備したのは Prometheus のサーバ (@h-otter がいい感じにやってくれた)と、やること/できることチェックリストぐらいでしょうか。だいたい大会では開始した瞬間にテンパってそのまま撃沈するのが常なので、思考停止状態でもコピペで動くようなコード片とかを用意しておくと便利ですね。あとは思考が無になったときに確認するべき事項とかを作っておくと良いのではないでしょうか? 頻繁に無になって帰りたくなりました。メンタルは大事。

例えば下のような感じです。

当日は3人がローカルで開発し、本番環境のVMへバイナリを転送して検証する、という進め方でやっていました。Go はクロスプラットフォームでのビルドがしやすいのが便利ですね。

具体的にやったことを羅列します。というか @h-otter が書いていたのを未承諾引用します。順番は適当

  • SELECT * する系のクエリを必要な列しか取らないようにした
  • /api/usersuser_idreservations を全部とってきて、アプリ側で処理してやったらめっちゃ速くなった
    • ここでベンチマーカが重いと言ってくるエンドポイントが /users/:id から /api/events/:id/actions/reserve になった
  • getEventgetEventWithoutDetail と分けた
  • getEventgetEvents を2クエリに
  • sheets へのクエリを消す
    • 効果があったのかは良くわからない
  • MariaDB のチューニング
  • Prometheus と Grafana で可視化
  • ログインのクエリを1つに
  • パスワードを平文で突っ込むようにした
  • DB にインデックス張った (けどあまり良い結果がでなくてもんにょりした)
    • 最初に mysql コマンドでインデックス張ったけど結果が全く変わらなくて、なぜ? と思ったら毎回 /initialize でテーブルを作り直していることに気がついた。
  • IN句を使いたかったので DBにアクセスするライブラリを sqlx に切り替えた
  • トランザクションの開始がおかしいところがあったので直したり デッドロック時にエラーを返さずリトライするようにした

最後は予約時のシート決定を高速化するコードが安定化しなくて入らなかったり、Redisでいい感じにやろうぜみたいなことを思うだけ思ってやらなかったりしました。多分ここができると数万点上がったはず。

あとはスコアに関係ないけど作業便利になる系として、 エラーログでソースコードの行番号を吐くようにしたり、 Makefile 弄って1コマンドでデプロイできるようにしました。
開発は3台のサーバでバラバラにやっていましたがDBは1台だけを参照するようにしました。これはDBのチューニングとかがあって、1台でやった変更を他に反映したりするのが面倒くさかったので。こうすると、やりたい人間が適当にベンチマーク対象のサーバを変更して実行してやればいいので楽でした。

ソースコードは GitHub で管理し、いい感じにやりました。コミットログは下の通りです。

数字がタグに付いていることがありますが、これはいいスコアが出た時にバイナリごとコミットしてタグつけておこうぜ、みたいな感じにした結果でした。

今回の僕の活躍はよく分からなくて、いい感じデバッグ担当だった気がします。PRを見るなりとりあえずマージしてベンチマーカを落としたりバグ探しをしていたりしました。とにかく @h-otter がぶち壊しつつ @hogashi がいい感じに安定化するコードを書いてくれてよかった感がある。

Webサーバはh2oで十分高速だし、画像のトラフィック詰まりもないしで、とにかくアプリケーションコードの改善に注力した/するしかなかった8時間でした。

最終的に残り30分でベンチマーカを叩いたところ3万点前後のスコアが5万点に若干跳ねてそこで打ち止め。一度再起動をしてブラウザからアクセスできることを確認し天命を待ったところ、無事再起動試験で落ち失格となりました。天命……

(追記: スコアが跳ねたのは、最後に実行先サーバを変えた時に インデックスを張る処理を init.sh に書いたサーバで実行したからかもしれないことを思い出した。)

なぜ失格になったのかは分かっていなくて、おそらく /admin/api/reports/events/:id/sales の処理が遅くて不整合が起きて落ちたのかなあなどと思っていますが、2回連続で落ちるのは運が悪かったなと……

なんやかんやでやることがなくならない8時間で、やることが見つからない8時間よりは良かったのではないかと思います。

イキっているなどと言われてもこれは事実だと信じていて、典型的な N+1 を潰すなどすれば予選は通過できるはずなことは分かりましたね。くぅ〜〜

来年はちゃんと本選に行けたらいいですね。頑張りましょう。

そして、参加会場を提供していただいた mixi 様、惜敗の悔しさを教えてくれる最高のコンテストを運営をしていただいたISUCONの運営の皆様、お疲れ様でした、ありがとうございました!

以下は画像です

ISUCON7 予選に参加しました

Infrastructure Programming

チーム「まだチーム名で消耗してるの?」で同期3人 (自分 @kyontan, @hogas, @h-otter) 初参加で2日目でした。学生枠突破ならずでした。

Ruby実装で挑み、最終スコア 38605点@2017-10-22 20:59:30, ベストスコア: 67792点@2017-10-22 20:44:59 でした。
ベストスコアでは予選ラインは超えていたんだなあと思いますが、最終的には伸び悩んだチームも多いようで、結局落ち着くところに落ち着いたのかなと思います。

ソースコードは kyontan/isucon7_qual です。踏み台でやっていた影響でコミッタが僕に見えますが、だいたい僕ではない。

ISUCON7 予選での Score / LoadLevel の変化

次回も参加したいなという気持ちになってきたので、ひとまずはやったことを記していきます。

read more »