社内ISUCONに参加しました

先日、社内 ISUCON である N-ISUCON に出場して惨敗しました。とても悔しいので振り返りの意を込めてブログを書くことにしました。

どんな問題だったか

Niita という 某技術情報共有サービス ポエム投稿サイトをお題とした問題です。 トップページにてWebpackで固められたjsが配送され、そこからバックエンドの API を叩いて得られる記事やユーザ情報のjsonを取得して表示するようなアプリケーションでした。バックエンドの初期実装は Python, Ruby, Go, Node.js があり、フロントエンドはWebpackでビルド済みのhtml, css, jsファイルが各1ファイルずつのみありました。

初期構成は以下のような感じでした。

  • Ubuntu 18.04 * 3 台
    • vCPU 2 core
    • Memory 1.7 GB

f:id:skitazawa1121:20190911203152p:plain

なお、自分たちのチームは Go 言語を使用したため、以降は Go 言語を前提として話します。

初期スコア : -200 点くらい

とりあえず点数を見て 「・・・マイナス?🤔」 となりました、ただこの時点ではタイムアウトが頻発した結果だと判断し普段どおりに進めていこうとなりました。

とりあえず初期状態で HTTP 配送サーバが Apache でしたので、使い慣れているnginxに移行しました。また、ボトルネック調査のために ISUCON 恒例の以下の作業を行いました。

  • nginx のログフォーマットを ltsv にして alp で解析
  • MySQL にスロークエリログを吐かせて pt-query-digest で解析
  • アプリケーションに pprof を追加

11:00 ハッシュを標準ライブラリを用いて実装 : -3000 点くらい

pprofを見ると、ユーザ認証で使用する関数内で「生パスワードにソルトを付与してsha256を1000回かける」といった処理をしていた部分が重かったです。当関数内では exec.Command を使用して外部プロセスで openssl sha256 コマンドを実行していたため、Go言語の sha256 ライブラリを用いて実装をしました。

11:00 は当実装がコミットされた時間ですが、ベンチマーカーが -3000 点という点数を叩き出したため、この後1時間くらいハッシュの実装のプリントデバッグやnginxの移行ミスを疑ったりしてました。ちなみにハッシュの実装に関してはブラウザから実際にログインできるかを確認するだけでよかったと気づいたのは14:30あたりです・・・。

12:00 クエリ改善 : -800 点くらい

自分がハッシュの問題に取り組んでる間に他のチームメンバーが行ってくれました。 /items のGETのハンドラの処理がとても重く、中を見ると SELECT COUNT(*) 1回で引けるところを SELECT id を引いて for 文の中で count++ をしていたため、そこの修正を行いました。

なおこの時点ではハッシュ化の実装は当作業ブランチに反映されてません。

13:30 画像ファイルの外出し : -20000 点くらい

ハッシュの実装はまだどこかがサチってるせいだという判断 (今思うと謎判断) で、スロークエリログで一番支配的な箇所であるDBから画像データの取得箇所の改善を行いました。それとこのあたりでDBにインデックスも張りました。

画像データは /users/:username/icon というパスでアクセスされるため、適当にDBから画像を抜き出す Python スクリプトを書き、/users/:username/icon へのGETはnginx の try_files を用いて配送するよう実装しました。また、/users/:username/icon へのPOSTで画像データがアップロードされるため、当ハンドラで画像データをファイルに書き出す処理を追加しました。

bench 中に dstat を見てると net/totalsend のカラムで 150~300M という値をずっとウロウロしていて帯域がサチってるのか?となったため、複数台構成にしてみるかとなりました。ここも今思うとそもそもハッシュの実装で -3000 点を出してる時点で問題は別にあると気づくべきでした。ちなみに send が 1Gbps を超えている理由は未だにわかってません (どなたか教えてください🙇)。 追記: GCE は Ingress 10Gbps, Egress 4Gbps (1vCPUあたり 2Gbps) だと教えていただきました! (参考: https://www.slideshare.net/GoogleCloudPlatformJP/cloud-onair-google-networking-deep-dive-201889 の P24)

13:30 - 15:50 お通夜ムード

複数台構成にするとベンチで不整合のエラーが出力されて結局複数台構成には出来ませんでした。後ほどアプリケーションを確認しましたが、ベンチ時にDBのイニシャライズを行う common/db/init.shmysql -h localhost を指定されていたためこれが原因かもしれません。アプリケーションのsystemdファイルの参照する環境情報ファイルが /home/isucon/.env だったのでこちらのみを修正して安心しきってました。

その他、アプリケーションを初期バージョンへrevertしてみてどこにバグが混ざったかの確認を行ったりもしました。この時点で既にかなり参っていたため「初期実装が悪いだろーーー」と数回言ったのを覚えています。

15:50 Python実装に切り替え : 208点 (Best Score)

取り敢えず点数出そうと言ってバックエンドの実装を Python に切り替えました。後日スコアサーバを確認したところ上記のスコアでした🙃

感想 (反省)

競技後の懇親会で知りましたが、ベンチの点数が永遠にマイナスな問題はGo言語の初期実装が悪いという「仕様」だったそうです (マニュアルにも、スコアがマイナスになる場合があるがそれは仕様であると書かれてました)。ベンチマーカー的には /users//icon (/usrs/:username/icon:username が空な場合) は 404 を返す想定だが、今回だと Golang の goji フレームワークのみ /users//icon301 Moved Permanently (/users/icon) をレスポンスするため無事死亡したみたいです。

個人的には、ベンチのバリデーションチェックが通らない場合は 0点(FAIL) となりエラー原因が出力されましたが、バリデーションチェックに通った場合はエラーしたリクエストの原因が出力されないのが辛かったです。特に上記の /users//icon のようなリクエストはバリデーションチェック後に来るために競技終了までずっと気づけませんでした・・・。

懇親会にてGo言語を使用した他チームにどうやってこの問題に気づいたかを聞いたところ、kataribe で見たら異様に 301 があったのが怪しかったからと言ってました。自分たちの使用していた alp ではステータスコード出力されてないぞと思い調べてみたら alp がステータスコードを吐くのは v0.4.0 以降だったので、今回の敗因は以下に尽きると思います😇

最後となりますが、とても悔しいですがとても楽しいイベントだったため運営の方々にはとても感謝しています。次回こそ参加者としていい結果を残したいと思いつつ運営もやってみたいなーという気持ちなので次回開催を楽しみにしてます!