Hateburo: kazeburo hatenablog

Operations Engineer / Site Reliability / 運用系小姑 / Perl Monger

ISUCON10 感想戦で 100,000 超えスコアを出した

感想戦優勝なんてものはない

ISUCON10本選は悔しいところではありましたが、Fail(失格)で終わってしまいましたが、1週間もの長い間サーバとベンチマーカーが使えるようにして頂いていたので、感想戦にチャレンジし、24x7 ベンチマークを回し、最終的には100,000超え(本選時の弊チームベスト 32,312、優勝者スコア 49,545)のスコアを出すことに成功しましたので、その方法です。

レポジトリはこちらにあります。

github.com

この記事を読み進める前に当日のマニュアルを確認するとよいでしょう

github.com

最終スコア

101,249 がベストで最後のスコアです。

f:id:kazeburo:20201014102538p:plain

この際のTeamCapacityは100です

15:07:32.437656 ===> PREPARE
15:07:41.629186 ===> LOAD
15:08:51.629218 ===> VALIDATION
15:08:58.020129 ===> SCORE
Count: 
  admin-answer-clarification: 599
  admin-get-clarification: 599
  admin-get-clarifications: 63
  audience-get-dashboard: 3378
  create-team: 100
  enqueue-benchmark: 4721
  finish-benchmark: 4704
  get-clarification: 672
  get-dashboard: 448
  join-member: 200
  list-notifications: 48676
  post-clarification: 672
  push-notifications: 49167
  resolve-clarification: 597
(53906 * 2.0) + 337 - 6900(err: 0, timeout: 6941)
Pass: true / score: 101249 (108149 - 6900)

他のチームでは、FetchDecodeExecWriteが91,874、百万円ドリブンが88,331を記録しています。みんなすごい

百万円ドリブンの方のブログはこちら

nakario.hateblo.jp

サーバ構成

本選時の最終構成がこちら

f:id:kazeburo:20201014102704p:plain

サーバ101にWeb(主にweb画面用API)とAPI(ベンチマーカー用API)のプロセスがいる状態で、envoyを102、MySQLが103でした。ただし、~/env に設定されている BENCHMARK_SERVER_HOST が101のままだったので、仮想ベンチマーカーからのpollingリクエストは101に届いているという状況でした。このため101ではenvoyが動いたままでした。

大きな改善として、APIのプロセスにてHTTPサーバを起動して、ベンチマークのエンキューがあった際に、WebからAPIにHTTPリクエストを送るようにしていました。

API

func pollBenchmarkJob(db sqlx.Queryer) (*xsuportal.BenchmarkJob, error) {
    select {
    case _ := <-benchmarkJobIdChannel:
        var job xsuportal.BenchmarkJob
        err := sqlx.Get(
            db,
            &job,
            "SELECT * FROM `benchmark_jobs` WHERE `status` = ? ORDER BY `id` LIMIT 1",
            resources.BenchmarkJob_PENDING,
        )
        return &job, nil
    case <-time.After(200 * time.Millisecond):
        return nil, nil
    }
}

func enqueueBenchmarkJob(e echo.Context) error {
    benchmarkJobIdChannel <- 42
    return e.JSON(http.StatusOK, nil)
}


func main() {
    ...
    benchmarkJobIdChannel = make(chan int, 300*4) // xsuportal.TeamCapacity
    srv := echo.New()
    srv.POST("/api/contestant/benchmark_jobs/:id", enqueueBenchmarkJob)
    go func() {
        srv.Start(":60051")
    }()
    ....
}

Web側

url_target := fmt.Sprintf("http://10.162.47.101:60051/api/contestant/benchmark_jobs/%d", job.ID)
args := url.Values{}
res, err := http.PostForm(url_target, args)
if err != nil {
    return fmt.Errorf("pass job id to benchmark: %w", err)
}
io.Copy(ioutil.Discard, res.Body)
res.Body.Close()

これにより、ジョブの起動速度の改善とMySQLの負荷削減が行われ、スコアも上昇してました。

また、WebPushやオーディエンスのleaderboard(Dashboard)のキャッシュなども実装してありました。

そして、スコア100,000を出したときの構成が下。

f:id:kazeburo:20201014103009p:plain

一週間の様々なトライがありましたが、最終的にはそれほど変わらない構成に落ち着いています。

変わったのは、静的コンテンツを出すためのnginxとleaderboardの処理を102に寄せたところです。

MySQLの追加設定

メモリが1GBと最近扱っているサーバの1/1000ぐらいなので、メモリ不足に陥らないような設定も必要となるでしょう。

disable-log-bin
innodb_doublewrite = 0
innodb_flush_log_at_trx_commit = 0
innodb_flush_method = O_DIRECT
innodb_adaptive_hash_index = 0
max_connections=1024

sort_buffer_size    = 128K
read_buffer_size    = 128K

sort_buffer_size/read_buffer_sizeはもっと小さくてもいいのかもしれない。 本当に1024接続きたらメモリ不足で死にます。

延長戦での変更点

いろんなことを試していたので、覚えている限りで変更点です。

nginxでの静的コンテンツ配信 + gzip_static

102上にnginxをたてて、サイズの大きな静的コンテンツをnginxのgzip_staticを使って配信しました。

envoyに以下を追加

routes:
  - match:
      prefix: "/packs"
    route:
      cluster: xsuportal_web_static
  - match:
      prefix: "/favicon.ico"
    route:
       cluster: xsuportal_web_static

nginxは設定ファイルのbackupを忘れましたが、gzip_staticを有効にして、大きなjsは事前に圧縮しています。 これによりチーム作成と参加時の負荷を抑えられました。

leaderboardのbackground生成

リクエスト来た時にcacheを作るのではなく、backgroundのgoroutineでcacheを更新しました

func backgroundLeaderboardPB() {
    ticker := time.NewTicker(500 * time.Millisecond)
    defer ticker.Stop()
    for {
        select {
        case <-ticker.C:
            leaderboard, err := makeLeaderboardPB(0)
            audienceDashboardCacheLock.Lock()
            audienceDashboardCache = res
            audienceDashboardCacheTime = n.UnixNano() + 800000000
            audienceDashboardCacheLock.UnLock()
        }
    }
}

func (*AudienceService) Dashboard(e echo.Context) error {
    audienceDashboardCacheLock.RLock()
    if audienceDashboardCache != nil && audienceDashboardCacheTime > time.Now().UnixNano() {
        defer audienceDashboardCacheLock.RUnlock()
        return e.Blob(http.StatusOK, "application/vnd.google.protobuf", audienceDashboardCache)
    }
    audienceDashboardCacheLock.RUnlock()
    log.Printf("cache miss audience dashboard")
    // 通常の処理

cacheの有効期限は700msecから900msecぐらいで様々調整しましたが、時間内にcache生成ができないケースも多く発生したので、リクエストがきた際に有効期限が切れていた場合にDBにアクセスするようになってました。

後述するクエリの最適化をした後は、cacheの有効期限はいくら伸ばしても大丈夫になってました。

polling処理の改善

fujiwara組のblogを参考に、polling処理に RAND() を使うようにしました。

beatsync.net

func pollBenchmarkJob(db sqlx.Queryer) (*xsuportal.BenchmarkJob, error) {
    select {
    case _ := <-benchmarkJobIdChannel:
        var job xsuportal.BenchmarkJob
        err := sqlx.Get(
            db,
            &job,
            "SELECT * FROM `benchmark_jobs` WHERE `status` = ? ORDER BY RAND() LIMIT 1",
            resources.BenchmarkJob_PENDING,
        )

これで、ベンチマーカーが同じjob IDを取り合って無駄に動くことが減ったので、ベンチマークの処理回数がかなり伸び、スコアは 60,000 になりました。

これで成仏した思っていたら、FetchDecodeチームがスコア 80,000を超えてきたので三途の川の前で引き返し、もうちょいトライすることに

ただし、しばらくはあまりスコアが上がっていかない、だいぶ茨の道でした。

push_subscriptions のcache

ListNotifications で空っぽを返すのは push_subscriptions があるユーザだけ(っぽい?)ので、アクセスのたびにpushが有効化確認するため、push_subscriptionsテーブルへのアクセスしていましたが、ListNotifications アクセスが多いのでインメモリでキャッシュしました。

contest_config のcache

コンテストの開始・終了、グラフのフリーズ時間を持っているテーブルですが、様々なエンドポイントでデータベースにアクセスするのでcacheしました。単純にcacheするだけではなく現在時間をみてキャッシュの中身を一部変更する必要がありました。

エンキュー時にjob IDを渡すように

本選時にうまくいかなかったのですが、WebからAPIに対してjob idを渡すように再度変更。RAND() がなくなりjobの競合がなくなるので多少高速化。

single flightの導入

オーディエンスのLeaderboardはキャッシュの有効期限が切れていた際に、その場で作成し直すようになってましたが、これをsingle flightにすることで、負荷を減らすようにしてみた。

こちらもfujiwara組のblogと以下の記事を参考にしました。

blog.lufia.org

var sfGroup singleflight.Group

func (*AudienceService) Dashboard(e echo.Context) error {
    .. cache の処理 ..
    res, err, _ := sfGroup.Do("dashboard", func() (interface{}, error) {
        leaderboard, err := makeLeaderboardPB(0)
        if err != nil {
            return nil, fmt.Errorf("make leaderboard: %w", err)
        }
        r := &audiencepb.DashboardResponse{Leaderboard: leaderboard}
        return proto.Marshal(r)
    })
    if err != nil {
        return err
    }
    return e.Blob(http.StatusOK, "application/vnd.google.protobuf", res.([]byte))
}

ベンチマークの後半はprotobufへの変換もCPUを使うようになるので、Marshalまでをsingle flightで包んでいます。

single flightはここだけではなく仮想選手のLeaderboardアクセス、ListBenchmarkJobsなどでも使いました。便利

Leaderboardのgzip

これは最後まで有効にしたり、外したりを繰り返しました。最終的には圧縮が有効になっています。 オーディエンスのLeaderboardのcaccheはbackgroundで作成しているのでそこでついでに圧縮しています。

leaderboard, err := makeLeaderboardPB(0)
r := &audiencepb.DashboardResponse{Leaderboard: leaderboard}
res, _ := proto.Marshal(r)
var buffer bytes.Buffer
ww, _ := gzip.NewWriterLevel(&buffer, gzip.BestCompression)
ww.Write(res)
ww.Close()
res = buffer.Bytes()
audienceDashboardCache = res

Accept-Encodingはみていませんmm

Leaderboardを作成するmakeLeaderboardPBでは、最終的には数千行のベンチマークのログを返すことになるのでレスポンスのサイズが大きくなります。最後には仮想選手のLeaderboardもgzip圧縮しています。

学生チームフラグをteamsテーブルに

cacheだけではそろそろスコアが上がらないので、makeLeaderboardPB内の大きなクエリの改善に着手しました。

query := "SELECT\n" +
    "  `teams`.`id` AS `id`,\n" +
    "  `teams`.`name` AS `name`,\n" +
    "  `teams`.`leader_id` AS `leader_id`,\n" +
    "  `teams`.`withdrawn` AS `withdrawn`,\n" +
    "  `team_student_flags`.`student` AS `student`,\n" +
    "  (`best_score_jobs`.`score_raw` - `best_score_jobs`.`score_deduction`) AS `best_score`,\n" +
    "  `best_score_jobs`.`started_at` AS `best_score_started_at`,\n" +
    "  `best_score_jobs`.`finished_at` AS `best_score_marked_at`,\n" +
    "  (`latest_score_jobs`.`score_raw` - `latest_score_jobs`.`score_deduction`) AS `latest_score`,\n" +
    "  `latest_score_jobs`.`started_at` AS `latest_score_started_at`,\n" +
    "  `latest_score_jobs`.`finished_at` AS `latest_score_marked_at`,\n" +
    "  `latest_score_job_ids`.`finish_count` AS `finish_count`\n" +
    "FROM\n" +
    "  `teams`\n" +
    "  -- latest scores\n" +
    "  LEFT JOIN (\n" +
    "    SELECT\n" +
    "      MAX(`id`) AS `id`,\n" +
    "      `team_id`,\n" +
    "      COUNT(*) AS `finish_count`\n" +
    "    FROM\n" +
    "      `benchmark_jobs`\n" +
    "    WHERE\n" +
    "      `finished_at` IS NOT NULL\n" +
    "      -- score freeze\n" +
    "      AND (`team_id` = ? OR (`team_id` != ? AND (? = TRUE OR `finished_at` < ?)))\n" +
    "    GROUP BY\n" +
    "      `team_id`\n" +
    "  ) `latest_score_job_ids` ON `latest_score_job_ids`.`team_id` = `teams`.`id`\n" +
    "  LEFT JOIN `benchmark_jobs` `latest_score_jobs` ON `latest_score_job_ids`.`id` = `latest_score_jobs`.`id`\n" +
    "  -- best scores\n" +
    "  LEFT JOIN (\n" +
    "    SELECT\n" +
    "      MAX(`j`.`id`) AS `id`,\n" +
    "      `j`.`team_id` AS `team_id`\n" +
    "    FROM\n" +
    "      (\n" +
    "        SELECT\n" +
    "          `team_id`,\n" +
    "          MAX(`score_raw` - `score_deduction`) AS `score`\n" +
    "        FROM\n" +
    "          `benchmark_jobs`\n" +
    "        WHERE\n" +
    "          `finished_at` IS NOT NULL\n" +
    "          -- score freeze\n" +
    "          AND (`team_id` = ? OR (`team_id` != ? AND (? = TRUE OR `finished_at` < ?)))\n" +
    "        GROUP BY\n" +
    "          `team_id`\n" +
    "      ) `best_scores`\n" +
    "      LEFT JOIN `benchmark_jobs` `j` ON (`j`.`score_raw` - `j`.`score_deduction`) = `best_scores`.`score`\n" +
    "        AND `j`.`team_id` = `best_scores`.`team_id`\n" +
    "    GROUP BY\n" +
    "      `j`.`team_id`\n" +
    "  ) `best_score_job_ids` ON `best_score_job_ids`.`team_id` = `teams`.`id`\n" +
    "  LEFT JOIN `benchmark_jobs` `best_score_jobs` ON `best_score_jobs`.`id` = `best_score_job_ids`.`id`\n" +
    "  -- check student teams\n" +
    "  LEFT JOIN (\n" +
    "    SELECT\n" +
    "      `team_id`,\n" +
    "      (SUM(`student`) = COUNT(*)) AS `student`\n" +
    "    FROM\n" +
    "      `contestants`\n" +
    "    GROUP BY\n" +
    "      `contestants`.`team_id`\n" +
    "  ) `team_student_flags` ON `team_student_flags`.`team_id` = `teams`.`id`\n" +
    "ORDER BY\n" +
    "  `latest_score` DESC,\n" +
    "  `latest_score_marked_at` ASC,\n" +
    "  `teams`.`id` ASC\n"

このクエリ、各チームの最新のスコア、ベストスコア、ベンチマーク試行回数、学生チームかどうかなどを出してきます。

この中から、まず学生チームのフラグをteamsテーブルに持ってくることにしました。

大雑把にteamsテーブル/contestantsテーブルを更新するタイミングで

UPDATE teams LEFT JOIN 
(SELECT team_id,(SUM(`student`) = COUNT(*)) AS `student` 
  FROM `contestants` GROUP BY `contestants`.`team_id`) `team_student_flags` 
 ON `teams`.`id` = `team_student_flags`.`team_id`
 SET `teams`.`student` = `team_student_flags`.`student`

としたらdead lockしたので、あとから where team_id = X を入れて、上記のでかいクエリから contestants テーブルのJOINを外しました。

ただ、これだけではあまりスコアに変化が感じられませんでした。

スコアサマリーテーブルの作成

学生フラグだけでは変わりがないので、narusejunのコードを参考にさせてもらって、サマリーテーブルを作りました。

github.com

最初はスコアだけでしたが、leaderboardで一切のjoinをしないようにするため、チーム名や学生フラグなどもいれた。

CREATE TABLE `team_scores` (
  `team_id` BIGINT NOT NULL PRIMARY KEY,
  `name` VARCHAR(255) NOT NULL,
  `leader_id` VARCHAR(255),
  `withdrawn` TINYINT(1) DEFAULT FALSE,
  `student_flag` tinyint NOT NULL DEFAULT '0',
  `best_score` INT,
  `best_started_at` DATETIME(6),
  `best_finished_at` DATETIME(6),
  `latest_score` INT,
  `latest_started_at` DATETIME(6),
  `latest_finished_at` DATETIME(6),
  `finish_count` INT,
  `fz_best_score` INT,
  `fz_best_started_at` DATETIME(6),
  `fz_best_finished_at` DATETIME(6),
  `fz_latest_score` INT,
  `fz_latest_started_at` DATETIME(6),
  `fz_latest_finished_at` DATETIME(6),
  `fz_finish_count` INT
) ENGINE=InnoDB DEFAULT CHARACTER SET utf8mb4;

スコアは、チームの最新のものと、グラフが更新されなくなる(freeze)直前までのスコアが必要になります。 また、スコアの更新時は次のようにUPDATEクエリを作ることで、余計な参照なく1回のクエリでテーブルの更新をしています。

q := "UPDATE `team_scores`" +
    "SET " +
    "`best_score` = IF(? >= IFNULL(`best_score`,0),?,`best_score`), " +
    "`best_started_at` = IF(? >= IFNULL(`best_score`,0),?,`best_started_at`), " +
    "`best_finished_at` = IF(? >= IFNULL(`best_score`,0),?,`best_finished_at`), " +
    "`latest_score` = ?, " +
    "`latest_started_at` = ?, " +
    "`latest_finished_at` = ?, " +
    "`finish_count` = IFNULL(`finish_count`,0) + 1 "
args := []interface{}{full, full, full, job.StartedAt, full, markedAt, full, job.StartedAt,markedAt}
if フリーズの時間「前」だったら {
    q = q +
        ", `fz_best_score` = IF(? >= IFNULL(`fz_best_score`,0),?,`fz_best_score`), " +
        "`fz_best_started_at` = IF(? >= IFNULL(`fz_best_score`,0),?,`fz_best_started_at`), " +
        "`fz_best_finished_at` = IF(? >= IFNULL(`fz_best_score`,0),?,`fz_best_finished_at`), " +
        "`fz_latest_score` = ?, " +
        "`fz_latest_started_at` = ?, " +
        "`fz_latest_finished_at` = ?, " +
        "`fz_finish_count` = IFNULL(`fz_finish_count`,0) + 1 "
    args = append(args, full, full, full, job.StartedAt, full, markedAt, full, job.StartedAt, markedAt)
}
q = q + "WHERE `team_id` = ?"
args = append(args, job.TeamID)
_, err = db.Exec(q, args...)

と、ここまでくると大きなクエリはもう必要がなくなり、

query := "SELECT " +
    "`ts`.`team_id` AS `id`, " +
    "`ts`.`name` AS `name`, " +
    "`ts`.`leader_id` AS `leader_id`, " +
    "`ts`.`withdrawn` AS `withdrawn`, " +
    "`ts`.`student_flag` AS `student`, " +
    "IF(`ts`.`team_id` = ?,`ts`.`best_score`,`ts`.`fz_best_score`) AS `best_score`, " +
    "IF(`ts`.`team_id` = ?,`ts`.`best_started_at`,`ts`.`fz_best_started_at`) AS `best_score_started_at`, " +
    "IF(`ts`.`team_id` = ?,`ts`.`best_finished_at`,`ts`.`fz_best_finished_at`) AS `best_score_marked_at`, " +
    "IF(`ts`.`team_id` = ?,`ts`.`latest_score`,`ts`.`fz_latest_score`) AS `latest_score`, " +
    "IF(`ts`.`team_id` = ?,`ts`.`latest_started_at`,`ts`.`fz_latest_started_at`) AS `latest_score_started_at`, " +
    "IF(`ts`.`team_id` = ?,`ts`.`latest_finished_at`,`ts`.`fz_latest_finished_at`) AS `latest_score_marked_at`, " +
    "IF(`ts`.`team_id` = ?,`ts`.`finish_count`, `ts`.`fz_finish_count`) AS `finish_count` " +
    "FROM `team_scores` `ts` " +
    "ORDER BY `latest_score` DESC, `latest_score_marked_at` ASC, `ts`.`team_id` ASC"
err = tx.Select(&leaderboard, query, teamID, teamID, teamID, teamID, teamID, teamID, teamID)

これだけとなりました。このクエリはfile sortとなってしまいますが、チーム数は100ちょいなので無視。

こんなにIFを多用したクエリを書くの初めて...

90,000と100,000のあいだで

ここまでの対策でデータベースの負荷が減り、4coreマシンの半分も使わなくなっていたので、4coreでenvoyとwebを動かすようなサーバ構成を行ったりしたが、あまり好ましい結果がでずに、最終的には戻すことに。

leaderboardの改善を進めてきたもののベンチマーク中になぜか2秒で返せてないtimeoutが1000-3000以上あり、これが全く解消できなかったが、スコア100,000を目指すためには、dashboardより質問への回答やベンチマークの実行完了を優先したほうが良さそうと考えることにしあまり気にしないことに。

また、ベンチマーク中のenvoyの負荷も高くなるので、仮想ベンチマーカーのpollingを行うBENCHMARK_SERVER_HOSTと実ベンチマークのターゲットとなるURLを別にするのも、本選時は意図してませんでしたが、効果があったようです。

ここまでで、だいたい安定的に80,000から90,000ぐらいのスコアがでるようになりました。

最後の調整はいくつかABテストのように試して、効果があったのが仮想参加者のDashboardでsingleflightを使うかどうかでした。

contestFreezesAt := contestStatus.ContestFreezesAt
if contestFreezesAt.Add(-10 * time.Second).Before(time.Now()) {
    res, err, _ := sfGroup.Do(fmt.Sprintf("dashboard%d", team.ID), func() (interface{}, error) {
        leaderboard, err := makeLeaderboardPB(team.ID)
        r := &audiencepb.DashboardResponse{Leaderboard: leaderboard}
        res, _ := proto.Marshal(r)
        var buffer bytes.Buffer
        ww := gzip.NewWriter(&buffer)
        ww.Write(res)
        ww.Close()
        res = buffer.Bytes()
        return res, nil
    })
    e.Response().Header().Set("Content-Encoding", "gzip")
    return e.Blob(http.StatusOK, "application/vnd.google.protobuf", res.([]byte))
} else {
    leaderboard, err := makeLeaderboardPB(team.ID)
    r := &audiencepb.DashboardResponse{Leaderboard: leaderboard}
    res, _ := proto.Marshal(r)
    buf := globalPool.Get().(*bytes.Buffer)
    defer func() {
        buf.Reset()
        globalPool.Put(buf)
    }()
    ww := gzip.NewWriter(buf)
    ww.Write(res)
    ww.Close()
    res = buf.Bytes()
    e.Response().Header().Set("Content-Encoding", "gzip")
    return e.Blob(http.StatusOK, "application/vnd.google.protobuf", res)
}

何回かの試行の結果、どうもsingle flightを使わない方がスコアは高くなるが、最後のスコアボード検証ができずFailし、single flightを使わないと100,000は届かない、ということで、グラフフリーズの数秒前からsingle flightをやめるようにしてみた。5秒、15秒などを試し、100,000に届いたのが、10秒前でした。

祈る

最後はfailしないことを祈るとか、祈るとか、祈るしかない

さいごに

いやぁ、本当に1週間楽しめました。楽しかったです(語彙)

白金動物園さん、すごい問題ありがとう。whywaitaをはじめサイバーエージェントの方々も1週間もサーバ使わせて頂いて、本当に感謝です