1. これはなに？
AWSにISUCONの過去問環境を作って初めてチューニングしてみるまでのメモです。
1.1 経緯
ISUCON は与えられたサーバを８時間でどれだけ高速化出来るか競うコンテストです。2022年予選で"MySQL"がtwitterトレンドにあがってきて阿鼻叫喚だった様子が面白過ぎました。
技術チャレンジ部で観戦していたら、いつの間にかチームを結成していました。
（Webチューニングって中々経験出来ないし、これだけガチスポーツなコンテストは貴重な気がします。来年参加目標。）
1.2 概要
- ISUCON の過去問のgithubから取得したAMIイメージでAWS EC2環境を構築（ここはお手軽）。
- ログインしてサーバの構成を確認してベンチマークを実施します（基本的にsshでCLI操作）。
- githubにコードリポジトリを作ってコード改変の準備をします。
- RDBのボトルネックを調査して超遅かったところにINDEXを追加しました。
- 再ベンチマークしてスコアのアップを確認します。
２．環境構築
2.1 AWS EC2構築
ISUCONの過去問サイトに各種環境（AWS/Docker/WSL2/MACなど）対応の構築手順が有ります。既にAWSアカウントを持っているなら、手早く本番に近いベンチマークが出来るAWSがおススメです。AWS版の過去問githubページには10種類程のAMIが有ります。
今回はISUCON11予選を選択しました。表からAMIを選んでクリックすると自分のAWS management consoleページが開いてAMIが操作出来るようになります。「AMIからインスタンスを起動」ボタンを押してEC2を作成しましょう。普段の作業にはローコストな小さいインスタンス（t2-microとか）で良いでしょう。ベンチマーク時だけスケールアップすれば良いので。上記表を見るとSSHアカウント名は"ubuntu"とのことなので、出来たEC2に下記の様にssh接続してみます。（sshの秘密鍵にはインスタンス作成時に登録したものを指定。）
$ ssh -l ubuntu -i ~/.ssh/mysecretkey.pem x.x.x.x
Welcome to Ubuntu 20.04.4 LTS (GNU/Linux 5.13.0-1022-aws x86_64)
...
Ubuntuにログインできました。
2.2 サーバ構成確認
ログイン出来たので環境確認です。homeを見るとisuconというユーザが居る様ですね。FAQによればコンテンツは/home/isucon/ 配下にあるそうですし、ここはユーザをisuconに切り替えてフォルダの中を少し見て見ましょう。
$ ls /home
isucon isucon-admin ubuntu
$ sudo -i -u isucon
$ pwd
/home/isucon
$ ls
README.md bench env.sh go local webapp
$ ls bench
Makefile README.md bench data gen go.mod go.sum images key logger main.go model random scenario service
$ ls webapp
NoImage.jpg ec256-public.pem frontend go nodejs perl php public python ruby rust sql
詳しいドキュメントが有るわけでは有りませんが、bench以下にベンチマークアプリとそのソース(go)、webapp以下にウェブアプリケーションとそのソース(go, node, perl, php, python, ruby, rustの何れか)が配置されている様です。
さて、それでは実際のサービスはどんな構成なのでしょうか。もしもサービスが既に起動しているなら、ポートをLISTENしているプロセスを特定するのが早そうです。（重要なサーバアプリはおそらくポートをLITSENしているでしょう。）
$ sudo lsof -P -i | grep -v sshd | grep -v systemd
COMMAND PID USER FD TYPE DEVICE SIZE/OFF NODE NAME
jiaapi-mo 362 isucon 3u IPv6 21400 0t0 TCP *:5000 (LISTEN)
nginx 425 root 6u IPv4 20603 0t0 TCP *:443 (LISTEN)
nginx 429 www-data 6u IPv4 20603 0t0 TCP *:443 (LISTEN)
mysqld 574 mysql 24u IPv4 22719 0t0 TCP localhost:3306 (LISTEN)
mysqld 574 mysql 46u IPv4 49172 0t0 TCP localhost:3306->localhost:42170 (ESTABLISHED)
isucondit 624 isucon 3u IPv6 23060 0t0 TCP *:3000 (LISTEN)
isucondit 624 isucon 8u IPv4 49171 0t0 TCP localhost:42170->localhost:3306 (ESTABLISHED)
Webサーバ(nginx)とRDBMS(mysqld)が動いているのを見つけました。なるほど。残るisuconditionとjiaapi-mockがアプリケーションプロセスでしょう。面白いことに、isuconditionからmysqlの待ち受けポート(3306)にTCP接続を確立済み(ESTABLISHED)の様です。これは多分SQLのConnection poolですね。WebアプリケーションからSQLサーバに常時接続を張って複数のクエリで使い回してるんですね。（ガチ構成だ。まじか。）
次にサービスプロセスの素性をさらに確認してみます。
$ ps -aux | grep -Ei "nginx|mysqld|isucondition|jiaapi"
isucon 362 0.0 0.3 1005080 2980 ? Ssl Jul30 0:00 /usr/local/bin/jiaapi-mock
root 425 0.0 0.0 8592 852 ? Ss Jul30 0:00 nginx: master process /usr/sbin/nginx -g daemon on; master_process on;
www-data 429 0.0 0.4 9768 4844 ? S Jul30 0:00 nginx: worker process
mysql 574 0.0 7.0 1252044 70240 ? Ssl Jul30 0:33 /usr/sbin/mysqld
isucon 624 0.0 0.7 1008480 7804 ? Ssl Jul30 0:01 /home/isucon/webapp/go/isucondition
プロセスがどこから起動されたか判ります。という訳でisuconditionがgoで書かれた主アプリケーションということが判り、nginx～isucondition～mysqldの三層サーバ構成であることが確定しました。教科書通りです。下記構成です。（nginxのmasterがworkerを１個起動中。jiaapi-mockは公式ブログによるとユーザ認証機能のモックだそうです。これは実戦時は事務局が提供するのでチューニング対象外。）
Webサーバが起動していてhttps(443)ポートをLITSENしているということは、ブラウザで接続すればサービス画面が見れそうですね。という訳で、アドレスバーにEC2のアドレスを入力してみると、以下のサービス画面が表示されました。
このサービスの速度を改善していくわけです。
３．ベンチマークとボトルネック調査
3.1 初回ベンチマーク
ここからベンチマークを試してみます。実行権限付きのファイル(/home/isucon/bench/bench)がベンチプログラムで間違いなさそうですが$ ./benchだけでは怒られました。起動パラメタ等は何でしょう。FAQには以下の説明が有りました。
benchの実行方法はイメージ毎に異なります。上記AMI表の対象列のリンク先をご確認ください。
という訳でisucon11-qualifyのgithubの説明を見ながら再度benchをやってみます。少し手直しして下記で動きました。
$ ./bench -all-addresses 127.0.0.1 -target 127.0.0.1:443 -tls -jia-service-url http://127.0.0.1:4999 > /tmp/my-bench.txt
初回スコアは988でした。score: 988(1000 - 12) : pass
ベンチマーク結果（詳細）
21:38:54.003635 ===> PREPARE
21:38:59.828505 score: 0(0 - 0) : Score
21:38:59.828516 deduction: 0 / timeout: 0
21:38:59.828566 ===> LOAD
21:39:02.828482 score: 1000(1000 - 0) : pass
21:39:02.829744 deduction: 0 / timeout: 1
21:39:04.832344 ユーザーは増えませんでした
21:39:05.828979 score: 999(1000 - 1) : pass
21:39:05.828995 deduction: 0 / timeout: 14
21:39:08.830963 score: 997(1000 - 3) : pass
21:39:08.849189 deduction: 0 / timeout: 34
21:39:09.832691 ユーザーは増えませんでした
21:39:11.830260 score: 995(1000 - 5) : pass
21:39:11.878128 deduction: 0 / timeout: 56
21:39:14.840657 score: 993(1000 - 7) : pass
21:39:14.874289 deduction: 0 / timeout: 78
21:39:14.849522 タイムアウト数が多いため、サービスの評判が悪くなりました。以降ユーザーは増加しません
21:39:17.843451 score: 990(1000 - 10) : pass
21:39:17.862477 deduction: 0 / timeout: 100
21:40:47.201561 score: 989(1000 - 11) : pass
21:40:47.209360 deduction: 0 / timeout: 118
21:40:47.356035 score: 988(1000 - 12) : pass
21:40:47.356066 deduction: 0 / timeout: 121
21:40:47.362376 SCORE: 00.StartBenchmark : 1
21:40:47.362385 SCORE: 01.GraphGood : 0
21:40:47.362389 SCORE: 02.GraphNormal : 0
21:40:47.362393 SCORE: 03.GraphBad : 0
21:40:47.362397 SCORE: 04.GraphWorst : 0
21:40:47.362401 SCORE: 05.TodayGraphGood : 0
21:40:47.362405 SCORE: 06.TodayGraphNormal : 0
21:40:47.362409 SCORE: 07.TodayGraphBad : 0
21:40:47.362412 SCORE: 08.TodayGraphWorst : 0
21:40:47.362416 SCORE: 09.ReadInfoCondition : 0
21:40:47.362420 SCORE: 10.ReadWarningCondition : 0
21:40:47.362424 SCORE: 11.ReadCriticalCondition: 0
21:40:47.364808 score: 988(1000 - 12) : pass
21:40:47.364819 deduction: 0 / timeout: 123
3.2 ベンチマーク結果の解釈
サービスが正しく動けば基本スコアが1000貰えるらしいです。そしてユーザを獲得してページビューを取るとスコアが加算されるらしい。つまりスコア988って誰にも何にも使ってもらえず-12のペナルティのみ。（有り体に言って、兎に角動いてる程度のごみサービス...）ベンチマーク詳細を見てもタイムアウト数が多いため、サービスの評判が悪くなりました。以降ユーザーは増加しませんと散々な云われ様です。
3.3 サーバ負荷測定
サーバの状態を解析してみましょう。
まずはUbuntuに入っているツールの確認です。vmstat,top,dstatは試したら使用できました。最低限の測定には問題ありません。このままベンチマークを実行しながら$ dstatを使って負荷を測ってみます。
負荷測定結果（詳細抜粋）
$ dstat
--total-cpu-usage-- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai stl| read writ| recv send| in out | int csw
97 2 0 0 1| 840k 0 | 360B 578B| 0 0 | 424 697
99 0 0 1 0| 856k 120k| 360B 586B| 0 0 | 476 750
99 0 0 1 0| 952k 0 | 360B 570B| 0 0 | 528 892
98 1 0 1 0| 592k 0 | 360B 562B| 0 0 | 469 784
88 3 0 9 0|5024k 0 | 632B 822B| 0 0 |1200 3003
13 11 52 23 0| 17M 7304k| 668B 1470B| 0 0 |2114 6814
3 4 90 3 0| 168k 11M| 704B 944B| 0 0 | 280 887
0 1 99 0 0|8192B 48k| 508B 814B| 0 0 | 152 379
0 0 100 0 0| 0 48k| 500B 806B| 0 0 | 150 359
1 3 96 0 0| 0 0 | 360B 570B| 0 0 | 135 350
41 27 23 8 0| 42M 8880k| 368B 1020B| 0 0 |3757 19k
60 40 0 0 0| 30M 19M| 40B 162B| 0 0 |4126 28k
61 39 0 0 0| 31M 31M| 428B 488B| 0 0 |4888 30k
63 37 0 0 0| 19M 16M| 40B 146B| 0 0 |3714 31k
67 33 0 0 0| 21M 4400k| 132B 192B| 0 0 |2741 29k
63 37 0 0 0| 15M 4592k| 40B 146B| 0 0 |2989 32k
62 38 0 0 0|9024k 30M| 40B 122B| 0 0 |4039 33k
どうもAPIの結果を得る為の内部処理が重すぎる様です。（netのsend/recvが数百Bと小さい割にcpu-usageやdisk read/writeが巨大なのはおかしいですよね。無駄が多そう。）
cpu-usageを見ると割とちゃんとusrにcpuが割当たっていて、waitが高すぎる感じでもないこともあり、これだけではCPU/IOのどこがボトルネックかまでは判らない感じです。またメモリのpagingは発生していなさそうです。メモリが十分かはおいといて今のボトルネックではない。
今回まずは、確認と改善がしやすいというのも有り、あてずっぽうでディスク読み出しが大きい点に焦点をあてて、RDBでINDEX使わずにフルスキャンしてるんじゃないかな～あたりの仮説をたてて確認を続けてみます。
3.4 MySQLテーブル構成の確認
最初にバージョン確認。MraiaDB(10.3.34-MariaDB)です。（MySQL5.7相当）
$ mysql --version
mysql Ver 15.1 Distrib 10.3.34-MariaDB, for debian-linux-gnu (x86_64) using readline 5.2
次にMySQLを操作する為のアカウントを調査します。
少し探してenv.shにuserとpasswordが設定されているのを発見しました。mysqlコマンドでRDBと対話を…
$ mysql -u isucon -p
Enter password:
Welcome to the MariaDB monitor. Commands end with ; or \g.
これで問題無く繋がりました。ここからDBとテーブルの構成を確認します。
MariaDB [isucondition]> show tables;
+------------------------+
| Tables_in_isucondition |
+------------------------+
| isu |
| isu_association_config |
| isu_condition |
| user |
+------------------------+
テーブル構成確認の結果：
・テーブルは４つある。
・ENGINEはInnoDBである。（問題無い）
・Primary Key(index)は各テーブルに一つづつ有る。（この限りでは問題なさそう）
・isuはimageを含む。（少し不穏かも）
テーブルのステータスからデータ量などを確認してみます。
+------------------------+------+-------------+
| Tables_in_isucondition | Rows | Data_length |
+------------------------+------+-------------+
| isu | 67 | 3686400 |
| isu_association_config | 1 | 16384 |
| isu_condition | 47267 | 9977856 |
| user | 13 | 16384 |
+------------------------+------+-------------+
思ったほど大きくはないですね。Rows=47k行（9.9MB程度）
これでdisk/read,wrireが数百MB単位になるのは大きすぎでおかしいので、やはり改善余地は有りそうです。
3.5 MySQLスロークエリ調査
ソースコードから演繹して改善個所を特定するのは効率が悪すぎますので、ベンチマークを実行しながらスロークエリ（遅いクエリ）を検出することにします。（詳しい参考はこちら）まずは、スローログを出力する様に設定を変えます。
$ cd /etc/mysql/mariadb.conf.d
$ sudo vi 50-server.cnf
''' 実行時間が1msを超えるSQLをログ出力する
# Enable the slow query log to see queries with especially long duration
slow_query_log = ON
slow_query_log_file = /var/log/mysql/mariadb-slow.log
long_query_time = 0.001
'''
$ sudo systemctl restart mysql
ベンチマークを実行した後、以下のコマンドでスローログファイルを解析します。
$ mysqldumpslow -s t mariadb-slow.log
解析結果から所要時間上位の２か所の改善候補をピックアップしました。
| 改善候補 | SQLクエリ | 解析 |
|---|---|---|
| １ | SELECT * FROM isu_condition WHERE jia_isu_uuid = 'S' ORDER BY timestamp DESC LIMIT N |
１行取得する為に平均で29K行ほど検索している。0.21sec x 598回=125secと断トツ遅い。判り易く酷い |
| ２ | SELECT * FROM isu_condition WHERE jia_isu_uuid = 'S' ORDER BY timestamp DESC |
194行取得するのに平均で12K行ほど検索している。0.06sec x 231回=13secと候補１ほど酷くはないが、SQLクエリが似ているのでまとめて改善できそう。 |
スローログの解析（詳細）
$ mysqldumpslow -s t mariadb-slow.log
Count: 598 Time=0.21s (125s) Lock=0.00s (0s) Rows_sent=1.0 (598), Rows_examined=29278.3 (17508418), Rows_affected=0.0 (0), isucon[isucon]@localhost
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY `timestamp` DESC LIMIT N
-----> 改善候補(1) : 1行取得する為に平均で29K行ほど検索している。これは酷い。
Count: 4194 Time=0.01s (27s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=0.0 (0), isucon[isucon]@localhost
COMMIT
-----> 書き込み全般のCOMMITの合計なので一旦スルーします。
Count: 5871 Time=0.00s (20s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=0.0 (0), isucon[isucon]@localhost
#
-----> コメントなのでスルーします。
Count: 3023 Time=0.00s (14s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=1.0 (3023), isucon[isucon]@localhost
INSERT INTO `isu_condition` (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`) VALUES ('S', 'S', N, 'S', 'S')
-----> 改善候補(3)： 書き込み。3023クエリで3023行更新。効率は悪く無さそう。一旦スルー。
Count: 231 Time=0.06s (13s) Lock=0.00s (0s) Rows_sent=194.4 (44904), Rows_examined=12602.1 (2911094), Rows_affected=0.0 (0), isucon[isucon]@localhost
SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY timestamp DESC
-----> 改善候補(2)： 194行取得するのに平均で12K行ほど検索している。改善候補(1)とほぼ同じ。LIMITなし。
Count: 201 Time=0.01s (1s) Lock=0.00s (0s) Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=0.0 (0), isucon[isucon]@localhost
ROLLBACK
-----> ロールバック。やけに多い。そんなに競合発生させるべきとは思えないが、ここも一旦スルー。
3.6 スロークエリである原因の調査
クエリが遅い原因特定のためにRDBの実行計画(EXPLAIN)を読みます。（論よりEXPLAINコマンド！）
MariaDB [isucondition]> explain extended SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'dd1f5e2f-ad5a-4a65-ab5c-c4eda9bc49ab' ORDER BY `timestamp` DESC LIMIT 1;
+------+-------------+---------------+------+---------------+------+---------+------+-------+----------+-----------------------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | filtered | Extra |
+------+-------------+---------------+------+---------------+------+---------+------+-------+----------+-----------------------------+
| 1 | SIMPLE | isu_condition | ALL | NULL | NULL | NULL | NULL | 40169 | 100.00 | Using where; Using filesort |
+------+-------------+---------------+------+---------------+------+---------+------+-------+----------+-----------------------------+
改善候補（１）の実行計画を読むと遅い理由が概ね判ります。まず行の検索がテーブルのフルスキャンになっていますね(type=ALL)。その結果rows=最大4万行を検索してヒット行を'timestamp'順にソートしLIMIT=1で最終的に1行を返しています。これは使えそうなINDEX候補がない（possible_keys=NULL）ためで、INDEXの追加で改善できそうです。改善候補（１）と（２）のクエリの内容をみると、jia_isu_uuidとtimestampの複合INDEXを導入するのが有効そうです。
４．コード改変と再ベンチマーク
4.1 コード改変準備
githubにコードリポジトリを作ってコード改変の準備をします。（この準備はチューニング的にはオプショナルな作業ですが、とても重要です。 チームで作業していると改変がコンフリクトしますし、効果や副作用が思わしくない時はロールバックも要るので、構成管理しましょう。それだけならgitでも良いのですが、インスタンスを壊してしまって破棄したり、負荷分散先のインスタンスにコードを展開したり、PullRequestをレビューしてスムーズに適用するなど、助かりそうなシーンの多いgithubを使います。）
まず、/home/isucon/webappで$ git initしてwebapp以下をgitに登録し、次いでgitのリモートリポジトリを自分たちのgithubに設定しました。
4.2 コード改変（INDEX追加）
それではINDEXを追加していきます。テーブルの構造を定義しているスキーマ(DDL)の場所はどこでしょうか。普通は各ソースに直接書かず、分離して定義してありますよね。/isucon/webapp/sqlフォルダ下を探すと下表の初期設定ファイルが有り、DDL定義も記載されていました。またアプリのイニシャライズ時はinit.shでテーブルを再構築する様です。
| File | 動作 |
|---|---|
| init.sh | 起動中のMySQLに接続し0_Schema.sqlと1_InitData.sqlを実行する |
| 0_Schema.sql | 全テーブルを一旦DROPしスキーマ定義に従って新たにテーブル作成 |
| 1_InitData.sql | テーブルに初期データを投入（バイナリ画像含む） |
という訳で0_Schema.sqlを修正してinit.shを実行する事にしましょう。修正内容は以下です。
@@ -26,6 +26,8 @@ CREATE TABLE `isu_condition` (
PRIMARY KEY(`id`)
) ENGINE=InnoDB DEFAULT CHARACTER SET=utf8mb4;
+alter table isu_condition add index isu_index (`jia_isu_uuid`, `timestamp`);
+
CREATE TABLE `user` (
`jia_user_id` VARCHAR(255) PRIMARY KEY,
`created_at` DATETIME(6) DEFAULT CURRENT_TIMESTAMP(6)
修正は(`jia_isu_uuid`, `timestamp`)"の複合indexをisu_conditionテーブルに追加しているだけですね。
修正内容はブランチ(sql-index)を作ってgithubにcommit,pushしておきます。（後で効果が良好ならプルリクしましょう。）
$ git branch sql-index
$ git checkout sql-index
$ git add 0_Schma.sql
$ git commit -m 'fix index in 0_Schema.sql'
$ git push -u origin sql-index
init.shの実行後、再度MySQLに接続して、実行計画(EXPLAIN)が想定通りに変化したか確認します。
MariaDB [isucondition]> explain extended SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'ccbc28a9-13c9-4ea5-b4fc-937b140ba8b3' ORDER BY timestamp DESC;
+------+-------------+---------------+------+---------------+-----------+---------+-------+------+----------+-------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | filtered | Extra |
+------+-------------+---------------+------+---------------+-----------+---------+-------+------+----------+-------------+
| 1 | SIMPLE | isu_condition | ref | isu_index | isu_index | 144 | const | 1 | 100.00 | Using where |
+------+-------------+---------------+------+---------------+-----------+---------+-------+------+----------+-------------+
possible_keysからisu_indexを選んでkeyに使い、type=ref(効率的なIndex参照)で検索する計画になった様です。結果として検索するrowsが4万行→1行に減りました。このまま、ベンチマークを実行しながらdstatで確認します。すると、どうやら巨大なdisk readは解消された様です。
改善後の負荷測定結果（詳細抜粋）
-total-cpu-usage-- -dsk/total- -net/total- ---paging-- ---system--
usr sys idl wai stl| read writ| recv send| in out | int csw
67 33 0 0 0| 152k 4640k|1284B 1204B| 0 0 |2781 28k
63 37 0 0 0| 608k 33M|1160B 2504B| 0 0 |3718 28k
69 31 0 0 0| 432k 4616k|1404B 76k| 0 0 |2612 26k
63 37 0 0 0| 392k 29M| 704B 1014B| 0 0 |3364 26k
68 32 0 0 0|1224k 4984k| 756B 854B| 0 0 |2250 25k
63 37 0 0 0| 512k 17M| 40B 146B| 0 0 |2705 27k
65 35 0 0 0| 824k 4616k| 132B 184B| 0 0 |3476 29k
60 40 0 0 0| 232k 5280k| 40B 138B| 0 0 |3093 30k
65 35 0 0 0| 72k 4208k| 40B 138B| 0 0 |3437 30k
66 34 0 0 0| 0 4760k| 40B 122B| 0 0 |3542 32k
58 42 0 0 0|7928k 28M| 40B 138B| 0 0 |3941 31k
67 33 0 0 0|1896k 23M| 40B 138B| 0 0 |3084 28k
65 35 0 0 0|3632k 4392k| 40B 130B| 0 0 |3003 28k
64 36 0 0 0|3128k 4352k| 80B 176B| 0 0 |2819 28k
66 34 0 0 0|2872k 39M|1568B 1986B| 0 0 |4389 28k
63 37 0 0 0|2384k 4880k| 240B 366B| 0 0 |3079 28k
68 32 0 0 0|1304k 4632k| 460B 1052B| 0 0 |3256 26k
62 37 0 1 0|1512k 35M| 180B 252B| 0 0 |4882 29k
72 28 0 0 0|1384k 5184k| 712B 830B| 0 0 |3831 27k
69 31 0 0 0| 520k 5880k|1396B 1302B| 0 0 |3162 26k
66 34 0 0 0| 480k 5680k| 608B 586B| 0 0 |4019 30k
70 30 0 0 0| 720k 19M| 140B 244B| 0 0 |5603 33k
4.3 再ベンチマーク
ついで再ベンチマークをかけてスコアアップしたかを確認します。負荷が減ったといっても、思わぬ副作用が出てユーザ操作が続けられなくなっているだけかもしれません。理屈を現実で裏付けてくれるベンチマークをかけましょう。INDEXを追加した時にもベンチマークをかけましたが、作業に使っているt2.microインスタンスでは非力すぎてスコアの変化が確認できませんでした。ここは本番環境に近いc5.largeあたりにスケールアップします。（AWSでしたらインスタンスのリブート程度の手間でスケールアップが可能です。）
./bench -all-addresses 127.0.0.1 -target 127.0.0.1:443 -tls -jia-service-url http://127.0.0.1:4999 > /tmp/2022-09-10b-bench.txt
18:03:58.291849 score: 13756(13758 - 2) : pass
改めて得られたスコアは13756 でした（１行の追加で初回の988から10倍以上アップとお得）。c5.large同士での新旧コードの直接比較がまだですが、感触として副作用では無く、きちんと性能アップしていそうです。（※測定しましたら改訂します。）
良い結果はプルリクして仲間に見てもらってmainにマージです。
以後mainをcheckoutすれば性能改善した状態で作業を続けられます。
５．おわりに
ISUCON12に触発されて始めたのですが、１サイクル回すのが精一杯という状況で、まだ漸くはじめの一歩です。
始めてみると、コマンドやツール・アジャイルなチーム連携など、経験も練度も圧倒的な不足を痛感しています。（試しにモブプロをやってみたら、どんだけ共同作業のコツを掴んでないんだとか。皆リモートですし、ツールを上手く使って連携したい。）
そういう訳でストレッチ・チャレンジ継続の所存で有ります。みなさま、良いクリスマスを！
参考資料