社内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 以降だったので、今回の敗因は以下に尽きると思います😇

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

ISUCON 9 予選を通過しました!

ISUCON9 予選に 「tmp」 というチーム名で参加し、10,450 点でギリギリ予選を通過することが出来ました。 大学の同期で社会人1年目が2人と修士1年生が1人のチームでした、ISUCON7では学生枠で本戦に出場させてもらいましたが、今回は社会人枠 (?) として予選を通過することが出来たのでとても嬉しいです!

メンバー

最終構成

2台目の Nginx から 1,2,3 台目の App に振り分け、App から 1 台目の MySQL, 3 台目の Redis へそれぞれ振り分けました。AppはGo言語です。

f:id:skitazawa1121:20190909002922p:plain

チームでやったこと

以下チームでやったことです。だいたいこの順番でやったはずですが記憶はあいまいです。

序盤

競技が始まってすぐに秘伝のタレと呼ばれる初期設定の反映作業やデプロイツールの配置等を行い、その後は大まかに自分と @ranksai がアプリケーション、@boringsloth がインフラ周りという役割分担でやりました。序盤の流れは学生時代から数回ISUCONの過去問で練習を重ねていたためすんなりと行うことが出来ました。

getNewCategoryItems() の N+1 の改善

getNewCategoryItems() の中で items の数だけ売り手の情報やカタログの情報を SELECT していた部分が重そうだったので、そこを改善しました。 売り手情報を引っ張ってくる getUserSimpleByID() の部分は N+1 の 1 のクエリとJOINし、カテゴリ情報を引っ張ってくる getCategoryByID() の部分は親カテゴリが存在するかを再帰的にチェックする部分を上手くJOINする方法が思いつかなかったため、カテゴリIDからCategoryを引けるmapをキャッシュすることで対応しました。

複数台構成

上記の N+1 を自分と @ranksai がやってる間、@boringsloth が複数台構成にしてくれました。 途中、ポータルサイトServers にベンチ対象となるサーバをすべて登録しないといけない仕様に気付かなかった等いろいろと苦しんでそうだったので、自分はめっちゃ応援 (ひとまかせ) してました!

キャッシュをRedisに

N+1を解消する際にカテゴリをキャッシュしましたが、複数台構成にするにあたりこれをRedisに乗せました。ここは特につまるところなく出来たので個人的に良かったなと思っています。

Index を貼る

ISUCON8の予選でもそうでしたが、今回のベンチは /initialize に POST が来たときに sql/init.sh ファイルを別プロセスで実行することでデータベースの初期化を行っていました。 ここで、init.sh では一度データベースをDropした後にCreateしてデータを注入するため、事前にインデックスが張られていてもベンチが走るたびにインデックスが吹っ飛びます。競技中盤には上記の仕様を把握していたのですが、 sql/init.sh に足したインデックスを張るコマンドが上手く実行できてない (スクリプトの途中にエラーしてexitしてた?) 問題のせいで競技終了30分前まで思うように点数が伸びなかったです。

競技終了30分前に適切にインデックスを張り、その後30分間でログ出力をやめたりCampaignの値を変えてみたりを行い、最終的に 10,450 点で終了しました。以下は点数の遷移のグラフです。

f:id:skitazawa1121:20190909002919p:plain

やれなかったこと

Bcrypt の処理が非常に重いのを観測しましたが、残り時間も少なく特になにも対応できませんでした。競技終了後に感想部屋で、「APIを非同期化する」だったり「複数回benchを回してみて割と決まったユーザからしかログイン要求が来ないので、生パスワードをダンプしてsha256で保存しておく」などのアイデアを見てなるほどなあとなりました。

以下は競技終了直前の pprof です。Bcryptの処理がすごい重い・・・

(pprof) top -cum 30
Showing nodes accounting for 73.48s, 94.29% of 77.93s total
Dropped 721 nodes (cum <= 0.39s)
Showing top 30 nodes out of 54
      flat  flat%   sum%        cum   cum%
     0.01s 0.013% 0.013%     76.92s 98.70%  net/http.(*conn).serve
         0     0% 0.013%     76.56s 98.24%  goji%2eio.(*Mux).ServeHTTP
         0     0% 0.013%     76.56s 98.24%  net/http.serverHandler.ServeHTTP
         0     0% 0.013%     76.53s 98.20%  goji%2eio.dispatch.ServeHTTP
         0     0% 0.013%     76.53s 98.20%  net/http.HandlerFunc.ServeHTTP
         0     0% 0.013%     72.21s 92.66%  main.postLogin
         0     0% 0.013%     72.03s 92.43%  golang.org/x/crypto/bcrypt.CompareHashAndPassword
         0     0% 0.013%     72.01s 92.40%  golang.org/x/crypto/bcrypt.bcrypt
     0.03s 0.038% 0.051%     71.98s 92.36%  golang.org/x/crypto/bcrypt.expensiveBlowfishSetup
     3.54s  4.54%  4.59%     71.89s 92.25%  golang.org/x/crypto/blowfish.ExpandKey
    68.42s 87.80% 92.39%     68.42s 87.80%  golang.org/x/crypto/blowfish.encryptBlock
     0.02s 0.026% 92.42%      1.59s  2.04%  main.getNewCategoryItems
...

感想

全体的に「ISUCON」という競技において抑えるところは抑えることが出来たかなと思います。ただここから点数を伸ばすためにはもっと序盤や中盤の実装を早く済ませるための実装力が無いとダメだと個人的に痛感しました。普段からこの手のアプリケーションに触れて、世の中のスーパーなエンジニアを目指しもっと頑張りたいと思います。

余談

もともと競技日は開始30分前に母校の大学に集まってどこかの席を借りてやる予定 (と勝手に思って) ましたが、起床試験にfailした人やらそもそもリモート参加で大学に来ない人やらで朝からわちゃわちゃしてました。開始が10分遅れてくれて結構助かりました・・・。

〆はラーメン (と酒) !

f:id:skitazawa1121:20190909002916j:plain