ISUCON11で予選敗退して悔しかったので予選突破ラインのスコアが出るまで延長戦をやりました

去年に引き続き、今年も @nari_ex、@kur_neko、@shiimaxx の3人で「( (0) / (0)) ☆祝☆」というチームで参加しました。結果は予選敗退、当日のベストスコアは35902でした。

当日やったこと

利用言語はGoです。

• 予選当日マニュアル、アプリケーションマニュアルをしっかり読む
• ボトルネック調査
  • アクセスログ解析: kataribe
  • スロークエリログ解析: pt-query-digest
  • システムリソース: top, dstat
  • アプリケーション: pprof, fgprof
• インデックス追加
  • ALTER TABLE isu_condition ADD INDEX idx_jia_isu_uuid_timestamp (jia_isu_uuid, timestamp);
• 自動prepared statementを抑制するためにDSNにinterpolateParams=trueを追加
• トランザクション内でやる必要のない処理を外出し
• GET /api/trend
  • ISUの性格は固定だったのでアプリケーション内部でsliceとして持たせてDB参照しない
  • 不要なカラムは取得しない
  • アプリケーション内で0.8秒キャッシュ
• MariaDBをMySQL 8.0に変更
• サーバ構成変更
  • isucondition-1
    • Nginx, Application(Go)
  • isucondition-2
    • MySQL(isu_conditionのみ)
  • isucondition-3
    • MySQL(isu_condition以外)

この他にDBに入っている画像の外出しやGET /api/trendのN+1対策をしていましたが、どちらも実装しきれず諦めています。

延長戦

後日実施した反省会で、スコアを上げるための要点が正確に把握できておらず注力する箇所を間違っていた、そもそも実装スピードが足りない、という課題があがりました。
これらは自然に身につくようなものでもなく継続的に練習が必要だという話になったので、ひとまずはISUCON11の予選問題を予選突破ラインのスコアが出るまでやることにしました。

解法を知らない状態でやりたかったので、予選関連エントリはほぼ読まず(1〜2エントリだけ軽く目を通した)、予選講評は読まない状態でやりました。

環境

MacBook Pro (13-inch, 2017) 上にVagrantで以下の環境を起動しました。

• matsuu/vagrant-isucon/isucon11-qualifier-standalone
  • CPU 2コア、メモリ 2GB
  • ベンチマーカ相乗り

スコア

予選突破ラインのスコアは、チーム「俺達の戦いはこれまでだ」の106094なので、このスコア以上を目標にします。本番はAmazon EC2のインスタンスを3台利用できるので構成の差異がありますが、縛りプレイということにして上記の環境で予選突破ラインのスコアを目指すことにしました。

初期スコアは1242。当日やったこと（構成変更以外）を適用した後のスコアは18019でした。

〜 35000

POST /api/condition/<uuid> のINSERTをbulk insertにする → 20534

予選関連エントリでチラ見してしまった内容なのですが、リクエストに含まれるISUのコンディションを都度INSERTしている箇所をbulk insertに変更しました。 sqlxのNamedExecを利用して以下のように実装。

   var values []map[string]interface{}
    for _, cond := range req {
        timestamp := time.Unix(cond.Timestamp, 0)

        if !isValidConditionFormat(cond.Condition) {
            return c.String(http.StatusBadRequest, "bad request body")
        }

        values = append(values, map[string]interface{}{
            "jia_isu_uuid": jiaIsuUUID,
            "timestamp":    timestamp,
            "is_sitting":   cond.IsSitting,
            "condition":    cond.Condition,
            "message":      cond.Message,
        })

    }

    _, err = tx.NamedExec(
        "INSERT INTO `isu_condition`"+
            "    (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`)"+
            "    VALUES (:jia_isu_uuid, :timestamp, :is_sitting, :condition, :message)", values,
    )
    if err != nil {
        c.Logger().Errorf("db error: %v", err)
        return c.NoContent(http.StatusInternalServerError)
    }

iconをDBから外出し → 21813

当日に@kur_nekoが8割方実装してくれていたのを再利用して実装しました。

最新のISUのコンディションをキャッシュしてGET /api/getTrend、GET /api/isuのDB参照を減らす → 23686

initializeで以下の処理を実行してキャッシュを準備、POST /api/condition/:jia_isu_uuidでコンディションを受けっ取ったときにも都度最新データを更新するようにして、最新のISUのコンディションを参照する箇所ではこのキャッシュを利用するようにしました。

var latestIsuConditions sync.Map

func prepareLatestIsuCondition() error {
    rowsx, err := db.Queryx("SELECT `isu_condition`.* FROM (SELECT `jia_isu_uuid`, MAX(`timestamp`) `latest_timestamp` FROM `isu_condition` GROUP BY `jia_isu_uuid`) `tmp`, `isu_condition` WHERE `tmp`.`jia_isu_uuid` = `isu_condition`.`jia_isu_uuid` AND `tmp`.`latest_timestamp` = `isu_condition`.`timestamp`")
    if err != nil {
        return err
    }

    for rowsx.Next() {
        var condition IsuCondition
        err = rowsx.StructScan(&condition)
        if err != nil {
            return err
        }
        latestIsuConditions.Store(condition.JIAIsuUUID, condition)
    }
    return nil
}

GET /api/condition/:jia_isu_uuid の改善 →27362

isu_conditionテーブルにis_dirty、is_overweight、is_brokenカラムを追加して必要なコンディションのレコードのみ取得できるようにしたり、必要な件数分のレコードのみを取得するようにLIMITを追加したりしました。

dropProbability := 0.8、コネクションプールの接続数を100 →34398

試しにやってみたらスコアが結構上がりました。これまでの変更が効いたプチブレイクスルーと思われます。

〜85000

GET /api/isu/:jia_isu_uuid/graph の改善 → 41850

isu_conditionテーブルから指定されたjia_isu_uuidの全レコードを引っ張っていたが、コードを読んでみると1日分のデータしか利用していないようだったので、timestampカラムで条件を絞ってDBからのデータ取得の件数を絞りました。

あと、calculateGraphDataPointの処理はWINDOW関数というやつでできるのでは、と思い頑張ってSQLを作って実装。が、この時点ではスコアにはあまり効果がありませんでした。インデックスを上手く使わせられず、EXPLAINして実行計画を見てみるとUsing temporary; Using filesortが出ていたので単にアプリケーションの負荷がMySQLに移っただけで全体としての効果が薄かったのかもしれません。

   query := "SELECT\n" +
        "       `isu_condition`.*,\n" +
        "       DATE_FORMAT(`timestamp`, '%Y-%m-%d %H:00:00') `truncate_timestamp`,\n" +
        "       SUM((\n" +
        "         CASE WHEN `condition_level` >= 3 THEN 1\n" +
        "         WHEN `condition_level` >= 1 THEN 2\n" +
        "         ELSE 3 END\n" +
        "       )) OVER w * 100 / 3 / COUNT(*) OVER w `score`,\n" +
        "       AVG(`is_sitting`) OVER w * 100 `sitting_percentage`,\n" +
        "       AVG(`is_broken`) OVER w * 100 `is_broken_percentage`,\n" +
        "       AVG(`is_overweight`) OVER w * 100 `is_overweight_percentage`,\n" +
        "       AVG(`is_dirty`) OVER w * 100 `is_dirty_percentage`\n" +
        "     FROM `isu_condition`\n" +
        "     WHERE `jia_isu_uuid` = ?\n" +
        "       AND `timestamp` >= ? AND `timestamp` < ?\n" +
        "     WINDOW w AS (PARTITION BY `truncate_timestamp`)\n" +
        "     ORDER BY `timestamp` ASC"

いくつかトランザクションを削除 → 49274

pt-query-digestのスロークエリログ解析の結果から、ロック待ちで時間がかかっているクエリが多かったので改めて見直したところ、必要のないトランザクションがいくつかあったので削除しました。
トランザクションについてはこの後も何度か見直していて、異常系を考慮しなければなくてもよいものと読み取れたので最終的には全廃しました。

dropProbability := 0.7 → 51876

細かい変更を色々→ 84391

• JIAServiceURLはDBではなくグローバル変数に保存する
• isu_conditionからAUTO_INCREMENTなidカラムを削除してプライマリキーをjia_isu_uuidとtimestampの複合キーに変更
• loglevelをDEBUGからERRORに変更
• dropProbability := 0.6
• 作成済みのISUのリストをキャッシュして、以下のようなISUの存在チェックのためのクエリを削減

var count int
err = db.Get(&count, "SELECT COUNT(*) FROM `isu` WHERE `jia_isu_uuid` = ?", jiaIsuUUID)

〜10000over

POST /api/condition/:jia_isu_uuid で受け取ったコンディションをキューイングして単一のGoroutineでbulk insert → 96413

このあたりで若干手詰まり感。
スコアを上げるにはPOST /api/condition/:jia_isu_uuidのスループットを上げる必要があるんだろうな、とは考えていたものの手段が思いつかず。そこで、改めて予選当日マニュアルを読んでみたところ、

POST /api/condition/:jia_isu_uuid で受け取ったコンディションの反映が遅れることをベンチマーカーは許容しています。

という記載が目につき、POST /api/condition/:jia_isu_uuidのレスポンスを返す時点でコンディションが反映されていなくてよいのであれば、一旦キューイングして一定間隔でまとめてINSERTするようにすれば競合せずにスループットが上がるのでは、と考えて実装してみました。
POST /api/condition/:jia_isu_uuidの中からは送られてきたコンディションをchannelで送信するだけにして、実際にDBにINSERTする処理はgoroutineで動かしている以下の関数内でやります。

func updateIsuCondition(q chan map[string]interface{}) {
    var records []map[string]interface{}

    for {
    wait:
        for {
            select {
            case record := <-q:
                records = append(records, record)
            case <-time.After(10 * time.Millisecond):
                break wait
            }
        }

        if len(records) > 0 {
            _, err := db.NamedExec(
                "INSERT INTO `isu_condition`"+
                    "    (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`, `is_dirty`, `is_overweight`, `is_broken`)"+
                    "    VALUES (:jia_isu_uuid, :timestamp, :is_sitting, :condition, :message, :is_dirty, :is_overweight, :is_broken)", records,
            )
            if err != nil {
                fmt.Println(err)
            }
            records = []map[string]interface{}{}
        }
    }
}

これが効いて一気にスコアが10k以上アップ。システムリソースに余裕がある状態だったので、更にdropProbabilityを調整していきます。

dropProbability := 0.4 → 116797

dropProbabilityを0.5→0.4→0.3と調整してみたところ、0.4で最高スコアが出ました。目標であった106094を超えるスコアも達成。

03:54:51.191862 score: 116797(116828 - 31) : pass
03:54:51.191882 deduction: 31 / timeout: 0
03:54:51.191889 <=== sendResult finish

まとめ

予選の翌日から2週間、少しず進めてある程度のスコアを出すことができました。実装の練習になりますし、どのようにスコアが積み上がっていくのかというのを体験できてよかったと思います。
このブログを大方書いたあとにISUCON11 予選問題の解説と講評を読んでみました。実施した内容が想定解法から大きくハズレていないという点についてはよかったのですが、そこに辿り着くまでに結構遠回りをしてしまっていたので、引き続き計測結果から正確にボトルネックを読み取れるようになるという課題に向き合う必要があるかなと思っています。ISUCONでは8時間で成果を出す必要がありますし。

最後に、運営の皆様今年もISUCONを開催していただきありがとうございます！ 予選本番だけでなく、事前練習や延長戦も含めて長く楽しませていただいています。本選問題が公開されたらそちらにもチャレンジしてみようと思います。