ISUCON9の予選に参加しました。最終スコアは5410 ｲｽｺｲﾝでした。 結論からいうと当たった施策は1つしかなく、しかもその施策に行き当たったのは偶然だということがわかりました。 この悔しさをバネにして一年間勉強します。

以下にISUCONの行動ログを書きます。行動ログの中に振り返りの内容が混ざっているところがあり読みづらいかも。

追記: 読みづらいところがあったので、記事の構成をかなり変えました(2019/09/09 21:00)

事前準備

  • 当日の動きをTODOリストにした
    • scrapboxを使った
    • このUserscriptが本当に便利。チェックしたときに時刻が入るopt-inの機能があって、これを使ってISUCON当日の作業ログを取った。
  • サーバーのセットアップスクリプトを書いた
    • 設定
      • .zshrc
      • .vimrc
    • ツール
      • alp
      • pt-query-digest
      • mysqltuner
      • sar

当日の動き

10:00~11:30 諸々のセットアップ

  • imageからインスタンスを起動した
  • Alibabaのセキュリティチェック？に引っかかり3つめのインスタンスが起動できないという問題が発生した
    • 運営の方に連絡し、とりあえず先に進んだ
  • 立ち上げたインスタンスにブラウザでアクセスしようとするが接続できずに詰まった
    • nginx.confを見て、SSLじゃないと接続できないということに気づいた
  • マニュアルを読んだ
  • nginxとmysqlとカーネルパラメーター(?)の秘伝のタレを導入した
  • ログローテーションをセットアップした
  • rack-lineprofを入れた

11:30~12:00 unicornを導入して戻した

  • とりあえずベンチマークを回した(1,810 ｲｽｺｲﾝ)
    • topを眺めて、MySQLがCPUめっちゃ消費してるということはわかった
      • Rubyもそれなり
      • nginxはそれほどでもない
  • Rubyの実装のsystemdファイルを見たらrackupコマンドでアプリが起動されていて、「rackupならwebrickだろうしこれをunicornとかに差し替えたらスコア伸びそう」という思考になって、unicornで起動するように設定を変えた
  • ベンチを回したら 410 ｲｽｺｲﾝ に下がってパニックになった (考察)
  • とりあえず起動コマンドをrackupに戻した

12:00~14:00 サービスの気持ちになる

  • ベンチを回した(1,810 ｲｽｺｲﾝ)
  • alpでログの統計を取ったが、これじゃ何もわからんなということがわかった(URLの意味がわからないので)
  • マニュアルとドキュメントを読みつつアプリを実際に動かして理解を深めることにした
  • しかし、Rubyの実装に関して、CSRF tokenまわり(というかsession?)がうまく動いてなくて、商品の購入ができずに詰まっていた (考察)
    • sinatraのsessionを調べたり、設定を色々いじったりしていた
    • Firefoxが悪いのか？と思ってchromeでやってみたが変わらなかった
    • どういう経緯か忘れたが、画像がsinatraから配信されていたのをnginxから配信されるようにした
      • どうせ必要になっただろうしべつにいいんだけど、なぜこのタイミングでやったのかは謎
    • 最終的に、アプリを動かすことは諦めて、URLの意味は想像することにした

14:00~17:00 N+1とWHERE INをJOINに直す

  • 何を思ったかとりあえずcampaignを4にしてベンチを回した(1700 ｲｽｺｲﾝぐらい)
    • アクセスの挙動が変わったのを確認した(しただけ)
  • /loginのレスポンスタイムの合計がやたら長いことが気になって、rack-lineprofで見てみるとBCryptが重いということがわかった (考察)
    • BCryptのコストを10から1に下げた
    • BCrypt::Password の生成をキャッシュした

  • ベンチマークを回したが、スコアは変わらなかった(1700 ｲｽｺｲﾝぐらい)

  • ここで、「MySQLのCPU使用率が高い(100%に張り付いている)のをまずどうにかするべきだ」という気持ちになった
  • pt-query-digestをして重いクエリを特定し、それが GET /new_items/:root_category_id.json から発生していることを突き止めた
    • WHERE status in ('on_sale', 'sold') AND caregory_id in (1,3,10) AND (created_at < '20190827T143034+0900' OR (created_at <= '20190827T143034+0900' AND id < 30000)) みたいなクエリ
    • これどうやったら速くなるの…?となった
    • また、同じエンドポイントの中にN+1クエリも存在していた
    • WHERE INで処理してるところをJOINになおしてついでに他の必要なものもJOINすれば、もとの重いクエリも速くなるしN+1クエリも消せるし最高じゃんという発想になった (考察)
  • 発見したクエリをJOINに直したら激重になって、ベンチ回したら300 ｲｽｺｲﾝまでスコアが下がりパニックになる
  • WHERE category_id = ? みたいな感じで参照されてるカラムに対してindexが貼ってないのに気づいて貼った
    • EXPLAINのrowsの数が100分の1ぐらいまで減った
    • しかしベンチマークを再度回すも300 ｲｽｺｲﾝから変わらず…

17:00~18:00 campaignとrack serverのチューニング

  • ここでおもむろにcampaignの値を4->2に変えてベンチを回してみた
    • 2800 ｲｽｺｲﾝ という値がでてびっくりした
  • じゃあ…ということでcampaignの値を1や0にして試してみた
    • campaign == 1 -> 3900ｲｽｺｲﾝ
    • campaign == 0 -> 1800ｲｽｺｲﾝ
    • campaignを1に変えることにした
  • campaignが1のとき、POST /buy から499というステータスコードが返ってコケていることがわかった
    • 499はnginxが定めるステータスコードで、upstreamがtimeoutしたときに返す番号らしい
    • じゃあタイムアウト伸ばせばいいんじゃないかという発想になった (考察)
  • ここでなぜかnginxのタイムアウトを伸ばす設定をした
    • 当然スコアは変わらない
  • nginxのタイムアウトじゃなくてupstreamのタイムアウト伸ばさなきゃだめじゃんということに気づく
    • しかしrackupコマンドでタイムアウトを設定する方法がわからない
    • なので、webappのsystemdファイルを書き換えて、unicornで起動するように変更し、unicornの設定でtimeoutを伸ばすようにした
      • 一番最初に作ったunicornの設定が残っていたのでそれを転用した
  • unicornに差し替えた状態でベンチ回す -> 4310ｲｽｺｲﾝ !! (考察)
    • ベンチ回している間に、「timeoutだけ伸ばしてworkerの数を増やさなかったら、workerが全部長いリクエストに拘束されて待たされるみたいなことが起こるのでは？」ということに気づく
  • workerを4 -> 16に増やしてベンチを回し直す
    • 5410ｲｽｺｲﾝ !!
  • alpを見ると、最大でも5秒程度でレスポンスが返っていることから、timeoutを5秒程度にしても問題がなさそうということに気づいた
  • workerを16 -> 32に増やしてtimeoutを5秒にして再度ベンチを回す -> スコアは変わらず(5410ｲｽｺｲﾝ)

ここで競技終了

考察

  • rackupをunicornにしたら遅くなった件 🔙
    • おそらくrackupコマンドによって起動していたのはwebrickではなくpumaだった(Gemfileにpumaが入っていた)
    • なのでunicornに変えたところで性能が上がる理由はない
  • Rubyの実装の不具合について 🔙
    • 結果論だが、「手順通りに立ち上げているインスタンスの挙動がおかしい」という状況なのだから、運営の方に確認するべきだった
      • 他の参加者が「CSRF tokenの検証でエラーが起こるがこれは想定された挙動か？」という質問をdiscordでしていて、「把握していない内容だ」という返答がなされているのを見て、この問題を追求してもしょうがないので、実装は動かさずにやるしかねえという気持ちになった
    • また、これも結果論だが、goの実装(初期設定で動く実装)はちゃんと動いていたっぽいので(これも前述の参加者の方の発言にあった)、goの実装に戻して動かすべきだった
      • というか実装を差し替える前にサービスを理解するべき
        • 特にRubyは初めから提供されていた実装ではない(最初から提供されていたのはPerl,PHP,Goだけ)ので、こういうこともあるのだろう1
  • BCryptをキャッシュしても意味がなかった件 🔙
    • BCryptのコストを下げて効果があるのは、新規登録ユーザーだけ(既存のユーザーのハッシュのコストは変えられないため)
    • そもそも1人のユーザーはベンチマーク中に2回以上ログインしないので、ログイン処理をキャッシュすることに意味がない
    • そもそも BCrypt::Password.new をキャッシュしても意味がない(BCrypt"::Password#==が重いので)
      • パスワードを平文で保存した参加者が話題になっていますが、やりたいことは結構近かったのではないかと後から思った
        • ユーザーから送られてきたパスワードをキャッシュして、ログイン時にはBCryptを計算するのではなくキャッシュと突き合わせて認証する、というのは共通している
        • 違うのは、全然キャッシュできていないということと、オンメモリキャッシュなのでデプロイするたびにキャッシュが吹き飛ぶので効率が悪いということ
  • N+1クエリに手を出してしまった件 🔙
    • ボトルネックではないN+1に手を出してしまった時点で負け感がある
      • rack-lineprofを見て、N+1がボトルネックではないことがわかっていたのに手を出してしまった
      • N+1クエリは見つけた人間のIQを下げる効果があるらしい
    • CPU Usageが高い -> N+1クエリが原因だ となってしまったのがだめ
      • CPU Usageが高いときはindexを貼ることを考える
        • N+1クエリは計算量を改善しないが、indexは改善するのでCPUに効く
  • Nginxが499を返していた件 🔙
    • nginxのステータスコード499
    • この記事を見返したら、upstreamのタイムアウトが499になるのではなく、クライアントが予期せぬタイミングでコネクションを切ったときに499になるということらしい
      • 焦っていたので誤読していた
    • また、さっきアクセスログを見返して、POST /buyの400番台のステータスコードのカウントを取ったら、一番多かったのが403だった(499も含めた他のステータスコードはほとんどない)
      • 競技中はアクセスログを grep "POST /buy" して出てきたやつを目視しただけなので、ログ全体を見ていたわけではなく、終盤のログだけを見ていた
        • アクセスログをシュッと解析してどのステータスコードが多いのかをその場でシュッと計算していたら、499がドミナントであるという誤解は生じなかった
        • こういうところで地力が出てしまうなと感じた
      • ベンチマーク終盤に499が頻発していたのは、ベンチマーカーが時間切れで止まったからだろう
      • なので、これ以降の施策が「当たった」のは全くの偶然ということになりますね…
  • unicorn導入したらスコアが上がった件 🔙
    • いまalpの統計を見かえしたら、 POST /buyのエラーを解消できたというわけではなく、さばいているリクエストの数が全体的に増えたということっぽい
    • おそらく POST /login のBCryptの処理がボトルネックになっていたのがunicornにしたことによって解決したという話
      • Gemfileをみたらとpumaが入っていたので、おそらくwebappはデフォルトではpumaで動いていたと考えられる
      • pumaはマルチスレッドのrack serverなので2、BCryptみたいなCPU boundedの処理だとマルチコア(今回は2コア)を有効に使えない
        • RubyのGILのせい
      • unicornはマルチプロセスのrack serverなので、マルチコアを有効に使ってBCryptの計算ができたのではないかと考えられる
    • 一番最初にunicornを入れて性能が落ちたのは、そのときのボトルネックがBCryptではなかったからではないかと考えられる
      • 最初にunicornを入れたときはcampaign値が0だったので、ベンチマーカーの挙動が違った可能性がある

振り返り

  • 参加にあたって「少しでもスコアを上げる」というのを目標にしていたので、まあ及第点かなという感想
    • ISUCON8は1点も伸びずに悔しい思いをしたので大きな前進
  • 無理やんけ -> 諦め ができてたのは偉かった
    • なぜかMySQLを他のサーバーに出すと接続できなかった
    • BCryptが高速化できなかった
    • うまくいくまでやったらそれだけでISUCON終わってたかもしれない
    • ブラウザ上でアプリケーションを動かすことにこだわってしまったのは良くなかったので反省する
  • レギュレーションがちゃんと読めてたのは良かった
    • BCrypt平文禁止もキャンペーンの存在も気づけていた
    • それを活かせるかは別の問題だが…
  • 結局、初見のアプリケーションをぽんと渡されて、8時間しかない中で最適化をする必要がありますって言われたとして、ユーザーの行動ログをじっと眺めてクリティカルパスを見つけて最適な場所を最適な方法で直すっていうのは、少なくとも僕にとっては無理なので、問題になってそうな場所に検討をつけて、ある程度投機的に最適化を入れていく必要がある
    • 「本当にこれがボトルネックなのか？」みたいなのは考えすぎても意味がなく、その意味では求められているのは手の速さだし、勝とうと思ったら人数が必要だと言われているのも納得(なので1人チームが1位取ってるの本当にすごい どうやってるんだろう)
  • 自分のデータベースへの弱点があらわになってしまった
    • 生SQLを書きなれてないので、ちょっと複雑なクエリになると書くのにけっこう苦労した
    • N+1を雑にJOINに直しただけでは速くならなかったことがあって、結局indexが適切に貼れてなかったからというのがわかったんだが、つまりJOINの挙動を知らないことと、indexへの意識が足りていない
    • これらは絶対に来年までに勉強して解決する
  • 作業ログを残しておいたのは結構良かった
    • 振り返り、反省が可能になる
  • 全体的に観察が足りてなかった感じがする
    • campaignを動かして、ベンチマーカーの挙動を観察する
      • campaignの値によってユーザーの行動がどう変わるのか、ということは考察するべきだった
      • 一回ベンチ回すのに2分ぐらいしかかからんし、全部試しても10分ぐらいで終わるからやるべきだった
    • POST /buyのエラー率の高さに気づく
    • ベンチマーカーの気持ちになる
      • ログインから取引終了に至るまでのファネル書いてた人もいるらしい
      • 何人ログインして、このエンドポイントが何回叩かれて、みたいなのを考えるとベンチマーカーの気持ちになれて良さそう
      • ファネル書いたらPOST /buyのエラー率にも初期段階で気づけてたかもしれない

雑感

  • sarの使い勝手が悪かった
    • 過去ログ見たくて導入したけど時間指定するのが面倒
    • デプロイしたタイミングでローテートするみたいな仕組みを作らないと快適にならなさそう
    • 結局topとvmstat見てた
  • BCryptを速くするのってどうするのが正解だったんですかね
    • そもそもBCryptが遅いのはなんでなんだろう
    • CPUバウンドで遅いのであればサーバーを複数台構成にするしかないのかな
      • POST /loginだけnginxで別のサーバーにリダイレクトするという話を聞いた
  • ネットワークがサチり気味だったとかいう話を見た
    • 全然気づかなかった。そもそもPublicとPrivateどっちからアクセス来てたんだろう。というかそれってどうやって調べるの？
      • 前日読んだ記事に書いてあった。このコマンド打ったことあるのになぜ忘れていたのか… https://qiita.com/makaaso/items/6e27a2f0948241891667#network%E4%BD%BF%E7%94%A8%E7%8A%B6%E6%B3%81%E7%A2%BA%E8%AA%8Dnic%E5%8D%98%E4%BD%8D
    • どっちにせよネットワークがサチるほどアクセスさばけてなかったと思うが
  • そういえばnginxがSSLを復号する処理、結構CPUを食っていたのではないか？
    • nginxのCPU使用率が結構高かった気がする
    • もしここをどうにかしようと思ったら、暗号化スイートをもっと計算量が小さいやつにしたりとか、nginxとアプリケーションサーバーを別のインスタンスで動かすとかしたらいいのだろうか
  • rack-lineprofは使いやすいし分かりやすくていいんですが、ベンチマークリクエストに対してプロファイリングができないという問題がある
    • リクエストの後ろにlineprof=web.rbみたいなのをつけなくてはならないため
    • 実は前日にstackprofというのも試してたんですが、なんかうまく導入できなかったので諦めた
    • 普段から素振りしておくことが大事っぽいのでやっていきたい
    • あとstackprofとかrack-lineprofの動作原理がわかってないので、そのあたりも勉強しておきたい
  • unicornとかpumaの秘伝のタレも用意しておいたほうが良いかもしれない

  1. http://isucon.net/archives/53555578.html ↩

  2. Cluster modeを設定すればマルチプロセスになるが、デフォルトだとシングルプロセスだと思う(たぶん) ↩