ISUCON12本選でチーム シン・ウー馬場ーイー2 として参加し、12位でした

TL;DR

ISUCON12本選の結果は12位となりました。最終スコアは106,254でした。

順位が振るわなかった理由は、以下の3点と自分では考えています。

• デッドロックの解消に時間を使い過ぎてしまった
  • デッドロックが発生しているテーブル特定に時間がかかった
  • デッドロックはテーブルの更新順が原因と思い込んでしまった
  • 本選の時間内にデッドロックを解決できなかった
• 複数台サーバの利用方法を最終盤まで後回しにした
  • 5台もあるので分割方法を早々に考えるべきであった
  • 結局2台しか活用できなかった
• シャーディングの発想がでてこなかった
  • シャーディングを自分で実装した経験がなかった
  • 仮に思いついたとしても作業コストが想定できなかった

デッドロックは延長戦で解消する方法をある程度確立したので、今後のISUCONに活かしたいと思います。 シャーディングは１度でも経験しておけば着手できたのではないかと思いますが、たとえ発想できたとしても実装経験がなくどの程度の難易度かを見積ることができなかったと思います。 本選終了後の延長戦で実際にシャーディングを試みたところ、想像していたよりは簡単に実装できたので、やはり1度でも経験というのは大事なのだなと噛み締めた次第です。

リポジトリは競技終了後に公開しました。

mainブランチ: 本選でやったこと github.com

延長戦ブランチ: 9/4までの延長戦でやったこと github.com

シーン	スコア	備考
本選初回スコア	534	スロークエリー出力など含む
本選最高スコア	113,637
本選最終スコア	106,254	運営計測
延長戦最高スコア	391,711

ISUCON12本選の延長戦、あえて他チームの解法を見ずに自力で解いてたけど、このあたりが限界です。対戦ありがとうございました。

本選の内容はmainブランチ、延長戦は延長戦ブランチに入れて公開。https://t.co/ISPgLNzcLO pic.twitter.com/E6LrcD1GMQ

— matsuu(シン・ウー馬場ーイー2) (@matsuu) 2022年9月3日

体制

あいこん	なまえ	やくわり	ペアプロ
	matsuu	バリバリ実装する前衛	ドライバー
	netmarkjp	司令塔+ベンチ実行+結果解析	ナビゲーター
	ishikawa84g	セキュリティ+情報官+動作確認 AppArmor、マニュアルや公式アナウンスの把握、ブラウザでの挙動確認	ナビゲーター

3人はそれぞれリモートで、Discordでビデオチャットをしつつ画面共有してました。

使用したツールなど

ツール	用途
sshrc	ssh接続時に手元の環境を持ち込むため
zellij NEW!	tmux代替
tmux	ターミナル分割など
neovim NEW!	エディタ
top	リソース使用状況確認
dstat	リソース使用状況確認
MySQLTuner	MySQLパラメータ確認
kataribe	アクセスログ解析
go-mysql-query-digest NEW!	MySQLスロークエリー解析

予選では使ってなかったzellijを今回導入しましたが、本選中に不具合に遭遇したので断念してtmuxに切り替えました。

最終構成

サーバ	構成要素	備考
1台目	nginx + app	appはGo実装
2台目	mysql
3台目		利用せず
4台目		利用せず
5台目		利用せず

今回は最後までDBの負荷が高い状態を改善できませんでした。トランザクションで処理するテーブル群をかたまりとして複数DBに分けようとしたのですが、関連するテーブルが多い上に負荷をうまく分散できる気がしなかったので、テーブル単位のDBサーバ分割は難しいと判断して結局活用できませんでした。

予選ではRustで始めて途中からGoに切り替えましたが、本選は最初からGoで進めました。来年こそは別言語で出たいと思います。

スコア推移

ISUCON12本選のスコア推移

後半伸び悩んでいるのはデッドロックに苦しめられた期間です。

やったこと

「時間 スコア 概要」 でまとめていきます。

10:25 534 初回ベンチ

一通りログ解析などができる体制をセットアップした後での初回ベンチです。 スロークエリー出力を仕込んだ上でのベンチ実行なので、何もせずにベンチを仕掛けるよりは遅くなっています。

github.com

10:34 7,888 user_present_all_received_historyにインデックス追加

topの出力を見る限りmysqldのCPU負荷が支配的だったので、まずはMySQLのスロークエリーから遅いクエリーを抽出してインデックスを追加しました。

 /* 全員プレゼント履歴テーブル */
 
 CREATE TABLE `user_present_all_received_history` (
   `id` bigint NOT NULL,
   `user_id` bigint NOT NULL comment '受けとったユーザID',
   `present_all_id` bigint NOT NULL comment '全員プレゼントマスタのID',
   `received_at` bigint NOT NULL comment '受け取った日時',
   `created_at` bigint NOT NULL,
   `updated_at`bigint NOT NULL,
   `deleted_at` bigint default NULL,
+  INDEX (user_id, present_all_id),
   PRIMARY KEY (`id`)
 ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin;

ここで暫定1位です。

github.com

10:42 12,503 MySQLチューニング

インデックス追加の結果をtopとdatatで確認したところ、cpu usrの割合が下がったものの、iowaitの比率が上がっていることを確認しました。そこでバイナリログなどの出力が多いと考えてMySQLをチューニングしました。

MySQLのバージョンは予選では8.0.29、本選は8.0.30でした。このバージョン差異は我々のチームにとっては影響大でした。詳しくは以下をご参照ください。

blog.s-style.co.jp

予選の復習中にこの差異は確認済だったので、秘伝のタレも合わせて修正しています。

/etc/mysql/mysql.conf.d/mysqld.cnf

disable-log-bin

innodb_buffer_pool_size=1G

innodb_doublewrite = 0
innodb_flush_log_at_trx_commit = 0
innodb_flush_log_at_timeout = 3

innodb_log_group_home_dir = /dev/shm
innodb_redo_log_capacity = 128M

/etc/tmpfiles.d/mysqld_redo.conf

d /dev/shm/#innodb_redo 750 mysql mysql

/etc/apparmor.d/usr.sbin.mysqld

   /etc/ssl/openssl.cnf r,
   # Site-specific additions and overrides. See local/README for details.
   #include <local/usr.sbin.mysqld>
+
+  /dev/shm/ r,
+  /dev/shm/** rwk,
 }

github.com

11:05 - 当日マニュアル読み合わせ

ここでishikawa84gが要点をまとめた当日マニュアルの読み合わせを行っています。要点だけを把握して共有しているのでとても効率が良い方針だと思っています。

11:54 20,011 generateIDをAUTO_INCREMENTに変更

MySQLのチューニングによってcpu iowaitの割合は下がり、再びcpu usrの割合が高くなりました。MySQLのスロークエリーは以下のクエリーが支配的であることを確認。

UPDATE id_generator SET id=LAST_INSERT_ID(id+1)\G

予選と実装方法は異なるものの、似たようなテーブルまたぎのID生成です。

// generateID uniqueなIDを生成する
func (h *Handler) generateID() (int64, error) {
        var updateErr error
        for i := 0; i < 100; i++ {
                res, err := h.DB.Exec("UPDATE id_generator SET id=LAST_INSERT_ID(id+1)")
                if err != nil {
                        if merr, ok := err.(*mysql.MySQLError); ok && merr.Number == 1213 {
                                updateErr = err
                                continue
                        }
                        return 0, err
                }

                id, err := res.LastInsertId()
                if err != nil {
                        return 0, err
                }
                return id, nil
        }

        return 0, fmt.Errorf("failed to generate id: %w", updateErr)
}

予選ではidが varchar(255) だったのでuuidに変更しましたが、今回のidは bigint だったので AUTO_INCREMENT 実装に取り急ぎ変更しました。 ただ、テーブル数が多くINSERTクエリーからidを取り除く対応にやや時間がかかっています。

github.com

12:11 - user_presentsテーブルのN+1を解消

スコアの記録は失念しましたが、ほとんど増えてなかったと思います。

引き続きMySQLのcpu usrが支配的なのでMySQLスロークエリーを確認します。上位はuser_presentsテーブルに対する更新だったのでここに注目し、user_presentsに対してN+1でUPDATEしている部分を外だししています。

@@ -1287,6 +1287,13 @@ func (h *Handler) receivePresent(c echo.Context) error {
        }
        defer tx.Rollback() //nolint:errcheck

+       query = "UPDATE user_presents SET deleted_at=?, updated_at=? WHERE id IN (?) AND deleted_at IS NULL"
+       query, params, err = sqlx.In(query, requestAt, requestAt, req.PresentIDs)
+       _, err = tx.Exec(query, params...)
+       if err != nil {
+               return errorResponse(c, http.StatusInternalServerError, err)
+       }
+
        // 配布処理
        for i := range obtainPresent {
                if obtainPresent[i].DeletedAt != nil {
@@ -1296,11 +1303,6 @@ func (h *Handler) receivePresent(c echo.Context) error {
                obtainPresent[i].UpdatedAt = requestAt
                obtainPresent[i].DeletedAt = &requestAt
                v := obtainPresent[i]
-               query = "UPDATE user_presents SET deleted_at=?, updated_at=? WHERE id=?"
-               _, err := tx.Exec(query, requestAt, requestAt, v.ID)
-               if err != nil {
-                       return errorResponse(c, http.StatusInternalServerError, err)
-               }

                _, _, _, err = h.obtainItem(tx, v.UserID, v.ItemID, v.ItemType, int64(v.Amount), requestAt)
                if err != nil {

github.com

12:20 37,716 nginxチューニング

nginxのerror_logを確認したところToo many open filesのエラーが発生していることを確認したので、ここでnginxをチューニングしています。

--- a/etc/nginx/nginx.conf
+++ b/etc/nginx/nginx.conf
@@ -1,12 +1,13 @@
 user  www-data;
 worker_processes  auto;
+worker_rlimit_nofile 65536;

-error_log  /var/log/nginx/error.log warn;
+error_log  /var/log/nginx/error.log notice;
 pid        /run/nginx.pid;


 events {
-  worker_connections  1024;
+  worker_connections  2048;
 }


@@ -24,6 +25,7 @@ http {
   #tcp_nopush     on;

   keepalive_timeout  65;
+  keepalive_requests 100000000;

   #gzip  on;
 
--- a/etc/nginx/sites-available/isuconquest.conf
+++ b/etc/nginx/sites-available/isuconquest.conf
@@ -1,27 +1,42 @@
+upstream app {
+  server localhost:8080;
+  keepalive 128;
+  keepalive_requests 10000000;
+}
 server {
   root /home/isucon/isucon12-final/webapp/public;
   listen 80 default_server;
   listen [::]:80 default_server;

   location /user {
-    proxy_pass http://localhost:8080;
+    proxy_pass http://app;
+    proxy_http_version 1.1;
+    proxy_set_header Connection "";
   }

   location /admin{
-    proxy_pass http://localhost:8080;
+    proxy_pass http://app;
+    proxy_http_version 1.1;
+    proxy_set_header Connection "";
   }

   location /login {
-    proxy_pass http://localhost:8080;
+    proxy_pass http://app;
+    proxy_http_version 1.1;
+    proxy_set_header Connection "";
   }

   location /health {
-    proxy_pass http://localhost:8080;
+    proxy_pass http://app;
+    proxy_http_version 1.1;
+    proxy_set_header Connection "";
   }

   location /initialize {
     proxy_read_timeout    600;
-    proxy_pass http://localhost:8080;
+    proxy_pass http://app;
+    proxy_http_version 1.1;
+    proxy_set_header Connection "";
   }

   location / {

github.com

12:38 - 昼食タイム

12:38頃まで昼食とってます。もぐもぐ

12:50 41,000 複数テーブルにインデックス追加

Too many open filesが解消した結果、再びmysqldのcpu usrが多いのでスロークエリーを確認してインデックスを追加しました。

--- a/home/isucon/webapp/sql/3_schema_exclude_user_presents.sql
+++ b/home/isucon/webapp/sql/3_schema_exclude_user_presents.sql
@@ -178,7 +178,7 @@ CREATE TABLE `user_items` (
   `updated_at`bigint NOT NULL,
   `deleted_at` bigint default NULL,
   PRIMARY KEY (`id`),
-  INDEX userid_idx (`user_id`)
+  INDEX userid_idx (`user_id`, `item_id`)
 ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin;
 ALTER TABLE user_items AUTO_INCREMENT=100000000001;

@@ -234,7 +234,8 @@ CREATE TABLE `user_sessions` (
   `expired_at` bigint NOT NULL,
   `deleted_at` bigint default NULL,
   PRIMARY KEY (`id`),
-  UNIQUE uniq_session_id (`user_id`, `session_id`, `deleted_at`)
+  INDEX (`session_id`),
+  UNIQUE uniq_session_id (`user_id`, `deleted_at`, `session_id`)
 ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin;
 ALTER TABLE user_sessions AUTO_INCREMENT=100000000001;

@@ -249,7 +250,8 @@ CREATE TABLE `user_one_time_tokens` (
   `expired_at` bigint NOT NULL,
   `deleted_at` bigint default NULL,
   PRIMARY KEY (`id`),
-  UNIQUE uniq_token (`user_id`, `token`, `deleted_at`)
+  INDEX (`token`),
+  UNIQUE uniq_token (`user_id`, `deleted_at`, `token`)
 ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin;
 ALTER TABLE user_one_time_tokens AUTO_INCREMENT=100000000001;

@@ -263,7 +265,8 @@ CREATE TABLE `admin_sessions` (
   `expired_at` bigint NOT NULL,
   `deleted_at` bigint default NULL,
   PRIMARY KEY (`id`),
-  UNIQUE uniq_admin_session_id (`user_id`, `session_id`, `deleted_at`)
+  INDEX (`session_id`),
+  UNIQUE uniq_admin_session_id (`user_id`, `deleted_at`, `session_id`)
 ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin;
 ALTER TABLE admin_sessions AUTO_INCREMENT=100000000001;

github.com

13:39 48,289 プレゼント付与処理のN+1解消

引き続きmysqldのcpu usrが高く、上位のクエリーは実行回数が多い状況を確認したので、上位のものから順番にN+1を解消する方向で進めています。このあたりから大掛かりなアプリ改修になっています。

github.com

13:50 52,453 JSONの生成ライブラリをgoccy/go-jsonに変更

すべての応答がjsonになっているので高速なライブラリである goccy/go-json に差し替えました。

github.com

14:01 50,961 もう一箇所のuser_presentsのINSERTをbulk insertに

引き続きN+1を解消させています。しかしこのあたりの改修でデッドロックが発生し始めています。

スコアは下がりましたが方向性は間違っていないと判断して突き進みますが、これが地獄の始まりでした。

github.com

14:10 50,239 user_presentsテーブルのインデックスを調整

スロークエリーの上位に来ているuser_presentsテーブルのインデックス周りを調整します。

--- a/home/isucon/webapp/sql/setup/1_schema.sql
+++ b/home/isucon/webapp/sql/setup/1_schema.sql
@@ -135,7 +135,7 @@ CREATE TABLE `user_present_all_received_history` (
 ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin;

 CREATE TABLE `user_presents` (
-  `id` bigint NOT NULL,
+  `id` bigint NOT NULL AUTO_INCREMENT,
   `user_id` bigint NOT NULL comment 'ユーザID',
   `sent_at` bigint NOT NULL comment 'プレゼント送付日時',
   `item_type` int(1) NOT NULL comment 'アイテム種別',
@@ -146,7 +146,7 @@ CREATE TABLE `user_presents` (
   `updated_at`bigint NOT NULL,
   `deleted_at` bigint default NULL,
   PRIMARY KEY (`id`),
-  INDEX userid_idx (`user_id`)
+  INDEX user_id (`user_id`, `deleted_at`, `created_at` DESC)
 ) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin;

github.com

14:27 54,744 obtainItemでSELECTしてからUPDATEしているものをUPDATE一発に変更

N+1の中でSELECT→UPDATEとしているのをUPDATEで一発更新にしました。

--- a/home/isucon/webapp/go/main.go
+++ b/home/isucon/webapp/go/main.go
@@ -497,18 +497,8 @@ func (h *Handler) obtainItem(tx *sqlx.Tx, userID, itemID int64, itemType int, ob

        switch itemType {
        case 1: // coin
-               user := new(User)
-               query := "SELECT * FROM users WHERE id=?"
-               if err := tx.Get(user, query, userID); err != nil {
-                       if err == sql.ErrNoRows {
-                               return nil, nil, nil, ErrUserNotFound
-                       }
-                       return nil, nil, nil, err
-               }
-
-               query = "UPDATE users SET isu_coin=? WHERE id=?"
-               totalCoin := user.IsuCoin + obtainAmount
-               if _, err := tx.Exec(query, totalCoin, user.ID); err != nil {
+               query := "UPDATE users SET isu_coin=isu_coin+? WHERE id=?"
+               if _, err := tx.Exec(query, obtainAmount, userID); err != nil {
                        return nil, nil, nil, err
                }
                obtainCoins = append(obtainCoins, obtainAmount)

github.com

15:00 59,147 obtainItem関数をreceivePresentへinline化

kataribe で確認するとトータルの応答時間が長いのは receivePresent でした。この中でN+1で呼ばれているobtainItemを最終的に解消すべく、まずはobtainItem関数をinline化して不要な処理は取り除いています。

https://github.com/matsuu/isucon12f/commit/ad0fe3d6078be542f96373fa4a2bc995b4c09282

15:15 53,345 receivePresentのN+1を一部解消

inline化したobtainItem関数の処理をN+1から外して一括処理させることで解消を目指しました。 しかしデッドロックが増えて事態はさらにひどくなりはじめました。

github.com

15:20 61,679 goからDBへの接続時のアイドルコネクション周りを調整

クエリー実行回数が多いことからDB接続周りをチューニングしています。

--- a/home/isucon/webapp/go/main.go
+++ b/home/isucon/webapp/go/main.go
@@ -125,6 +125,8 @@ func connectDB(batch bool) (*sqlx.DB, error) {
        if err != nil {
                return nil, err
        }
+       dbx.SetMaxOpenConns(140)
+       dbx.SetMaxIdleConns(140)
        return dbx, nil
 }
 

github.com

16:47 50,216 テーブルの更新順を並び替えてみたがデッドロック解消せず

このあたりは時間をかけてデッドロックの原因を探っており、複数のトランザクションのテーブル更新順を入れ替えるなどしていました。一通り対応したものの本選中はデッドロックは解消しません。うんとこしょ、どっこいしょ

github.com

16:51 35,649 SQLにFOR UPDATEをつけたがデッドロック解消せず

SELECT時にFOR UPDATEをつけてテーブルロックの順番を揃えようとしましたが、それでもデッドロックは解消しません。難しいですね。

github.com

17:08 61,197 14:27時点までrevert

辛い決断をしました。15:20のDB接続周りを除き、14:27時点までrevertしています。

github.com

17:21 78,910 dbを2台目サーバに移動

残り時間もなくなってきているので、まずDBを2台目サーバに移動しました。それによりスコアは伸びましたが3台目以降の使い道は決められませんでした。

github.com

17:37 85,692 セッションのdeleted_at更新をレコード削除に変更

コミットメッセージがやや間違ってますが、user_sessionsの論理削除を物理削除に変更しました。少しでもスコアを伸ばそうという涙ぐましい努力です。

github.com

17:59 113,637 ログ出力無効化やappのnofile調整など

最後にスロークエリーログやアクセスログを停止してLimitNOFILEを定義してフィニッシュです。お疲れ様でした。

延長戦 391,711 いろいろ

本選参加者はそのまま同じ環境を使って9/4まで延長戦ができたので参戦しました。 シャーディングやセッションのRedis化などを諸々実装しました。詳しくは下記コミットをご確認ください。

github.com