ISUCON9予選参加記呑んだくれ穏健派

チーム「呑んだくれ穏健派」の daiju です。 ISUCON9予選に参加してきました。

結果は予選敗退。特にいいところなく終わってしまいました。

僕らのチームは去年のISUCON8が初参加で、そのときは「飲んだくれ穏健派」で出場。（今年はチーム名を typo してそのまま出場したので表記揺れが発生した）

ISUCON8は社会人枠の最下位で予選突破こそしたけれども決勝で「何もわからん」をやっていた。

去年の予選・決勝の参加記書いてなくて、その時の反省が生かされずに今回は予選落ちになってしまった。このままだと今年も反省できずに終わりそうな気がしたので参加記を書きます。

チームメイト

インフラ担当が一人
SREみたいな人が一人
アプリケーションを僕

３人とも元同じ会社の同僚。

当日まで

去年も出場しているので雰囲気はわかっているし、特別な素振りはしていない。

1週間くらい前に集まって方針決めて、その時に決まったことが

言語はPython、よほどハマりそうな問題だったらGoかも
- メンバー的に共通して書けるのが Python だけ。Python だと大規模サービス運用経験も豊富なのでなんとかなると思っている
集まる場所は会社の会議室
個人の gitlab.com にレポジトリを作って、基本的にgit経由でコード変更を現地反映させる
ログ周り
- Splunk/Prometheus/Grafanaなどは事前に立てておく
  - ダッシュボードも事前にほしい(MySQL Slowquery, Grafanaにいろいろ)
- Prometheusのexporterを入れる素振りはやる (node-exporter, mysql, nginx とか)
  - VMにバイナリを入れる想定、docker系だったらdockerベース
- netdataも念のため入れる
- 基本Dockerも想定して、ログ周りの準備も素振り
  - 基本 hostのディレクトリをvolume mountしてホスト側にforwarder, exporterを入れる
  - アプリケーションの分析はログを出してSplunkでよしなにやる

予選２日前にこんなこと言ってた（フラグ）

f:id:q2KWLv7s:20190914124232p:plain

当日

朝

全員起床成功。

僕は iMac を担いで会社まで行った。重い。

10:10〜11:10

（開始が10分遅れる）

ルールを読んだりインスタンスを起動したり nginx のログを splunk に入れたりしてた。

この段階で

外部APIがある
campaign で負荷を調整する

みたいなことに気づき、「去年の決勝やん、嫌な予感がする」みたいになってた。

nginx のアクセスログを仕込めたので Python のデフォルト実装に対してベンチマーク動かして様子見たりする。試しに campaign=1 にしたら暫定1位になってた。

f:id:q2KWLv7s:20190914124941p:plain

11:10〜12:10

ボトルネックを探るために Python コードに原始的なデバッグコードを仕込んでベンチをする。デバッグコードはこれ https://gitlab.com/nondakure-onkenha/isucon9-qual/commit/969bd7df95b71e57fa3858a508b93b3b41e486f5

この頃から外部API由来の以下のエラーがちょくちょく出て、「何だろうね」みたいな話をしていた。

requests.exceptions.HTTPError: 502 Server Error: Bad Gateway for url: https://shipment27.isucon9q.catatsuy.org/status

12:10〜13:00

この段階で nginx のアクセスログから分析した「重いエンドポイント」がこんな感じ。

normalized_resource	count	avg(sec)	weight
`POST:/buy`	539	2.60	1403
`POST:/login`	660	1.13	742
`GET:/settings`	622	0.87	542
`GET:/items/<int>.json`	932	0.50	470

weight = count * avg

上から潰していこうとなって

POST /buy は外部APIが遅く(一回0.9秒くらい)、直列に2回投げてる。この2回に関連はないので並列に投げよう
特にメリットがあるかもわからないけど、とっとと3台構成にしてしまおう

とか言ってやってた。

13:00〜14:30

外部API並列化 requests-async というライブラリを使った。

async 対応になっていない Flask との共存は結構しんどいので「0.9秒に比べたらオーバヘッドは微々たるもんだよね」といってこんなコードになった。

loop = asyncio.new_event_loop()

async def ship_and_pay(ship_url, ship_header, ship_body,
                       pay_url, pay_body):
    ship = requests_async.post(ship_url, headers=ship_header, json=ship_body)
    pay = requests_async.post(pay_url, json=pay_body)
    return await asyncio.gather(ship, pay)


@app.route("/buy", methods=["POST"])
def post_buy():
    # 略
    ship, pay = loop.run_until_complete(
        ship_and_pay(ship_url, ship_header, ship_body, pay_url, pay_body),
    )
    # 略

実際 POST /buy は0.8秒くらいは早くなった。

あとは categories テーブルをダンプしてハードコーディングしたり、新規ユーザー登録時の bcrypt.gensalt(4) にしたりしてた。

スコアは変わらず。

13:00〜16:30

3台構成にするのが難航する。

外部APIが

403 Forbidden response: {"error":"IP address is not allowed"}

とのエラーを返しまくってベンチが全てこけるようになった。 discardでも同様の質問があったが「マニュアルを確認してください」との回答だった。

原因の結論から言えば、 外部APIにアクセスするサーバーはポータルサイトから登録しておかなければダメ だった。マニュアルの記述で言えば以下が該当すると思う。

ポータルサイトでは、ベンチマーカーが負荷をかける対象となるサーバーを1台に加え、競技に利用するサーバーを2台入力することができます。 後述する競技後の追試でもこの設定を利用します。

これに気づくまでに凄まじい回り道をした

複数台構成にすると403になる
1台構成にすると問題は起きない
nginx が乗っているインスタンス（s1と呼称）にプロキシを建てて、appからのリクエストを s1 経由にするとエラーは起きない
- env.sh に https_proxy を追加することで実現していた
じゃあ全部プロキシ経由にするか
外部API並列化コードをマージしたらまた 403 エラーになる
どうやら requests-async を使っているとプロキシにアクセスが来ていない
requests-asyncが https_proxyを無視しているんじゃね？
アプリケーション側でもいろいろ書くけど、 requests-async だと最後までプロキシを使えない
諦めて httpx を使うことに
httpx はドキュメントを見るとすごく良さそうなのに、実際にはサンプルすら動かないようなライブラリだった
- httpx と requests-asyncは作ってるところが同じ。地雷だった

とかやってるうちにポータルでサーバーを登録すればいいことに気づく。

これが16:30、辛い。

16:30〜17:50

3台構成の内訳は

nginx + MySQL + app(python)
- app は画像系と初期化系を担当
app(python)
app(python)

外部API並列化とほんの少しのチューニングが入った状態でベンチをするも、外部APIの502が多発する（ベンチ的には POST /buy が 500 だったので失敗）。

他チームの運営への同様の質問で「回答できません」だったので、これも仕様だと判断して何とかしようとする。

具体的には「同時アクセス数絞ってみるか」となり、 POST /buy のAPIリクエスト部分をセマフォで囲ったりしていた。セマフォの範囲を変えるために gunicorn のプロセス数（最初は10）を減らしてスレッド数（最初は1）を増やしたりしてた。

十分にプロセス数を減らせば502は出なくなったが、スコアも出なくなった。

じゃあということでリトライを入れる。 10回リトライしても全部502だったので「一旦502になったら二度と生き返らないのかも」となる。

17:50に「ベストスコアを出した構成に戻そう」となる。

17:50〜18:10

最終構成は

nginx + MySQL + app(python)
- app は画像系と初期化系を担当
app(python)
なし

campaign は 2。

gunicorn はプロセス10スレッド1。

ログを削除したり余計なインスタンスを消したりしていた。

再起動試験はできていないが、 systemd の設定だけ見て「大丈夫だろう」となりそのままフィニッシュ。

f:id:q2KWLv7s:20190914142744p:plain

その後

終わってから知ったこと

外部APIの502はベンチマーク終了後にアクセスが来ていたら出る、スコアには関係ない
POST /buy はデッドロックするらしい
N+1 があった（気づいてなかった）

これだけをみると、僕らが502の原因と思っていた外部APIへの同時アクセス数は完全に的外れで、

appが強くなって捌ける量が増える
POST /buy がデッドロック
何かエラー（タイムアウト？）
（ここでベンチ終了）
残っているプロセスからの外部APIリクエストが502

だったのかも。

アプリケーションログのエラーログには外部APIの502しかなかったので完全にそれが原因だと思っていたけど原因は別だったのかも。この頃に nginx のステータスコードもエラーログ（Splunkに入れてすらなかった）も注視していなかったから 499 とか 500 とか出てたのかもしれない。

あと、502と戦っていた時に2回ほどMySQLにロックが残っていてベンチからの初期化に失敗するということがあった。これとかデッドロックの名残だったのかも。詳しく見ずにスルーしてしまった。

反省

アクセスログから見える遅いエンドポイントにこだわり過ぎた
- N+1クエリ見逃した
アプリケーションロジックを読み解かず、コードの字面だけから最適化を初めてしまった
- 実は余計な外部APIリクエストがかなりあったらしい
デバッグ下手
- 外部APIの502の原因切り分けとして取れる手は他にもあった
- プロキシの下りもデバッグが効率的ではなかった
デプロイスクリプト作っとけばよかった
asyncライブラリの調査は普段からしとこう

感想

去年の決勝を思い出す辛いコンテストになってしまった。

外部APIの403に関しては運営質問で答えてくれてもよかったのになーと思っている。

来年もあるなら出たい。

だいじゅの技術メモ

プログラミング関連、ボードゲームの解析、物理シミュレーション関連、その他について書いていく