Gマイナー志向

とくに意味はありません

ISUCON12予選の様子(画面操作)をYouTubeに公開しました

今回のISUCONで初の試みとして、画面操作を録画したのでYouTubeに公開しました。自分の肉声も含まれています。

youtu.be

映像は8時間ノーカットです。音声は乗せられない会話、クシャミ、昼食中の啜る音などだけ除去しています。

チームメンバーと会話しながら進めたものの、プライバシーを配慮してあえて自分の声しか入れてません。相槌を打っているだけのシーンもあるので内容はすべて把握できないかもしれません。

画面収録はmacOS標準機能を使いました。動画編集はmacOS標準のiMovieを使っています。

ちゃんとした動画をYouTubeにアップロードしたのも初めてだったので不手際があれば教えてください。

得られた教訓

  • 黒地に白文字は動画にすると読みづらいので白地に黒文字にすべきだった
  • 更新があまりないターミナルの画面(1920x1080)を8時間録画すると約20GBの動画ファイルになる
  • 音声を編集するためにiMovieを初めて使ったが、レンダリングファイルで500GBのストレージ容量がすぐに埋まってしまうのでこまめに消す必要がある
  • 8時間をまるごとYouTubeにアップロードするとYouTube上の動画エディタが長過ぎて使えず、字幕編集機能もメモリ不足でエラーになるので複数の動画に分けるべき
  • 自分の滑舌が悪いこともありYouTubeが自動でつけてくれる字幕はお粗末、かつ8時間もあると膨大な量で修正するのは心が折れる(折れた)
  • YouTubeには動画チャプター機能があるが、タイムラインを書いたものの反映されなかったので悲しい
  • サムネイルは重要なんだろうなと思った

テキトーに作成したトップ絵

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

TL;DR

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

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

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

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

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

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

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

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

体制

あいこん なまえ やくわり ペアプロ
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

ISUCON12予選にシン・ウー馬場ーイー2として参加し、2位で予選突破しました

TL;DR

ISUCON12予選にシン・ウー馬場ーイー2 として出場しました。 結果、予選2位で本選出場をきめました。やったね。 最終スコアは75800、予選中のベストスコアは76525でした。本選もがんばるぞ!

毎年素晴らしいコンテストを開催してくださる運営様には感謝しかありません。本当にありがとうございます!!1

体制

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

今年も3人が別々の場所からリモート参加です。 コミュニケーションはDiscordを使ってます。3人それぞれの画面を共有しながら音声チャットつなぎっぱなしです。

手元の環境

どうでもいい話ですが物理スペックです。

項目 品名
メイン機 Mac mini(M1, 2020) NEW! + モニター2台
キーボード Magic Keyboard NEW!
マウス logicool ELGO M575 NEW!
イヤホン Shokz Aeropex
マイク marantz MPM-1000U
椅子 Ergohuman Basic NEW!

値上げ発表後にヨドバシで駆け込み購入したMac miniです。購入費用はISUCONの優勝賞金の前借りです(皮算用)。

使用したツールなど

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

今回vimからneovimに乗り換えました。設定はこちら。 pt-query-digestが解析に時間がかかることに業を煮やして拙作go-mysql-query-digestを導入しました。

方針

  • サーバ上で直接neovimでソースコードを変更するスタイル
    • 手元での再現環境構築や外部からのデプロイは行わない
    • sshrc で環境がかぶらないようにしてメンバーごとにnvim/ssh環境を分離
  • 実装言語はまずはRustを選択、問題が出たらGoを選択
  • 負荷テスト中は topdstat -tlamp を目視確認
  • 負荷テスト後にアクセス解析
    • nginxのログをkataribeで解析して /result/kataribe.log に出力
    • MySQLのスロークエリーログをgo-mysql-query-digestで解析して /result/slowquery.log に出力
    • MySQLTunerを実行して /result/mysqltuner.log に出力
  • /git init
    • /etc/home と解析結果を含む /result をまるごとコミット(必要に応じて.gitignoreで除外)
    • git add / して git commit
    • GitHubのプライベートリポジトリに git push

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

最終構成

当初は1台目のみを使い、残り1時間のタイミングで複数サーバを使うように構成変更しました。

サーバ 構成要素 備考
1台目 nginx + app(go) nginxは1台目と3台目のappにround-robin
2台目 MySQL 初期実装のままバージョン変更なし
3台目 app(go) 1台目のapp(go)と同じ実装

ちなみに昨年こんなこと書いており

当初はRustで進めていたんですが、競技中にRustからGoに切り替えました。😥

スコア推移

スコア推移

大きな飛躍はなく順当にボトルネックを潰したようなスコア推移になりました。

ベンチマーク履歴

ベンチマーク履歴

今回はベンチを回した回数は少なめになりました。

やったこと

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

10:04 - 間違えてバージニア北部リージョンにCloudFormationスタック作成してしまう

開始早々やってしまいました。東京リージョンで作成すべきCloudFormationスタックをバージニア北部リージョンで作成してしまいました。運良く早い段階で気づいて作成完了する前に削除しています。

10:06 - 東京リージョンでCloudFormationスタックを再作成

バージニア北部で作成していることに気づいて東京リージョンで作り直しています。

10:11 - サーバにSSH接続、環境構築

3台のサーバが作成されたことを確認したのでSSHで接続、環境構築をしています。我々はサーバ上で直接編集するスタイルですのでサーバ上にnvimを用意しています。 nvimはAppImageで持ち込んでますが、今回 libfuse.so.2 がインストールされてなかったので --appimage-extract で展開しました。

nvim --appimage-extract
rm nvim
ln -s squashfs-root/AppRun nvim

10:25 0 Rustで初回ベンチ失敗

言語をRustに切り替えて初回ベンチを回しましたが0点でした。docker compose上はrunningになのに正常に応答できない原因を調べていたんですが、なんと5分近く経過してもcargo buildがまだ終わってなかったというオチ。まじかよ厳しいなRust。

繰り返しbuildすることを考えるとDocker環境では厳しいと判断してDockerを剥がす対処を行いました。*1

剥がして再ビルドを行なっている間にベンチ前準備スクリプトベンチ後解析スクリプト、解析用にログ出力などを整備しています。

10:45 2601 Rustでベンチ初成功

開始から45分経過してようやくベンチに成功しました。 ベンチ結果を解析するためのkataribe設定ファイルの整備などをこのタイミングで実施しています。

10:54 - 当日マニュアル読み合わせ

@ishikawa84g が整備してくれた当日マニュアルまとめ(プレゼン資料)の読み合わせをおこなっています。必要な情報だけを抽出してくれるのでとても助かっています。

11:22 - UUIDにあたりをつけるもcargo buildによってメモリ不足でサーバが固まりGoへの移行を決意

topコマンドでmysqldのCPU使用率が高いことを確認したのでMySQLのスロークエリーを確認、ユニークなキーを降り出す id_generator テーブルに対するクエリーが遅いことを確認しています。 当初AUTO_INCREMENTでいいのでは?と考えましたがテーブルまたぎでユニークなIDを割り振っていることが判明、しかし格納先の各テーブルのIDがVARCHAR(255)であることを確認したのでUUIDで格納する方針にしました。uuid crateを使って実装していたんですが…

ここで競技サーバ(メモリ4GB)上でnvim+rust-analyzerを開きながらcargo buildを実行したせいでメモリが枯渇、SSH操作ができなくなりました。ohまじか。メモリ足りない。厳しい。

なんとかAWS管理コンソールからサーバを再起動して復旧させたものの、このまま進めるのは難しいと判断してRust言語を諦め、Go言語への切り替えを決断しました。

11:38 2493 Goで初ベンチ

Go言語もDockerから剥がした上で初ベンチを実施しています。ようやくここが我々のスタートラインだ。

11:43 3831 UUID実装に切り替え

Rust実装の際に検討していたUUIDへの切り替えをこのタイミングで適用しました。スコアがちょっと伸びてます。

func dispenseID(ctx context.Context) (string, error) {
       return uuid.NewString(), nil
}

github.com

12:06 4936 visit_historyをvisitに置き換え

まだmysqldのCPU負荷が高いのでMySQLのスロークエリーを確認したところ visit_history が最上位にきていることを確認。しかしSELECTしているのは1ヶ所しかなくUPDATEやDELETEもなし、また一番最初のレコードしか必要がないと判明したので、visit_historyへのINSERTをやめて別テーブルvisit を作って集計自体をやめる実装に切り替えることにしました。

CREATE TABLE visit (
  `tenant_id` BIGINT UNSIGNED NOT NULL,
  `competition_id` VARCHAR(255) NOT NULL,
  `player_id` VARCHAR(255) NOT NULL,
  `created_at` BIGINT NOT NULL,
  PRIMARY KEY (tenant_id, competition_id, player_id)
) ENGINE=InnoDB DEFAULT CHARACTER SET=utf8mb4;

初期データは流し込みinitializeで流し込み。

TRUNCATE TABLE visit;
INSERT INTO visit (tenant_id, competition_id, player_id, created_at) SELECT tenant_id, competition_id, player_id, MIN(created_at) AS min_created_at FROM visit_history GROUP BY tenant_id, competition_id, player_id;

これが23秒近くクエリーだったのでちょっとヒヤヒヤものでしたが、あとで流し込みではなくdump/restore方式に置き換えています。

github.com

12:08 昼食タイム

昼食はしっかりとりましょう

12:50 6785 SQLiteにインデックス追加

前の対応でmysqldの負荷が大きく下がり、アプリ側の負荷になったことを確認しました。

isuportsのCPU使用率が圧倒的でsysとiowaitが高い

ここでSQLiteのままでは厳しいのではないかと判断しMySQLへの移行を検討しています。webapp/sql/配下に移行で使えるsqlite3-to-sql スクリプトが存在し、これをそのまま使えるのではと検討。ですが、その前にまずはSQLiteにインデックスがなかったのでインデックスを追加しました。インデックスはMySQLに移行しても利用できますからね。

CREATE INDEX player_score_idx1 ON player_score (tenant_id, competition_id, player_id, row_num DESC);
CREATE INDEX player_score_idx2 ON player_score (tenant_id, competition_id, row_num DESC);
CREATE INDEX competition_idx1 ON competition (tenant_id, created_at DESC);
CREATE INDEX player_idx1 ON player (tenant_id, created_at);

SQLiteの初期化にはinitial_data配下がコピー元になっていたのでinitial_data配下のdbファイルにインデックスを追加、また随時DBが追加されるのでwebapp/tenant/10_schema.sqlにも上記を盛り込んでいます。

github.com

14:05 5164 rankingのN+1を解消

インデックスを追加してisuportsプロセスの%CPUは下がったものの、sysとiowaitは下がらないことを確認。一旦まずはSQLの改善をできないかと考えてrankingの改善をを検討しています。まずranking内のN+1となっていた部分を解消させています。

github.com

N+1の解消はスコアが下がってしまったのですが、これは次の布石のため必要になると判断してそのまま続行しています。

14:43 13349 SQLiteのデータをMySQLに移行しつつ最終スコア記録用テーブルの作成

tenantDBの各テーブルにはtenant_idカラムが含まれておりきちんとデータが入っていたので、テーブルを分ける必要はないと判断して1つのテーブルにすべて集約することにしました。 webapp/sql/sqlite3-to-sqlを使って初期データの全テーブルをMySQLに流し込んでいます。

MySQLへのデータ流し込みに時間がかかることを想定し、

for f in initial_data/*.db ; do echo $f ; webapp/sql/sqlite3-to-sql $f | mysql -u isucon -pisucon isuports ; done

なお、この実行にとても時間がかかるのですが、redo logの無効化などをおこなって処理の軽量化をおこなっています。

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

  /dev/shm/ r,
  /dev/shm/** rwk,

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

# 本番環境でやってはいけない
innodb_log_file_size = 64M
innodb_doublewrite = 0
innodb_flush_log_at_trx_commit = 0
innodb_flush_log_at_timeout = 3
innodb_log_group_home_dir = /dev/shm

2022/07/31追記:7/27にリリースされたMySQL 8.0.30で、上記パラメータをそのまま適用はできなくなっています。お気をつけください。

mysql

-- 本番環境でやってはいけない
ALTER INSTANCE DISABLE INNODB REDO_LOG;

ソースコードを注意深く読んだところ、必要なのはtenant, competition, playerごとに最終スコアだけだと判断できたので、それを記録するためのlast_player_scoreテーブルを作成しました。

CREATE TABLE last_player_score (
  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,
  created_at BIGINT NOT NULL,
  updated_at BIGINT NOT NULL,
  INDEX last_player_score_idx1 (tenant_id, competition_id, score DESC, row_num ASC),
  PRIMARY KEY (tenant_id, player_id, competition_id)
);

player_scoreにはすでにたくさんのレコードが登録されており、そこからlast_player_scoreを含めたデータの生成を毎回initializeでやっていると時間がいくらあっても足りないので、player, last_player_scoreはmysqldumpした結果をinitialize時に流し込むようにしています。

INSERT INTO last_player_score SELECT tenant_id, player_id, competition_id, score, row_num, created_at, updated_at FROM player_score WHERE (tenant_id, player_id, competition_id, row_num) IN (SELECT tenant_id, player_id, competition_id, MAX(row_num) FROM player_score GROUP BY tenant_id, player_id, competition_id);
mysqldump -u isucon -pisucon isuports player > ~/webapp/sql/admin/player.dump
mysqldump -u isucon -pisucon isuports last_player_score > ~/webapp/sql/admin/last_player_score.dump

github.com

15:04 20303 インデックスの追加とinterpolateParamsを設定

SQLiteからMySQLに移行したのに合わせてボトルネックが再びMySQLになりはじめました。 MySQLのスロークエリーログを解析してインデックスを追加し、またPrepareが上位にきたのでGo実装の定番設定であるinterpolateParams=trueを追加しました。

ALTER TABLE player ADD INDEX (tenant_id, created_at DESC);

github.com

15:18 15672 competitionもMySQLへ移動してSQLite撤廃

まだSQLiteを利用していたcompetitionテーブルもMySQLへ移動させました。結果としてスコアは下がりましたが方向性は間違っていないはずと判断してそのまま突き進んでいます。

github.com

15:32 34464 参加者向けAPIのN+1を解消する

引き続き MySQLの%CPUが高いので、 GET /api/player/player/:player_id で呼ばれているcompetitionをベースとしたN+1をJOINすることで解消させています。

github.com

15:54 43629 flockを外してトランザクション実装に変更

SQLiteを使わない実装には切り替えていたものの、まだflockの削除は行っておらず、flockが原因と思われる余計な遅延をアクセスログの解析結果で確認していました。 そのためflockを外しつつ、問題が出ないようにトランザクション処理を実装しました。

github.com

16:03 44383 INSERT player後のSELECTを削除

playerへINSERTする際、INSERTした結果をSELECTする実装になっていましたが、INSERT時にID含め必要な情報はすべて揃っているため、SELECTを行わない実装に変更しました。

github.com

16:42 44268 last_player_scoreのデッドロック対策

捌ける量が増えてくるとlast_player_scoreのDELETEしてからINSERTする処理でデッドロックが発生していました。 この事象は今年のkayac社内ISUCONでも発生した事象で、「あ、これ進○ゼミでやったところだ!」となり以下のように変更しています。

  • 変更前:レコードをDELETEしてからREPLACE
  • 変更後:レコードをREPLACEしてから古いレコードをDELETE

github.com

16:52 44051 scoreのN+1を部分的に解消した

アクセスログを解析するとscoreが上位に来ていたので、N+1を可能な範囲で解消させました。スコアへの影響は微妙でしたがそのままとしています。

github.com

17:15 63991 サーバ分割(1台→2台構成)

まだ改善できる余地は見つけてはいたものの、残りの時間内ですぐに解消できそうになかったので、このタイミングでアプリとDBのサーバを分けることにしました。ここまでは1台で処理していました。

サーバ 変更前 変更後
1台目 nginx + app(go) + MySQL nginx + app(go)
2台目 利用なし MySQL
3台目 利用なし 利用なし

我々のチームは基本的にサーバ分割はやることがなくなったり終盤になってから行うようにしています。その理由はボトルネックとなる箇所は随時変わるので、序盤に分割してもボトルネック次第で載せ替え直す必要がでてくる可能性があるためです。

github.com

17:24 62301 POST scoreで空データが投げられた場合に対処

空データが投げられてエラーになる状況が発生したので空でもエラーにならないよう対処しました。

github.com

17:39 72760 サーバ分割(2台構成→3台構成)

引き続きボトルネックMySQLのように見えたのですが、ベンチの後半でapp側の負荷が上がるシーンが発生していることを確認したので、3台目にもappを設置しました。結果スコアがさらに伸びることを確認しています。

サーバ 変更前 変更後
1台目 nginx + app(go) nginx + app(go)
2台目 MySQL MySQL
3台目 利用なし app(go)

github.com

17:47 76525 再起動対応と各種ログ無効化

再起動時のapp-db間接続の問題を回避するため秘伝のタレである StartLimitBurst を/etc/systemd/system/isuports.serviceに投入しています。これぞインフラ屋らしい運用でカバー作戦だ。

[Service]
StartLimitBurst=999

その他、各種ログの無効化を行いベストスコアは76525でした。再起動後に再度ベンチを行い75800が最終スコアとなっております。

github.com

*1:後から確認するとtargetやregistryはvolumesとしてマウントしてたのでdocker内でのcargo再ビルドは一応ケアされていた模様

書籍「達人が教えるWebパフォーマンスチューニング」はチューニングの考え方を教えてくれる良本

通称 #ISUCON本 を著者様からご恵贈いただきました。ありがとうございます。 gihyo.jp

所感

この書籍、言っていいのかわかりませんがまったくの初心者・初学者には難しい本かもしれません。私の感触では、Webサイトのプログラム作成、改修、構築、運用などに携わったり、Webサイトのパフォーマンスの問題に向き合ったことがある人が対象読者だと思いました。職種でいえばバックエンドエンジニア、インフラエンジニア、SREなどですね。もちろんそういった職種を目指している方や、純粋にISUCONに挑戦したい、パフォーマンスチューニングに興味がある、といった方も含まれます。

この本は特定の問題に対する直接的な答えではなく、パフォーマンスチューニングの考え方を教えてくれる内容になっています。この本を参考に実際に手を動かして実践するのが良いでしょう。現実のWebサイトをチューニングするでもいいですし、そのようなWebサイトが手元になければこの本でも何度も紹介されているprivate-isuISUCON過去問にチャレンジするのが得策です。付録Aにprivate-isuの攻略実践がありますが、これをただ単になぞるだけでなく、さらにそこからチューニングを重ねていき手に馴染ませるのがいいと思います。

ISUCON12に向けて

今年もISUCONが開催されます。この書籍を参考に鍛錬を積んで、ISUCON本選で会いましょう。この書籍で参加者のレベルが底上げされてさらに熾烈な戦いになると思いますが、私も本選に出られるように頑張ります。 isucon.net

レビュー

私は本書籍のレビューには参加してなかったのですが、レビュアーの気持ちになっていくつか補足します。

Cahpter2 モニタリング

世の中には様々なモニタリングツールがありますが、ISUCONにおける我々のチームはtopとdstatがメインですね。ベンチマーク前からtmux上でtopコマンドとdstatをならべて起動しておき、ベンチマーク中の負荷状況はこの2つのコマンドの結果を観察しています。dstatの個人的オススメオプションは以下です。

dstat -tlamp

横幅が133文字になるのでターミナルの幅は広げておきましょう。

tmux内でdstatとtopの結果を並べて眺める例

Chapter3 基礎的な負荷試験

P62 アクセスログの集計ツールとしてalpが紹介されていますが、拙作kataribeもご検討いただければ幸いです(宣伝)。 github.com ただ、kataribeは複雑になることを避けるため、あえてJSON形式のログには対応しませんでした。jqなどで整形してからkataribeに引き渡すか、書籍で紹介されているとおりalpの利用をご検討ください。

github.com

P68 アクセスログのローテーションについてですが、ISUCONにおいては昨年あたりからログの削除に truncate コマンドを使っています。

truncate -s 0 /var/log/nginx/access.log

truncateでファイルサイズを変更してもinodeは変わらずサービス再起動なども必要ないのでnginxの再起動やリロードも必要ありません。お試しください。truncateにdrawbackがあるようなら是非教えてください。

先日private-isuがarm64(aarch64)に対応したため、M1 Mac環境でもmultipass+cloud-initを利用することで手元で環境を用意できるようになりました。m1 macの手元で試したい方はこちらもご検討ください。

github.com

Chapter4 シナリオを持った負荷試験

P114 実際のアクセス状況を再現した負荷試験 についてですが、1つのWebページを読み込んだ際にどのようなリクエストが発生するかを調べる便利ツールが各種負荷テストツールには用意されています。

こういったツールはリクエストヘッダーも採取できるほか、ajaxなども捕捉できるので便利です。

また、こういったツールが用意されていないベンチマークツールでも、ブラウザが生成するHAR(HTTP Archive)ファイルを使えば手動でシナリオを書くよりも比較的簡単にシナリオを構築できると思います。ぜひお試しください。 riotz.works

Chapter5 データベースのチューニング

pt-query-digestは私もISUCON中に愛用するツールです。pt-query-digestでよく使用するオプションは --limit 100% です。

Chapter7 キャッシュの活用

P193 Thundering herd problemについてですが、これは厳密にいえばCache Stampedeの方が用語として正しいかもしれません。深掘りする場合はThundering herd problemのほかに、Cache Stampedeでも調べてみることをオススメします。

Chapter9 OSの基礎知識とチューニング

P252 systemdのunitファイルにulimit設定を追加するにあたり /etc/systemd/system/mysql.service.d/limits.conf を手動で作成されていますが、これは以下のコマンドを使うのがオススメです。

systemctl edit mysql.service

$EDITOR に設定されたエディタが起動するので上記limits.confで追加した記述を記載すればokです。 systemctl editで設定する場合は、手動でのdaemon-reloadも不要ですので、そのままrestartを実行することができます。

ISUCON11本選でチーム ウー馬場ーイー2 として参加し、7位になりました

TL;DR

運営の皆様、参加者の皆様、本当にありがとうございました。ISUCONと嫁は私の生きがいです。 優勝までは届きませんでしたが、Failで終わったISUCON10本選から少し人権を取り戻した気がします。

スコアについて

本選時間中のベストスコアは80,473、再計測による最終スコアは83,756、7位でした。 本来は12位ぐらいので実力でしたがFailとなったチームがいたので運良く10位以内に入れたようです。

f:id:tmatsuu:20210920165946p:plain

今回、途中で急激なスコアの伸びたことが理由でTVer賞をいただいたのですが、スコアが伸びたのは開始から3時間44分後の1台構成から2台構成に切り替えたタイミングでした。最初しばらくは1台構成で進めて、煮詰まったら複数台構成としているので、予め複数台構成にするよりも大きく伸びやすいというのがあると思います。そのようなスコア評価があることは事前に知らなかったのでラッキーでしたね。わいわい。

体制

あいこん なまえ やくわり
f:id:tmatsuu:20210822141550j:plain:w100 matsuu バリバリ実装する前衛
f:id:tmatsuu:20190909215614p:plain:w100 netmarkjp 司令塔
f:id:tmatsuu:20190909215620j:plain:w100 ishikawa84g SELinux AppArmorとマニュアルやコードやDiscordを見るセキュリティ&情報官

予選と同様に3人別々リモート、VDO.ninjaで画面共有、Discordで音声+文字チャットです。

使用したツールなど

  • sshrc ssh接続先に手元の環境(dotfilesなど)を持っていく
  • tmux ターミナル分割として
  • vim 我らがエディタ
  • top リソース使用状況確認
  • iotop I/Oが多いプロセス特定 NEW!
  • dstat リソース使用状況確認
  • MySQLTuner MySQLパラメータ確認
  • kataribe アクセスログ解析
  • pt-query-digest MySQLスロークエリー解析

このチームはサーバにSSH接続してサーバ上で直接vimを叩いてプログラムを変更するポリシーなので、isuconユーザ上にお互いのvim環境やtmuxの設定を分離するためにsshrcを使っています。便利。

最終構成

今回は最後までDBの負荷が高い状態を改善できませんでした。トランザクション処理を考えるとDBレプリケーションで整合性をとりつつ性能を出すのは難しいと判断したのでDB1台、app2台としています。

サーバ 構成要素 備考
1台目 nginx + app(go)
2台目 app(go)
3台目 mysql

やったこと

10:16 31,928 初期スコア

一通り環境を揃えてperformance_schemaなども有効化してベンチマークを回した結果です。

10:35 36,321 interpolateParams=true

golangの王道、interpolateParams=trueを設定しています。

10:41 32,810 スロークエリーログ集計に変更

performance_schemaからの集計は見にくいとの結論から従来どおりpt-query-digestによるスロークエリーログ集計に切り替えました。スコアは落ちました。

11:24 30,448 トランザクション処理引き剥がし

スロークエリーログで上位にCOMMITがきてしまい内容がわからないため、外せるトランザクション処理は引き剥がしていきました。スコアは下がりましたがスロークエリーログの見通しは良くなったためそのまま進めます。

11:30 33,240 アプリログ外しとCOMMIT特定

11:24の対応でもある程度COMMITは排除できたのですが、残るCOMMITを判別するため、COMMITにコメントを入れることでスロークエリーログの出力を分ける対策をしました。こんな感じ。

- if err = tx.Commit(); err != nil {
+   if _, err := tx.Exec("COMMIT /* RegisterCourses */"); err != nil {

これは慧眼。自分たちを褒めてやりたい。スコアが少し上がったのはアプリログ外しのおかげです。

11:51 40,492 mysqlとnginxのパラメータチューニング

秘伝のタレの時間です。

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

innodb_log_file_size = 32M
innodb_doublewrite = 0
innodb_flush_log_at_trx_commit = 0
innodb_flush_log_at_timeout = 3

innodb_log_group_home_dir = /dev/shm

disable-log-bin

innodb_log_group_home_dir の変更はそのままだと正しく動作しないためAppArmorも調整してます。ワレワレハAppArmorト共存スル。

nginxはupstreamとHTTP/1.1の接続設定の他、nginxのerror.logに client request body is buffered to a temporary file が出力されていたのでassignmentsは proxy_request_buffering off を追加しています。

  location ~ ^/api/courses/.*/classes/.*/assignments$ {
    proxy_pass   http://app;
    proxy_set_header Connection "";
    proxy_http_version 1.1;
    proxy_request_buffering off;
  }

12:06 39,072 db接続数を増やしたら遅くなった

DBの接続数がデフォルトの10のままだったので100に増やしてみました。

-    db.SetMaxOpenConns(10)
+   db.SetMaxOpenConns(100)
+   db.SetMaxIdleConns(100)

が、これが元でスコアが下がりました。状況を確認するとFOR UPDATEによるロック待ちで滞留が増えてしまっているようでした。なるほどなるほど。ただ将来ロックを解消して接続数を増やす必要がでてくるだろうと判断して差し戻さずそのまま進めています。

12:52 41,368 cpをlnに変更する

今回の本選は提出された課題(pdfファイル)をzip形式で一括ダウンロードする機能があるのですが、pdfファイルをzipで圧縮する前にcpでファイル名をかえつつ集めている処理があったのですが、ここでインフラエンジニア力が発揮されcpをlnで置き換える奇策が適用されました。

   // ファイル名を指定の形式に変更
    for _, submission := range submissions {
        if err := exec.Command(
-          "cp",
+           "ln",
            AssignmentsDirectory+classID+"-"+submission.UserID+".pdf",
            tmpDir+submission.UserCode+"-"+submission.FileName,
        ).Run(); err != nil {

lnコマンドは-sをつければシンボリックリンクを作成しますが、-sをつけなければハードリンクになるため副作用が発生しにくいうえに高速にリンクを作成できるため今回の用途にピッタリでした。わいわい。これがインフラエンジニアだ。

13:35 42,491 GetGradesのN+1を一部解消

/api/users/me/grades でたびたびタイムアウトが発生しており、IFNULLが使われれているクエリーがスロークエリーログのトップに来ていたのですが、かんたんな改善が思いつかず、取り急ぎ同処理内の修正できそうなN+1を解消しています。スコアの伸びはわずかです。

13:44 68,795 2台構成に変更

ここまでで一番のボトルネック(と思っていた)DBに対して打つ手がなくなってきたので、3台目をDBサーバとして利用するよう構成変更を行いました。このときのスコアの伸びがTVer賞になっています。

16:07 75163 GPAの統計値を予め計算したスコアテーブルを作成

DBサーバを分離してもDBのCPU負荷がボトルネックになっていたため、採点をするたびに total_score として積算していくためのカラムを追加したのですがdeadlockが多発、ええいテーブルも分離して積算だとテーブルを分けてもdeadlock、最終的には一応スコアが出るようになったのですが、何がなんだかさっぱりわからずやたら時間を食ってしまいました。厳しい。

16:22 77,029 課題提出周りを改善

zipダウンロードでnginxにてbufferingが発生していることを確認したため proxy_buffering off を追加しています。

  location ~ ^/api/courses/.*/classes/.*/assignments/export$ {
    proxy_pass   http://app;
    proxy_set_header Connection "";
    proxy_http_version 1.1;
    proxy_buffering off;
  }

また、合わせてアップロードされた課題は io.ReadAll() の代わりに io.Copy() でメモリに読ませず直接出力するようにしています。

16:45 73,395 DB接続数上限を200に増やすもスコア下がる

DBの接続数が上限まで使い切っていたので上限を増やしてみたものの、スコアはむしろ下がってしまいました。LOCK待ちが増えたからですね。

17:00 78,336 appを2台構成に

引き続きDBのCPU負荷がボトルネックになっている状況(だと思っていた)のですがDBを2台構成にするのは難しい(と思い込んでいた)ので2台目にもappを配置して最終構成としました。結果、スコアは少しだけ伸びました。

17:35 80,473 ログ出力を無効にしてスコアアップ

nginxのアクセスログmysqlのスロークエリーログの出力を停止することで若干のスコアアップとなりました。

18:00まで 偏差値がマイナスになっていることに気づいて慌てふためく

ふとサイトにログインして動作確認していたところ、S99999ユーザで偏差値がマイナス値になっていることに気づいて焦りました。 f:id:tmatsuu:20210920201312p:plain 学内GPA偏差値 -331.8 とは

偏差値でマイナスとかありえへんのでどこかでエンバグしてしまったのだと思い、関連しそうな場所をrevertしてみたりしたものの改善せず。ええい仕方ない最終的にスコアのよかった実装にしてそのままフィニッシュとなりました。

この偏差値は最初からバグってたのか、エンバグしたのかはまだわかってません。追試で調査を行おうと思います。おわり。

おまけ1 やったこと公開しました。

予選本選でやったことはgithubで公開してます。

github.com github.com

おまけ2 OODAループについて

本選直前のgihyo.jpのインタビュー記事でも少しだけ回答したのですが、我々の戦略はOODAループを基本としています。

OODAループ - Wikipediaより:

OODAループは、観察(Observe)- 情勢への適応(Orient)- 意思決定(Decide)- 行動(Act)- ループ(Implicit Guidance & Control, Feedforward / Feedback Loop)によって、健全な意思決定を実現するというものであり、理論の名称は、これらの頭文字から命名されている。

これはgihyo.jpのインタビュー記事の設問に

1.今回の予選課題が発表されて,最初に感じたこと,また,具体的に取り組むに当たってどのような方針でスタートしましたか。

とあって、事前に環境整備の準備はするものの、予選課題の発表後に大方針のようなもの決めてないしPDCAじゃないよなぁ、とググってたら見つけた理論で、我らが今までISUCONでやっていたことはOODAループと同じだった、というだけです。

OODAループに関する書籍YouTube解説動画などもあるのですが、ビジネス寄りでちょっと胡散臭い雰囲気があるのが残念ですね。エンジニアの我々は理論だけ活用していきましょう。

OODAループに関して1冊だけ書籍購入しました。まだ全部読めてません。

ISUCON11予選でチーム ウー馬場ーイー2 として参加し、本選進出を決めました

TL;DR

ISUCON11予選にチーム ウー馬場ーイー2 として出場しました。 上位25チームに残り本選進出が決まりました。やったね。 最終スコアは389509で8位、予選中のベストスコアは394682でした。本選もがんばるぞ!

毎年素晴らしいコンテストを開催してくださる運営様には感謝しかありません。本当にありがとうございます!!1

体制

あいこん なまえ やくわり
f:id:tmatsuu:20210822141550j:plain:w100 matsuu バリバリ実装する前衛
f:id:tmatsuu:20190909215614p:plain:w100 netmarkjp 司令塔
f:id:tmatsuu:20190909215620j:plain:w100 ishikawa84g SELinuxAppArmorとマニュアルやコードやDiscordを見るセキュリティ&情報官

3人がそれぞれ別々の場所にいたのでリモート接続しながら挑みました。 画面共有は VDO.ninjaRemote Screenshare into OBS で生成されたURLを直接相互参照しました。遅延なく解像度も高くて最高。 音声と文字チャットはDiscordを使ってます。ISUCON公式のコミュニケーションツールもDiscordなのでツールを統一できて便利。

使用したツールなど

方針

  • サーバ上で直接vimソースコードを変更するスタイル
    • 手元での再現環境構築や外部からのデプロイは行わない
    • sshrc で環境がかぶらないようにしてメンバーごとにvim/ssh環境を分離
  • 実装言語はGoを選択
  • 負荷テスト中は topdstat -tlamp を目視確認
  • 負荷テスト後にアクセス解析
    • nginxのログをkataribeで解析して /result/kataribe.log に出力
    • mysqltuner.plを実行して /result/mysqltuner.log に出力
    • MySQLはスロークエリーを出力せずパフォーマンススキーマを有効にしてslowquery2tsvでTSV化して /result/slowquery.tsv に出力
      • ただslowquery2tsvはMariaDBへの対応ができておらず
      • 急遽使い慣れたpt-query-digestに差し替えてスロークエリーを /result/slowquery.log に出力
  • /git init
    • /etc/home と解析結果を含む /result をまるごとコミット(必要に応じて.gitignoreで除外)
    • git add / して git commit
    • GitHubのプライベートリポジトリに git push

今回スロークエリー解析用にslowquery2tsvを作成したのですが、その理由は以下のとおりです。

  • GitHubCSV/TSVビューアが優秀なのでこれを使いたかった
  • pt-query-digestは大量のスロークエリーが出力された場合に解析が遅いのでPerformanceSchemaを使いたい
  • TSVであればless/vimでもおおよそ桁揃えできるので見やすい

slowquery2tsvは次回までに修正しておきたいと思います。

gitは履歴管理と差し戻しが必要になった際の確認用です。パッケージインストールでの /etc 配下更新やアクセス解析結果を含むため git revert の実行は想定してません。割り切り。 /home/etc を含むことで何をやったかが後から追えるのでブログでまとめやすくなります。

最終構成

当初は1台目のみを使い、ある程度負荷傾向が定まってきてから複数サーバを使うように構成変更しました。 複数サーバに分けることにしたタイミングではDBよりもappのCPU負荷が高かったので、appを2台配置としています。

サーバ 構成要素 備考
1台目 nginx + varnish + app(go) varnishを追加インストール
2台目 MariaDB 初期実装のままバージョン変更なし
3台目 app(go)

nginxの設定はこんな感じです。

  • /api/trend はvarnish経由で1台目のappへ
  • /api/isu/*/graph/api/condition/* はvarnishを経由せず1台目と3台目のappへ
  • 上記以外の /api//initialize はvarnishを経由せず1台目のappへ
  • それ以外はすべてnginxで応答

ベンチマーク結果

ベストスコア

f:id:tmatsuu:20210822133617p:plain

あくまでベストスコアであって実際には上下してます。

全スコア

f:id:tmatsuu:20210822134154p:plain

回数多いかな。どうでしょう。

やったこと

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

10:23 2974 初期ベンチ

公式マニュアルに従いインスタンス作成完了が 10:05、SSHでログインが 10:10 でした。 そこから必要なパッケージのインストールや git init などが完了して初回ベンチマークが 10:23 でした。

10:35 1829 パフォーマンススキーマ有効化

集計のためにMariaDBのPerformanceSchemaを有効にして再計測したらスコアが下がりました。まぁそんなもん。

10:42 1683 スロークエリーログ出力に切り替え

MariaDBのPerformanceSchemaは出力結果がMySQL8と異なり手元の集計ツールが正しく動作しなかったので、方針変更してスロークエリーログ出力とpt-query-digestに切り替えました。スコアはさらに下がって1683。まぁそんなもん。

10:51 16664 DB周りチューニング

pt-query-digestでスロークエリーが顕著に出ていたので、この内容を見ながらDB周りの調整を行っています。

# Rank Query ID                            Response time  Calls R/Call V/M
# ==== =================================== ============== ===== ====== ===
#    1 0x8155B89FFD74A9D523D19AC409FD97AF  330.2609 56.9%  2447 0.1350  0.06 SELECT isu_condition
#    2 0x931A992E852C61FC6D46141A39DEF4FE  178.2064 30.7%  3393 0.0525  0.06 SELECT isu_condition
#    3 0xFFFCA4D67EA0A788813031B8BBC3B329   31.0515  5.3%  7506 0.0041  0.01 COMMIT
#    4 0xDA556F9115773A1A99AA0165670CE848   16.7825  2.9% 87951 0.0002  0.00 ADMIN PREPARE
#    5 0xB8B32624C3268C0925657C305C0ED778   14.2339  2.5% 69887 0.0002  0.00 INSERT isu_condition
#    6 0x9C6C682008AE0D08F3E2A0049B030C70    4.3813  0.8%   141 0.0311  0.03 SELECT isu_condition
#    7 0x5F580A12ADA1633C9634298BE5BD9422    1.7119  0.3%    61 0.0281  0.05 SELECT isu_condition
#    8 0x1E561CE87F050ED58A7E1A7FBB6C2285    1.0212  0.2%  7023 0.0001  0.00 SELECT isu
#    9 0x07890000813C4CC7111FD2D3F3B3B4EB    0.5763  0.1% 87951 0.0000  0.00 ADMIN CLOSE STMT
#   10 0x8C2BC651CBBBF3DB41D1CAD61AA0BD68    0.5094  0.1%  1200 0.0004  0.00 SELECT isu
  • goのdb接続パラメータに interpolateParams を追加
  • インデックス追加
    • テーブル isuINDEX (jia_isu_uuid) を追加
    • テーブル isu_conditionINDEX (jia_isu_uuid, created_at) を追加
      • しかしこの created_attimestamp の間違いだったと後で気づく

これによってpt-query-digestの結果は、Response timeが大きく改善しました。

# Rank Query ID                            Response time  Calls R/Call V/M
# ==== =================================== ============== ===== ====== ===
#    1 0x931A992E852C61FC6D46141A39DEF4FE  116.4533 39.7% 13452 0.0087  0.02 SELECT isu_condition
#    2 0x9C6C682008AE0D08F3E2A0049B030C70   50.8375 17.3%  2649 0.0192  0.02 SELECT isu_condition
#    3 0xFFFCA4D67EA0A788813031B8BBC3B329   42.2897 14.4%  9056 0.0047  0.01 COMMIT
#    4 0x8155B89FFD74A9D523D19AC409FD97AF   38.4616 13.1%  4336 0.0089  0.02 SELECT isu_condition
#    5 0xB8B32624C3268C0925657C305C0ED778   25.6250  8.7% 75058 0.0003  0.01 INSERT isu_condition
#    6 0x5F580A12ADA1633C9634298BE5BD9422   12.4012  4.2%   731 0.0170  0.02 SELECT isu_condition
#    7 0x677D4DCDF729CC334DE038E9477B32B3    1.8281  0.6%   232 0.0079  0.01 SELECT isu_condition
#    8 0x8C2BC651CBBBF3DB41D1CAD61AA0BD68    1.0356  0.4%  4400 0.0002  0.01 SELECT isu
#    9 0x1E561CE87F050ED58A7E1A7FBB6C2285    0.9872  0.3%  7556 0.0001  0.01 SELECT isu
#   10 0xADCA4F127A769A45A2D1B74705103105    0.9068  0.3% 11201 0.0001  0.00 SELECT user

ちなみに各テーブルは /initialize が呼ばれるたびに毎回 DROP TABLE が実行されるので、インデックスは ~/webapp/sql/* もしくは /initialize の中で追加する必要がありました。

11:03 18138 nginxチューニング

続いてnginxにチューニングに入ります。

  • nginxとapp間で持続的接続が有効化
  • /api/と/initialize以外はnginxから直接返す

プログラムをみると /isu/*/register などはindex.htmlを返していたので、 try_files を使って存在しないファイルはすべて /index.html を返すようにしているのが工夫ポイントです。

upstream app {
  server 127.0.0.1:3000;
  keepalive 16;
  keepalive_requests 10000000;
}

server {
    listen 443 ssl http2;

    ssl_certificate /etc/nginx/certificates/tls-cert.pem;
    ssl_certificate_key /etc/nginx/certificates/tls-key.pem;

    location /api/ {
        proxy_set_header Host $http_host;
        proxy_set_header Connection "";
        proxy_http_version 1.1;
        proxy_pass http://app;
    }

    location /initialize {
        proxy_set_header Host $http_host;
        proxy_set_header Connection "";
        proxy_http_version 1.1;
        proxy_pass http://app;
    }

    root /home/isucon/webapp/public;
    index index.html;
    location / {
      try_files $uri /index.html;
      expires 86400s;
    }
}

11:09 17774 nginxにclient_body_buffer_size追加

/var/log/nginx/error.log を確認すると POST /api/isu で一時ファイルが生成されていることを確認したため、アクセスログ$request_length を出力してサイズを確認しその最大値を少し上回る値を client_body_buffer_size として設定しました。

    location ~ ^/api/isu$ {
        client_body_buffer_size 128k;
        proxy_set_header Host $http_host;
        proxy_set_header Connection "";
        proxy_http_version 1.1;
        proxy_pass http://app;
    }

でも今思えば proxy_request_buffering でやるべきだったかもですね。このあたりは後日追試しようと思います。

11:23 17618 bulk insertに変更

kataribeの出力結果を見るとトップは POST /api/condition/* でした。ちなみにkataribeはほとんど Sort By Total しか見てません。

Top 40 Sort By Total
Count    Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max    2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
75487  433.603  0.0057  0.0139  0.000  0.001  0.016  0.035  0.073  0.107  75213    0  274    0          42          0          0         14  POST /api/condition/<uuid> HTTP/2.0

そこで該当の関数を以下のように変更しました

  • INSERT前のSELECTが0件以上あるかの確認だったので SELECT 1 FROM ... LIMIT 1 に変更
  • INSERTを数珠つなぎにしてbulk insertに変更

結果スコアは下がったものの、Countが増えてMeanは下がってるので負荷軽減に効果があったと判断しokとしています。

Top 40 Sort By Total
Count    Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max    2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
75731  339.605  0.0045  0.0106  0.000  0.001  0.012  0.023  0.055  0.216  75508    0  215    8           0          0          0          0  POST /api/condition/<uuid> HTTP/2.0

11:44 20127 /api/trendの全件取得を1件に

引き続きMariaDBのCPU負荷が高いためpt-query-digestのトップに来ているクエリーを確認したところ /api/trend の中で実行しているクエリーであることを確認しました。

SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY timestamp DESC

このクエリーはLIMITが使われていないものの、その後の処理で最初の1件しか使っていないこと、また一部のカラムしか利用していないので以下ようにクエリーを変更しました

SELECT `condition`, timestamp FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY timestamp DESC LIMIT 1

conditionが予約語らしく バッククォートでくくる必要があったのが罠でしたね。 ちなみにN+1は解消してません。1件取得するだけの変更にとどめています。

11:49 37019 インデックスの間違いに気づく

10:51に追加したインデックスの間違いに気づき isu_conditionINDEX (jia_isu_uuid, created_at)INDEX (jia_isu_uuid, timestamp) に変更しました。

変更前のpt-query-digest

# Rank Query ID                            Response time  Calls R/Call V/M
# ==== =================================== ============== ===== ====== ===
#    1 0x2C2674DBBE2489BF6C83BB0B21790D62  140.3237 32.3% 16026 0.0088  0.02 SELECT isu_condition
#    2 0x9C6C682008AE0D08F3E2A0049B030C70  107.6753 24.8%  3357 0.0321  0.02 SELECT isu_condition
#    3 0x8155B89FFD74A9D523D19AC409FD97AF   97.9899 22.6%  7478 0.0131  0.02 SELECT isu_condition
#    4 0xFFFCA4D67EA0A788813031B8BBC3B329   36.3303  8.4%  9885 0.0037  0.00 COMMIT
#    5 0x5F580A12ADA1633C9634298BE5BD9422   27.1060  6.2%   974 0.0278  0.02 SELECT isu_condition
#    6 0xB8B32624C3268C0925657C305C0ED778   12.5142  2.9%  7610 0.0016  0.01 INSERT isu_condition
#    7 0x677D4DCDF729CC334DE038E9477B32B3    4.6057  1.1%   381 0.0121  0.02 SELECT isu_condition
#    8 0xADCA4F127A769A45A2D1B74705103105    1.8215  0.4% 17482 0.0001  0.00 SELECT user
#    9 0x8C2BC651CBBBF3DB41D1CAD61AA0BD68    1.4361  0.3%  5154 0.0003  0.00 SELECT isu
#   10 0xB5F4855605637317357023AD70B91455    1.3706  0.3%  8824 0.0002  0.00 SELECT isu

変更後のpt-query-digest

# Rank Query ID                            Response time Calls R/Call V/M 
# ==== =================================== ============= ===== ====== ====
#    1 0x9C6C682008AE0D08F3E2A0049B030C70  42.6501 29.9%  5344 0.0080  0.01 SELECT isu_condition
#    2 0xFFFCA4D67EA0A788813031B8BBC3B329  35.1129 24.6% 13416 0.0026  0.01 COMMIT
#    3 0x2C2674DBBE2489BF6C83BB0B21790D62  25.9887 18.2% 45806 0.0006  0.00 SELECT isu_condition
#    4 0x5F580A12ADA1633C9634298BE5BD9422  13.6792  9.6%  2282 0.0060  0.01 SELECT isu_condition
#    5 0x8155B89FFD74A9D523D19AC409FD97AF   8.8025  6.2% 22660 0.0004  0.00 SELECT isu_condition
#    6 0xB8B32624C3268C0925657C305C0ED778   6.4959  4.6%  7621 0.0009  0.00 INSERT isu_condition
#    7 0xADCA4F127A769A45A2D1B74705103105   2.3164  1.6% 44119 0.0001  0.00 SELECT user
#    8 0xB5F4855605637317357023AD70B91455   1.8257  1.3% 26210 0.0001  0.00 SELECT isu
#    9 0x8C2BC651CBBBF3DB41D1CAD61AA0BD68   1.6544  1.2% 14503 0.0001  0.00 SELECT isu
#   10 0x88716D544EA925A1EE9114761B982E3E   0.7488  0.5%  7627 0.0001  0.00 SELECT isu

Response timeが大きく改善しましたね。

12:09 44034 Varnishで/api/trendをキャッシュ

マニュアルと実際の動作をにらめっこしたところ、 /api/trend はログイン状況に関わらずコンテンツの出し分けがなくログインチェックもないのでキャッシュで返せることに気づきました。 そこでVarnishをインストールしてキャッシュ応答をするように変更しています。CookieリクエストヘッダーがついているとVarnishはキャッシュを返さないので、Cookieリクエストヘッダーは vcl_recv で削除しています。

nginx

upstream varnish {
  server 127.0.0.1:6081;
  keepalive 16;
  keepalive_requests 10000000;
}

server {

    # ...

    location ~ ^/api/trend$ {
        proxy_set_header Host $http_host;
        proxy_set_header Connection "";
        proxy_http_version 1.1;
        proxy_pass http://varnish;
    }

varnish

backend default {
    .host = "127.0.0.1";
    .port = "3000";
}

sub vcl_recv {
    if (req.url ~ "^/api/trend") {
        unset req.http.cookie;
    }
}

sub vcl_backend_response {
    set beresp.ttl = 0.8s;
    set beresp.grace = 0.2s;
}

変更前のkataribe

Count    Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max    2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
  637  257.361  0.4040  0.1896  0.003  0.415  0.638  0.713  0.870  0.978    573    0    3   61     2575394          0       4043       4535  GET /api/trend HTTP/2.0

変更後のkataribe

Count    Total    Mean  Stddev    Min  P50.0  P90.0  P95.0  P99.0    Max    2xx  3xx  4xx  5xx  TotalBytes   MinBytes  MeanBytes   MaxBytes  Request
  864   15.936  0.0184  0.0651  0.000  0.000  0.023  0.158  0.359  0.515    798    0    0   66     3559454          0       4119       4537  GET /api/trend HTTP/2.0

Meanが大きく下がりました。わいわい。

13:39 79819 たくさん修正

だんだん雑になってきました。昼飯を食べながらざっくりやったほうがいいことを調べて、まとめて適用します。

  • isu にインデックス INDEX (jia_user_id, jia_isu_uuid) を追加
  • アプリからのDB接続数を引き上げ db.SetMaxOpenConns(150) db.SetMaxIdleConns(150)
  • /api/trendのレスポンスをVarnishでgzip圧縮
  • POST /api/condition/* は最後のconditionだけ登録だけでいいのでは?と判断してで最後の1件だけ登録、ついでにトランザクション処理を解除
  • dropProbabilityを0.9から0.6に変更
  • innodb周りのチューニングを追加

14:25 74425 iconを静的ファイルに出力してアプリから返す

GET /api/isu/*/icon がkataribeで2位となっているのでDBに格納せずnginxから返すようにしました。このエンドポイントはログイン必須であるため単純に画像を返すとエラーになるのではと判断し、ファイルに書き出したもののnginxからは応答せずアプリから応答しています。 スコアは下がったもののDBの負荷とトラフィック量は減っており、後々効いてくるだろうと判断して差し戻しは行ってません。

14:44 146710 DBを2台目サーバに移す

スコアに直結するような改修がおもいつかなくなってきたこと、またアプリとdbでCPU負荷を食い合う状況になってきたので、2台目サーバのMariaDBを利用するようにしました。それまではずっと1台目サーバだけで進めていました。

15:22 208386 iconをnginxから返すためX-Accel-Redirectレスポンスヘッダーを追加

DBを分離したあともアプリの負荷が高いため、アプリの処理を減らそうと X-Accel-Redirect レスポンスヘッダーを返すことでnginxから静的ファイルを返すように変更しました。またiconは一度登録すると更新されることはないためキャッシュするよう設定しています。

画像の出力は /home/isucon/tmp に生成していたので、そこをinternalで取得できるようにして X-Accel-Redirect でリダイレクトさせています。ついでにexpiresも追加しています。

    location /icon {
        internal;
        alias /home/isucon/tmp; 
        expires 86400s;
    }

    location ~ ^/api/isu/.*/icon$ {
        proxy_set_header Host $http_host;
        proxy_set_header Connection "";
        proxy_http_version 1.1;
        proxy_pass http://app
        expires 86400s;
    }

15:31 188370 静的ファイルをgzip圧縮で応答するもスコアが下がる

~/webapp/public/ 配下のファイルについてそういえばgzip圧縮応答していなかったと思い出し、gzip圧縮してnginxの gzip_static で応答したのですがなぜかスコアが下がってしまいました。何度かon/offを切り替えながらベンチを回したもののoffが良さそうなので最終的にはoffとしました。

この原因は何だったんでしょうね。gzip展開でベンチマーカーのCPU負荷が高まるからか?とか思ったんですが真相は不明です。

16:27 66170 graphの改善を試みるもスコアだだ下がる

マニュアルを読むとグラフの確認による加点があるものの、自分たちの環境はすべてWorstになっていることからこれを改善すればスコアが大きく伸びるのではと思ったのですが、改善しきれませんでした。ここは今後の課題となります。

16:49 269411 3台目サーバをapp用に利用する

アプリのCPU負荷が高い状況が続いていたため、ここで3台目サーバをapp用に利用しています。ほぼほぼ上記最終構成と同じ構成になりました。 これによりスコアが大きく改善しました。

17:00 379417 dropProbabilityを差し戻すとスコアが上がる

打つ手が思いつかない中、13:39に0.6に下げていたdropProbabilityを0.9に戻してみたら大きく改善しました。なんでやねん。よくわかりません。

18:18 394682 最終調整

最終調整を行っていました。

  • nginxの worker_connections を増やす
  • nginxの upstream において keepalive を増やす
  • MariaDBquery_cache を無効にしてみたもののスコアが下がったので差し戻す
  • MariaDBのスロークエリーログ出力をやめる
  • nginxのアクセスログ出力をやめる
  • 再起動試験を実施

最終調整の中で記録したベストスコアが 394682 でした。

その後も何度かベンチガチャを回して予選中の最終スコアは18:39に記録した388657です。

HighLoad Cup 2021(Gold Rush) write-up

ロシア企業Mail.ruが主催するパフォーマンスチューニングコンテストHighLoad Cup 20201に参加したのでその報告。

Webサイト

https://cups.mail.ru/en/contests/goldrush

結果

Battle-Round 47位(63位以上がFinal進出)、Final-Round 37位でした。 Battle-RoundとFinal-Roundは内容は同じまま、Finalはチート対策でSEEDがランダムになっただけなので実質課題は1つです。 可もなく不可もなく、微妙なスコアですね。はい。

課題

簡単にまとめるとこんな感じです。

時間内に宝物を「探索」して「掘削」して「換金」するHTTPクライアントを実装せよ

ざっくりとした仕様は以下の通り。

  • 縦横3500x3500、深さ10の領域が与えられる
  • POST /exploreで指定した縦横範囲の探索ができる
    • 探索するとその範囲に含まれる宝物の数がわかる
    • 探索は範囲指定が可能(0,0の座標から3x4の範囲を探索など)
    • 探索ではどの深さに宝物があるかわからない
  • POST /digで指定した場所(x, y, depth)を掘削ができる
    • 1度に掘削できる深さは1のみ
    • 深さ2を掘削するためには先に深さ1を掘削しないといけない
    • 横に掘ることはできない
    • 掘削にはライセンスが必要
  • POST /licenseでライセンス取得ができる
    • ライセンスは無料と有料がある
    • 1ライセンスで掘削できる回数は無料と有料で異なる
    • 1度に保持できるライセンスは10まで
  • POST /cashで掘削された宝物をコインに換金できる
    • コインの数=最終スコア
    • 有料ライセンスはコインを消費する=最終スコアも減る

詳細は以下をご参照ください。

やったこと

以下、ネタバレ含みます。

  • 公式のpython実装を元にgolang実装で書き換え
  • ライセンスを10個取得して並行処理
  • 「探索」「掘削」「ライセンス取得」「換金」をそれぞれgoroutineにしてchannelで受け渡し
  • channelのcapを抑えめにすることで無駄なHTTPリクエストが発生しないように調整
    • それぞれの処理を複数workerを構成に
  • 有料ライセンスを使用してレイテンシ改善
    • ただし有料はコインを消費=スコアが下がるのでいい塩梅を模索
    • コインが入手できるまでは無料ライセンス、入手できるようになったら1コイン消費で有料ライセンス
  • 1つのライセンスで複数回掘削できることから、ライセンスを掘削回数分コピーして一斉に同時掘削
    • 掘削完了を検知するためにsync.WaitGroupを活用しまくる
  • 4x4や8x8など広めの範囲から枝刈り全探索で効率化
    • 試行錯誤の結果、1x10、1x15、2x7あたりが何故か効率が良かったので採用
  • GOGC=off
  • ライセンス取得のレイテンシがボトルネックになるのでPOST /digのHTTPリクエストを投げた時点でライセンス取得を行う
  • net/http/httptrace.ClientTrace.WroteRequest を使って最速再取得を試みる
    • しかしWroteReuqestではエラー多発。GotFirstResponseByteであればエラーはなくなるものの改善効果なし
  • encoding/jsongithub.com/goccy/go-json に置き換え
    • go build 時のメモリ消費がネックに
    • 簡易なJSONは自力の文字列処理でencode/decodeすることでさらに軽量化
  • net/httpgithub.com/valyala/fasthttp に置き換え
    • CPU負荷は下がったがCPUがボトルネックになってなかったのであまり効果はなかった
  • HTTP Keep-Aliveが無効になっているので事前に net.Dial を行うことで自前コネクションプール
    • 思いついたときは勝利を確信したもののあまり効果はなかった

スコア上位がやっていた(らしい)こと

公式Telegramでの事後チャットを眺めていたのですが、こんな感じみたいです。

  • Battle-roundは宝物の配置が固定なため配置をハードコードして探索処理をスキップ
  • Final-roundはハードコード対策が行われたものの、サーバサイドがgolang実装なのを考慮して疑似乱数生成(PRNG)の使われ方を推測、宝物の配置パターンからSEEDを特定することで探索処理をスキップ

いやーこれは度肝抜かれましたね。主催側もここまですることを想定していなかったようです。まじかよスゲーなロシア。

ソースコード

サーバサイドのソースコードは全日程終了後公開されたので手元環境で再現可能です。わいわい。 https://github.com/All-Cups/highloadcup/tree/main/goldrush/server

まとめ

今回はHTTPクライアントを実装することもあって、これまでISUCONなどで培ってきたWebサービスに関する知識が生かせず苦労したのですが、その分HTTPクライアントに関する知見を多く得られたこと、またgoroutine、channel、syncパッケージを使った並行処理の良い練習になりました。今後どこかで活かせるといいですね。