Classi開発者ブログ

教育プラットフォーム「Classi」を開発・運営するClassi株式会社の開発者ブログです。

ISUCON12予選 スコア4位相当でしたが失格になりました

勉強会・イベント

TL;DR

こんにちは。Classi開発部のminhquang4334です。 今年は開発支援部のhenchiyb先輩と一緒に 2回目でyasuoチームとして ISUCON12の予選に参加しました (参考: 1回目で参加したブログ)。

最終結果は予選通過スコアを超えて、 4位/700チーム相当でしたが、SecurityGroupの TCP:8080 ポートがオープンされていたため、レギュレーションに引っ掛かって失敗しました。

以下のチームは予選通過スコアを記録していましたが、追試において失格となっています。

  • yasuo

    • 環境チェックにおいて、SecurityGroupの TCP:8080 ポートがオープンされていた

このブログでは積極的に自分の感想やチームがやったことを共有したいと思っています。

全体的な感想

正直、悲しい気持ち半分、嬉しい気持ち半分で戸惑っています。予選の実施前には、ここまでスコアを伸ばして、上位のチームと並べるのが想像できなかったので、競技中にリーダボードでずっと1位や2位などになっているのがとても嬉しかったです。しかし、そこまでやったのに、夢でも考えられないポート公開したミスで、失格となったことはとても悔しい気持ちでした。

失格という結果だけみると、大失敗のようですが、私がISUCONに参加した目的は自己成長で、昨年参加した時の結果である100位から今年の上位のチームになるまで学びになったことは数多くあるため、大成功だと考えています。

体制

今回チームは二人の体制で予選に参加しました。

  • アプリケーション担当: minhquang4334
    • 役割: ファシリテーターとしてアプリケーションとデータベース周りの改善を進める
  • インフラ担当: henchiyb
    • 役割: インフラ設定やチューニングやスクリプト作成など

二人は同じビルに住んでいますが、Meet経由でお互いに画面を共有しながら、作業を行いました。チャットはSlackを使いました。

使用したツール

  • mysqldumpslow
  • alp
  • top
  • pprof
    • プロファイリングを見るため、TCP:8080 ポートを公開したので、失敗になった原因だ
  • VSCode

チームの方針

予選に参加する前に、チーム内のアグリーメントを決めました。

  • 実装言語はGoにする
    • 予選までアプリケーション担当の自分の経験は6ヶ月しかないが、社内のGoベテランから色々教わっていたため
  • 自動のスクリプト使用する
    • Gitにコミットしてからなるべく早くリリースできるようにスクリプトを工夫した
    • モニタリング結果の取得でも一括取得できるためのスクリプトなど
  • 複数選択肢がある場合、ロジック修正が必要ない選択肢を優先する
    • ロジック修正はミスになりやすいし、デバッグ時間もかかる
    • 例として、N+1の問題であれば、N+1を解消するより、キャッシュの方が簡単にできたら、キュッシュする
  • チームなりのベストプラクティス資料を準備して、それ以外に経験がない技術ならやらない
    • たった8時間の競技で新しい技術を試したら、リスクが高いし、失敗したら精神も落ちる
  • モニタリング結果を心から信じて、それに基づいて改善する
    • 推測するな、計測しよう
    • topやalpやslowlogの結果などを斜めてから、改善の優先順位を判断して進める

当日チームのリポジトリと関連な情報

最終構成

  • サーバー 1つ目: Nginx
  • サーバー 2つ目: アプリケーション + SQLite
  • サーバー 3つ目: MySQL

結果

リーダボード

最大スコアは 75209点で、最終スコアは 59911点です。

競技終了時間のリーダボード

スコア変動

15時ごろ予選通過スコアを超えました。

yasuoチームの競技中のスコア変動グラフ

やったこと

10:32 最初のモニタリング結果 (スコア： 3768)

運営チームから準備してくれたCloud FormationをAWSに適用したり、インスタンスにアクセスしたり、gitやalpやslowログを設定したりするのが30分ぐらいかかりました。10:32ごろに初めてモニタリング結果を出力しながら、ベンチマーカーを実行できました。

10:46 Visit HistoryテーブルにIndexを適用する (スコア： 4920)

モニタリング結果をみたら、すぐにMysqlのCPU利用率が高すぎることや遅いクエリがあると見えました。

# top
   PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND                                                                                  
   4883 mysql     20   0 2569292 528048  34932 S  89.0  13.9   2:27.14 mysqld 

# slowログ

Count: 2106  Time=0.05s (106s)  Lock=0.00s (0s)  Rows=83.3 (175390), isucon[isucon]@localhost
  SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = N AND competition_id = 'S' GROUP BY player_id

MysqlのCPU利用率を減らしないと前に進められないため、Indexを追加しました。以下のIndexを追加した結果、1千点ぐらいのスコア伸ばしました。

CREATE INDEX `visit_history_id_idx` ON visit_history (`tenant_id`, `competition_id`, `player_id`);

このvisit_historyテーブルは初期データでは32万ぐらいのレコードがあるため、Indexの作成時間もかなりかかりました。

10:57 いつもの設定 (スコア： 5094)

  • いつもと同じ設定を追加して、少しスコアが増えました。
    • MySQLに接続するオプションのinterpolateParams=trueに設定する
    • アプリケーションのDebugモードを外して、e.Use(middleware.Logger())をコメントアウトする

12:04 Nginxとアプリケーションの様々なチューニングを行う (スコア： 9955)

11:00からの一時間ぐらいでいくつかの修正を行いました。

  • Staticファイル (.css, .jsなど)をNginxに任せて配信したり、Expiresを設定したりする
  • playerテーブルとcompetitionテーブルはほぼInsertで、Updateがあまりないため、Goでオンメモリにした
  • competitionScoreHandlerメソッドのplayer_scoreのデータをCSVから挿入する処理は N+1になっているので、Bulk Insert化した

チューニングした結果、2倍近くスコアを伸ばしました

12:14 MySQLでID Generatorをやめる (スコア： 11884)

予選のアプリはマルチテナントの仕組みで、複数のテナントデータベースがあるが、テナントのテーブルのIDを発行する処理は共通データベースに任せる仕組みです。

// システム全体で一意なIDを生成する
func dispenseID(ctx context.Context) (string, error) {
//省略
ret, err := adminDB.ExecContext(ctx, "REPLACE INTO id_generator (stub) VALUES (?);", "a")
//省略

id_generatorテーブルの構成ですが、PKのIDカラムが AUTO_INCREMENTと設定されて、順番的にIDを生成する必要があるため、高負荷のシステムに適切ではない仕組みです (参考: MySQL AUTO_INCREMENT ハンドリング)。なので、その仕組みをやめて、Goのxidを採用して、アプリケーション側で一意なIDを発行できるように修正しました。

// システム全体で一意なIDを生成する
func dispenseID(ctx context.Context) (string, error) {
  guid := xid.New()
  return fmt.Sprintf("%x", guid.String()), nil
}

この修正を反映して、ベンチマーカーを実行したら、初めて1万点を超えるチームになりました。リーダーボードでも一位になったことを気づいて、自信を持てました。

12時ごろから初めて1万点を超えるチームになりました

12:36 playerの最新スコアを latest_player_scoreで保存できるようにSQLiteのトリガーを工夫する (スコア: 12472)

alpを確認したら、/api/player/player/:player_idと/api/player/competition/:competition_id/rankingは遅いエンドポイントなので、なんとかしないとなあと思いました。

+-------+-----+------+-----+-----+-----+--------+---------------------------------------+-------+--------+----------+-------+-------+-------+--------+--------+-----------+------------+--------------+-----------+
| COUNT | 1XX | 2XX  | 3XX | 4XX | 5XX | METHOD |                  URI                  |  MIN  |  MAX   |   SUM    |  AVG  |  P90  |  P95  |  P99   | STDDEV | MIN(BODY) | MAX(BODY)  |  SUM(BODY)   | AVG(BODY) |
+-------+-----+------+-----+-----+-----+--------+---------------------------------------+-------+--------+----------+-------+-------+-------+--------+--------+-----------+------------+--------------+-----------+
|  5029 |   0 | 4977 |   0 |  52 |   0 | GET    | /api/player/player/                   | 0.008 | 22.848 | 1283.200 | 0.255 | 0.360 | 1.624 |  3.768 |  0.982 |     0.000 |   2124.000 |  5922926.000 |  1177.754 |
|  2823 |   0 | 2790 |   0 |  33 |   0 | GET    | /api/player/competition/              | 0.004 | 22.316 |  585.556 | 0.207 | 0.224 | 0.680 |  3.528 |  1.039 |     0.000 |  12265.000 | 26362948.000 |  9338.628 |

両方のAPIはテナントデータベースのplayer_scoreテーブルに触って、playerの最新スコアを取得しています。player_scoreテーブルはplayerのベンチマーカーの実行回数とスコアを履歴として保存するテーブルです。なので、playerの最新スコアがあるレコードだけは別のテーブルで保存した方がより効率になると思って、latest_player_scoreテーブルを作成しました。player_scoreにレコード追加・更新が発生したら、トリガー経由でlatest_player_scoreも追加・更新できるように設定しました。SQLiteのトリガーは書いたことがないですが、無事に以下のように実装できました。

CREATE TABLE latest_player_score (
  id VARCHAR(255) NOT NULL,
  tenant_id BIGINT NOT NULL,
  player_id VARCHAR(255) NOT NULL,
  competition_id VARCHAR(255) NOT NULL,
  score BIGINT NOT NULL,
  row_num BIGINT NOT NULL,
  PRIMARY KEY(tenant_id, competition_id, player_id)
);

CREATE TRIGGER IF NOT EXISTS tr1 AFTER INSERT ON player_score
BEGIN
  INSERT OR REPLACE INTO latest_player_score(id, tenant_id, player_id, competition_id, score, row_num) VALUES(NEW.id, NEW.tenant_id, NEW.player_id, NEW.competition_id, NEW.score, NEW.row_num);
END;

それにより、アプリケーション側でplayerの最新スコアを取得する処理はlatest_player_scoreでクエリできるように修正して、不要なORDER BYも外せました。

-- 修正前
SELECT * FROM player_score WHERE tenant_id = ? AND competition_id = ? AND player_id = ? ORDER BY row_num DESC LIMIT 1

-- 修正後
SELECT * FROM latest_player_score WHERE tenant_id = ? AND competition_id = ? AND player_id = ? LIMIT 1

14:12 N+1解消とsort.Sliceを外す (スコア: 15175)

  • /api/player/player/:player_idではlatest_player_scoreでクエリした後、まだN+1の問題が残っているので、解消した
  • /api/player/competition/:competition_id/ranking ではplayerのランキングを取得する処理はGoのsort.Slice処理などをやめて、全部クエリに任せた
SELECT * FROM latest_player_score WHERE tenant_id = ? AND competition_id = ? ORDER BY score DESC, row_num ASC LIMIT ?

14:31 /api/organizer/players/add のBulk Insert 化 (スコア： 18581)

/api/organizer/players/addでplayerを追加する処理が N+1なので、Bulk Insert化しました。

14:55 終了した大会の請求金額計算をキャッシュ (スコア： 22705)

alpを確認したら、請求金額計算APIが遅くて、15s以上かかるAPIがありました。

+-------+-----+------+-----+-----+-----+--------+---------------------------------------+-------+--------+---------+-------+-------+--------+--------+--------+-----------+------------+--------------+-----------+
| COUNT | 1XX | 2XX  | 3XX | 4XX | 5XX | METHOD |                  URI                  |  MIN  |  MAX   |   SUM   |  AVG  |  P90  |  P95   |  P99   | STDDEV | MIN(BODY) | MAX(BODY)  |  SUM(BODY)   | AVG(BODY) |
+-------+-----+------+-----+-----+-----+--------+---------------------------------------+-------+--------+---------+-------+-------+--------+--------+--------+-----------+------------+--------------+-----------+
|    36 |   0 |   34 |   0 |   2 |   0 | GET    | /api/admin/tenants/billing?before=xxx | 0.004 | 16.256 |  84.792 | 2.355 | 3.400 | 14.224 | 16.256 |  3.246 |     0.000 |    988.000 |    31387.000 |   871.861 |
|    90 |   0 |   89 |   0 |   1 |   0 | GET    | /api/organizer/billing                | 0.004 | 20.320 |  40.444 | 0.449 | 0.556 |  0.836 | 20.320 |  2.266 |     0.000 |   6489.000 |   260072.000 |  2889.689 |

slowログでも 一番遅いクエリも請求金額計算処理にあるクエリです。

Count: 5500  Time=0.01s (50s)  Lock=0.00s (0s)  Rows=135.9 (747469), isucon[isucon]@localhost
  SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = N AND competition_id = 'S' GROUP BY player_id

コードを読んだら、大会が終了している場合のみ請求金額が確定するので、終了している大会の請求金額をキャッシュした方が良いではないかと仮説を立てました。

func billingReportByCompetition(ctx context.Context, tenantDB dbOrTx, tenantID int64, competitonID string) (*BillingReport, error) {
  cachedKey := fmt.Sprintf("%d_%s", tenantID, competitonID)
  if comp.FinishedAt.Valid {
      if cached, ok := cachedFinishedBillingReport.Load(cachedKey); ok {
          result := cached.(BillingReport)
          return result, nil
      }
  }
  // 省略
  result := &BillingReport{..}
  cachedFinishedBillingReport.Store(cachedKey, result)
  return result, nil

キャッシュした後、エラーはほぼなく実行できました。alpをみたら、請求金額計算のAPIの負荷が一気に減らせたと確認できました。

+-------+-----+-------+-----+-----+-----+--------+---------------------------------------+-------+--------+---------+-------+-------+-------+--------+--------+-----------+------------+--------------+-----------+
| COUNT | 1XX |  2XX  | 3XX | 4XX | 5XX | METHOD |                  URI                  |  MIN  |  MAX   |   SUM   |  AVG  |  P90  |  P95  |  P99   | STDDEV | MIN(BODY) | MAX(BODY)  |  SUM(BODY)   | AVG(BODY) |
+-------+-----+-------+-----+-----+-----+--------+---------------------------------------+-------+--------+---------+-------+-------+-------+--------+--------+-----------+------------+--------------+-----------+
|    56 |   0 |    55 |   0 |   1 |   0 | GET    | /api/admin/tenants/billing?before=xxx | 0.024 | 11.284 |  74.860 | 1.337 | 2.128 | 7.032 | 11.284 |  2.054 |     0.000 |    999.000 |    49014.000 |   875.250 |
|   112 |   0 |   112 |   0 |   0 |   0 | GET    | /api/organizer/billing                | 0.004 | 10.556 |  30.120 | 0.269 | 0.060 | 0.108 |  8.684 |  1.506 |   242.000 |   6810.000 |   315668.000 |  2818.464 |

請求金額計算処理にある遅いクエリも呼ばれる回数は5500回から3779回まで抑えました。

Count: 3779  Time=0.01s (46s)  Lock=0.00s (0s)  Rows=179.0 (676478), isucon[isucon]@localhost
  SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = N AND competition_id = 'S' GROUP BY player_id

更なる改善ですが、大会を終了する時点からすぐ非同期で請求金額計算処理を走らせた方が効率的ではないかと思って、大会が終了させるcompetitionFinishHandlerのメソッドで、非同期で請求金額計算のキャッシュを更新できるように修正しました。

func competitionFinishHandler(c echo.Context) error {
  // 省略
  // 大会を終了させる処理が終わったら
  go billingReportByCompetition(ctx, tenantDB, v.tenantID, id)

15:40 MySQLを3つ目のサーバーに設定した (スコア: 〜25000)

MySQLは3つ目のサーバーに移動してみた結果、少しスコアだけが増えました。例年なら、スコアが急増するという記憶があったので、あまりスコアが伸びず残念でした。

15:56 Fileでロックする方法をやめて、Golangのsync.Mutexにした (スコア: 31452)

テナントデータベースでクエリする時に、トランザクションをかけるために、ロックファイルを作成するという仕組みがあると気づけました。

// 排他ロックする
func flockByTenantID(tenantID int64) (io.Closer, error) {
    p := lockFilePath(tenantID)

    fl := flock.New(p)
    if err := fl.Lock(); err != nil {
        return nil, fmt.Errorf("error flock.Lock: path=%s, %w", p, err)
    }
    return fl, nil
}

わざわざファイルを作成して、ファイルロックを取ることは非効率ではないかと思って、Goのsync.Mutexに変更してみたら、点数が急増しました。それぞれテナントごとにsync.Mutexのインスタンスが必要なので、sync.Mapを合わせて実装しました。一回目の実装で不具合なく無事に動いたので今大会の自分の一つのハイライトでした。

   // / DELETEしたタイミングで参照が来ると空っぽのランキングになるのでロックする
    // fl, err := flockByTenantID(v.tenantID)
    // if err != nil {
    //     return fmt.Errorf("error flockByTenantID: %w", err)
    // }
    // defer fl.Close()
    var lock sync.Mutex
    if cached, ok := mapTenantLock.Load(v.tenantID); !ok {
        lock = sync.Mutex{}
        mapTenantLock.Store(v.tenantID, lock)
    } else {
        lock = cached.(sync.Mutex)
    }

    lock.Lock()
    defer lock.Unlock()

16:06 既存の100個のテナントデータベースにIndexをまだ適用していないと気づいたので、修正した (スコア： 37056)

SQLiteで動いているマルチテナントデータベースのクエリslowログはどうすれば監視できるのかものすごく悩みました。アプリケーションで発行するクエリをみて、Indexを追加したのですが、全部のテナントで機能しているか分かりませんでした。調べてみたら、やっばり 10_schema.sqlで追加Indexを定義しても、既存の100個のテナントDBに影響がないと気づいて、initializeの時点で、全てのテナントにIndexを適用できるように修正しました。

16:52 請求金額計算処理で重いクエリを2sでキャッシュして、sqlx.DBのMax Connsを50まで増やした (スコア： 〜60000)

請求金額計算処理はリアルタイムで反映しなくてもいいかもしれないとマニュアルを読みつつ気づきました。それで、slowログの一番遅いクエリのランキングにアクセスした参加者のIDを取得するクエリを2sでキャッシュしてみました。

visitCacheKey := fmt.Sprintf("%s_%d", tenantID, comp.ID)
now := time.Now()
if cachedTime, ok := cacheVisitHistoryTimeAt.Load(visitCacheKey); ok {
    if cached, ok := cacheVisitHistory.Load(visitCacheKey); ok && now.Sub(cachedTime.(time.Time)) < 2*time.Second {
        vhs = cached.([]VisitHistorySummaryRow)
    }
} else {
    if err := adminDB.SelectContext(
        ctx,
        &vhs,
        "SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = ? AND competition_id = ? GROUP BY player_id",
        tenantID,
        comp.ID,
    ); err != nil && err != sql.ErrNoRows {
        return nil, fmt.Errorf("error Select visit_history: tenantID=%d, competitionID=%s, %w", tenantID, comp.ID, err)
    }
    cacheVisitHistoryTimeAt.Store(visitCacheKey, now)
    cacheVisitHistory.Store(visitCacheKey, vhs)
}

ベンチマーカーを実行したところ、「へ〜」、「すごい〜」、「マージか〜」という感じでスコアとモニタリング結果を確認しました。キャッシュした一番重いクエリの実行回数が一気に減らせるため、MySQLサーバーのCPU利用率は100%ぐらいから安定に20%で動いていました。逆にアプリケーションのCPUが150~170%までピークになっていて、「大量のリクエストが来るのではないか」と思って、スコアも一気に伸ばしました。この実装は正直GoのSingleFlightを使った方が良いと思いますが、時間があれば修正したいけど、結果がいい感じなのでそのままにしました。

MySQLサーバーのCPU利用率はものすごく低くなったので、sqlx.DBのConnection Poolingを有効にするための設定を行いました。色々試した結果、50で行くと決めました。

adminDB.SetMaxOpenConns(50)
adminDB.SetMaxIdleConns(50)

17:02 Appを2つ目のサーバーに移動して、最終構成を固めた (スコア： 〜75000)

アプリケーションのCPU利用率が高すぎて、限界になってしまうので、どうしてもスコア伸ばせないと思いました。 CPU利用率を減らすため、いくつかのAPIを2つ目のサーバーに分散できないかいろいろ調べましたが、SQLiteの制約でやっばり今の技術スタックでは不可能だと分かりました。それで、APIを分散しないで、システムレイヤを分けました。1つ目のサーバーはNginxにして、アプリケーション自体は全て3つ目のサーバーに移動しようと決めました。その結果、チームの最終の構成で、当日の最大スコアの〜75000点 (+86000点、 -11000点) に到達できました。

17:52 競技終了まで挑戦したが、最終スコア: 59911ぐらいだった

最後まで、alpで一番時間がかかる/api/player/player/:player_idと/api/player/competition/:competition_id/ranking にはなんとかしたいと工夫したが、どれでも改善できなさそうなので、諦めました。 17:35ぐらいで、掃除して、再起動試験を行いました。何度もベンチマーカーを実行した結果はスコアは安定せず、60000〜72000ぐらいでしたが、マニュアルを確認したら、再現スコアが最終スコアの85%以下の場合は失格 というルールがあると気づいたので、6万ぐらいで全然本戦に出られると思うので、安全のため、最終スコアは6万のままにしました。

最後に

今年の予選の問題は上手く作られていたと思っています。一番の謎を解いたら、点数が一気に伸ばせるという問題じゃなくて、小さい改善を積み重ねて、こまめにリリースしていくことでスコアがどんどん高くなると感じました。ISUCON12の運営の皆様がいい感じなIsuconを開催してくださって、感謝してもしきれません。

yasuoチームは今年でポート公開したミスで本戦に出られないのがすごく悔しいですが、まだまだ本戦で挑戦したい気持ちがあるので、また来年楽しみに参加しようと思います。

以上です。

© 2020 Classi Corp.