ISUCON攻略はじめの一歩

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の秘密鍵にはインスタンス作成時に登録したものを指定。）

EC2接続

$ 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

ベンチマーク結果（詳細）

/tmp/my-bench.txt

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のバージョン

$ 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への接続

$ 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を含む。（少し不穏かも）
テーブルのステータスからデータ量などを確認してみます。

show table status;（結果から列抜粋）

+------------------------+------+-------------+
| 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を実行する事にしましょう。修正内容は以下です。

/webapp/sql/0_Schema.sql

@@ -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は解消された様です。

改善後の負荷測定結果（詳細抜粋）

dstat

-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でしたらインスタンスのリブート程度の手間でスケールアップが可能です。）

c5.large instance

./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に触発されて始めたのですが、１サイクル回すのが精一杯という状況で、まだ漸くはじめの一歩です。
始めてみると、コマンドやツール・アジャイルなチーム連携など、経験も練度も圧倒的な不足を痛感しています。（試しにモブプロをやってみたら、どんだけ共同作業のコツを掴んでないんだとか。皆リモートですし、ツールを上手く使って連携したい。）
そういう訳でストレッチ・チャレンジ継続の所存で有ります。みなさま、良いクリスマスを！

参考資料