理系学生日記

おまえはいつまで学生気分なのか

ISUCON11予選で敗退してきました

usual day

一昨年同様、@kkasaiさん、@hondaYoshitakaさんとISUCON 11へ参加しました。

一昨年はインスタンスチェックに失敗し、まさかのスコア0でフィニッシュでした。 一方で、今年はきちんとインスタンチェックも無事パスし、最終的なスコアは12,000前後という結果です。 参加チーム数が598組(1,421名)、最終的なぼくたちの順位は半分よりちょっと上くらいになりました。

対象となったお題やレギュレーションはこちらで公開されています。

インフラ

今回対象となったクラウドサービスはAWSでした。 チューニング対象となるシステムのインフラは、競技を開始した10:00から、公式から提供されるCloudFormationのコードを展開して構築します。 構築自体はスムーズに完了しました。あらかじめGitHubに登録したsshの鍵でログインができるようになる親切設計です。

構成としては、VPC内に3台のEC2が構築されるというシンプルなものです。

個々のEC2の中はほぼ同一構成となっており、nginx、アプリ(isucondition)、MariaDBで構築されていました。

ファシリティ

コロナ禍のため、全員が自宅からの参加です。 コミュニケーションはDiscord、リポジトリはGitHub、タスク管理や図の共有はmiroを使いました。

ソースの共有はCode With Meを利用しました。 こちらは、全員がIDEを共有しながらリアルタイムにコーディングを行えるというものです。 ある種モブプロのような開発になるわけで、私にとって初体験でしたが、極めて良い経験でした。

状況の確認

エンドポイント

ISUCON11にはNew Relic支援プログラムが存在するため、こちらを利用してパフォーマンスの悪いエンドポイントを確認することから始めました。

@kasaiが10個くらい出してくれて、おおよそ以下のエンドポイントから潰していこうという方針です。

  1. /POST /api/condition/:jira_isu_uuid
  2. /GET /api/isu

それぞれのソースについては@hondaYoshitakaさんが解析し、チューニングポイントを検討してくれました。

nginx

私の方もnginxのログ設定に$request_timeを加え、アクセスログにレスポンスタイムが出力されるようにしました。 その後、ベンチマーカーがどのようなアクセスパターンなのかを解析してみていました。

https://f.hatena.ne.jp/kiririmode/20210828090438

MariaDB

DB側で遅いクエリに関しては、@kasaiがスロークエリを取得し、いくつかマズそうなクエリを見つけてくれました。

Golang

ぼくはGoのプロファイラ(net/http/pprof)を担当しました。 前回は以下のような結果を取得し、ここからもチューニングポイントを絞り込んだので、それを再びという気だったのですが。

f:id:kiririmode:20190915083503p:plain

なぜか今回はその結果が取れず、CLIでpprofを操作して、時間がかかっているポイントを調べることにしました。

(pprof) peek getTrend
Showing nodes accounting for 40.65s, 100% of 40.65s total
----------------------------------------------------------+-------------
      flat  flat%   sum%        cum   cum%   calls calls% + context
----------------------------------------------------------+-------------
                                            17.63s   100% |   github.com/labstack/echo/v4.(*Echo).add.func1
         0     0%     0%     17.63s 43.37%                | main.getTrend
                                            17.62s 99.94% |   github.com/jmoiron/sqlx.(*DB).Select (inline)
                                             0.01s 0.057% |   runtime.duffcopy
----------------------------------------------------------+-------------

やったこと

インデックスの付与

MariaDBには全4テーブルがありました。 このうち今回のアプリは、isu、isu_conditionあたりに多くのクエリが発行される実装になっています。

+------------------------+
| Tables_in_isucondition |
+------------------------+
| isu                    |
| isu_association_config |
| isu_condition          |
| user                   |
+------------------------+
4 rows in set (0.000 sec)

大量レコードの検索キーになっているにもかかわらず、インデックスが貼られていない部分にインデックスを張っていきます。

POST /api/condition/:jia_isu_uuidのBulk Insert対応

POST /api/condition/:jia_isu_uuidのAPI実装では多数回のinsertを独立したINSERT文で行っていたため、 これをbulk insertに変更しました。

POST /api/condition/:jia_isu_uuidでリクエストをdropしない

スコア加点要素としてISUのConditionは重要です。

ISU のコンディション確認（GET /api/condition/:jia_isu_uuid）で、ユーザが前回確認したコンディションより新しいコンディションを確認した際に加点

  • Info（50 件ごとに 20 点）
  • Warning（50 件ごとに 8 点）
  • Critical（50 件ごとに 4 点）

負荷走行時における加点について

その登録APIには一定確率でリクエストを落とす実装がされていました。

/ POST /api/condition/:jia_isu_uuid
// ISUからのコンディションを受け取る
func postIsuCondition(c echo.Context) error {
    // TODO: 一定割合リクエストを落としてしのぐようにしたが、本来は全量さばけるようにすべき
    dropProbability := 0.9
    if rand.Float64() <= dropProbability {
        c.Logger().Warnf("drop post isu condition request")
        return c.NoContent(http.StatusAccepted)
    }

これをすべて処理するように修正しました。 おそらく、我々がカリカリにチューニングできれば、このあたりがボトルネック化してくるのでしょう。 一方で今回我々がチューニングできた範囲だと、ここがボトルネックになるまでに至らなかったようです。

GET /api/isu/:jia_isu_uuid/iconのCache-Control対応

椅子画像を取得するGET /api/isu/:jia_isu_uuid/iconでは、データベース上に格納されているバイナリ画像を読み出し返却します。 ベンチマーカーはConditional GETに対応していること、 それなりにサイズの大きな入出力を都度させたくなかったため、当該APIではCache-Controlヘッダを返すようにしました。

画像が最新でなかったとしてもスコア減点要素はなかったため、雑にmax-age=60を指定しています。 スコアが下がったらチューニングする方針でしたが、スコアはあがったのでこのままいきました。

    c.Response().Header().Set("Cache-Control", "max-age=60")

なお、画像をデータベースではなくファイルとして保存しnginx等からサーブさせるという案もありましたが、 実装にちょっと時間がかかりそうなので見送りました。

MariaDBの外だし

EC2は3インスタンスある中で、ベンチマークは1インスタンスに対してのみ実行します。 MariaDBはCPU boundになっていたこともあり、アプリが利用するデータベースを別EC2インスタンス上のMariaDBへ向けるようにしました。

ベンチマーカーは、アプリの初期化用エンドポイント/initializeを実行し、データベースのデータを初期化するところからスタートする仕様になっています。 このため、単純にアプリ設定のホスト名変更ではうまくいきませんでしたが、そのあたりは@kasaiさんがうまく対応してくれました。

Echoのログを抜いた

pprofのpeekを見る限り、ログ出力に時間がかかる様子も見えていたため、EchoのLogger Middlewareを抜きました。

最後にインスタンスチェッカーだけ流し、タイムアップを迎えました。

$ isucon@ip-192-168-0-11:~/webapp/go$ sudo /opt/isucon-env-checker/isucon-env-checker
環境をチェックしています...
全てのチェックをパスしました

感想

振り返ってみれば、やればよかったことはたくさんあります。 コネクションプールの設定やAPMの駆使はチーム内でも話にあがりましたし、ジェイウォークも直したかった。

やるべきことはわかっているのに、実装スピードの出ないもどかしさがありました。 Golangを多少触ったくらいではなかなか対応できません。チームとして苦しんだポイントでした。

ただ、それでも2年ぶりのISUCONはとても楽しかったです。 アーキテクチャ図等が整備された中で計画を立て確実に進めていくのではなく、 瞬発的な仮説検証を繰り返すアプローチは、エンジニアとして非常に刺激的でした。 本戦進出を目指して、またぜひ精進して参加したいです。

もう1つ感動したのが運営で、これだけの規模のコンテストをここまでの完成度で運営できるというのはそれだけで優勝では ？ 本当にお疲れ様でした。

なお、この日が妻の誕生日と重複していた点については参加申し込みをした後に気づき、誠心誠意謝罪いたしました。