関連記事
【ISUCON11予選】ISUCON に入門してみる（①セットアップ）
【ISUCON11予選】ISUCON に入門してみる（②計測ツールの導入）
【ISUCON11予選】ISUCON に入門してみる（③1296→15434）
【ISUCON11予選】ISUCON に入門してみる（④15434→???）

これは何？

「ISUCONに入門してみる」シリーズでは、筆者が ISUCON11 を解く際にやったことを備忘録的に時系列順に書き並べていきます。本記事（③1296→15434）では、スコアを1296から15434まで上げた過程でやったことを、以下の順で説明していきます。

DBインデックス貼り（→11146）
バルクインサート（→12852）
SQLクエリにLIMITを付ける（→14080）
テーブルの変更（→13494）
nginx のパラメーターチューニング（→15434）

DBインデックス貼り（→11146）

slow-query-log の出力を見ると、一番上のクエリが異常に遅いことがわかり、インデックスを貼っていない等の予想ができます。

Count: 4973  Time=0.17s (842s)  Lock=0.00s (0s)  Rows_sent=1.0 (4948), Rows_examined=41311.2 (205440672), Rows_affected=0.0 (0), isucon[isucon]@localhost
  SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY `timestamp` DESC LIMIT N

Count: 6714  Time=0.04s (282s)  Lock=0.00s (0s)  Rows_sent=450.6 (3025524), Rows_examined=10085.0 (67710459), Rows_affected=0.0 (0), isucon[isucon]@localhost
  SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY timestamp DESC

Count: 21267  Time=0.01s (142s)  Lock=0.00s (0s)  Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=0.0 (0), isucon[isucon]@localhost
  COMMIT

 〜以下省略〜

実際、EXPLAINしてみると、以下のようにkeyがNULLでインデックスが貼られていないので、jia_isu_uuidにインデックスを貼りました。

MariaDB [isucondition]> EXPLAIN SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY `timestamp` DESC LIMIT 1;
+------+-------------+---------------+------+---------------+------+---------+------+-------+-----------------------------+
| id   | select_type | table         | type | possible_keys | key  | key_len | ref  | rows  | Extra                       |
+------+-------------+---------------+------+---------------+------+---------+------+-------+-----------------------------+
|    1 | SIMPLE      | isu_condition | ALL  | NULL          | NULL | NULL    | NULL | 46488 | Using where; Using filesort |
+------+-------------+---------------+------+---------------+------+---------+------+-------+-----------------------------+

バルクインサート（→12852）

nginx のログ出力を alp で見てみると、POST /api/condition/[-a-z0-9]+が支配的で、COUNT 数も異常に多いので注目してみると、バルクインサートせずに1つずつforループの中でインサートしていることがわかったので、修正しました。

+--------+--------+------------------------------+-------+-------+----------+-------+-------+
| COUNT  | METHOD |             URI              |  MIN  |  MAX  |   SUM    |  AVG  |  P99  |
+--------+--------+------------------------------+-------+-------+----------+-------+-------+
| 140897 | POST   | /api/condition/[-a-z0-9]+    | 0.004 | 0.192 | 1561.895 | 0.011 | 0.104 |
| 752    | GET    | /api/isu                     | 0.400 | 3.004 | 392.130  | 0.521 | 1.016 |
| 2298   | GET    | /api/condition/[-a-z0-9]+    | 0.004 | 1.012 | 264.785  | 0.115 | 0.544 |
+--------+--------+------------------------------+-------+-------+----------+-------+-------+
　〜以下省略〜

SQLクエリにLIMITを付ける（→14080）

nginx のログを alp で確認すると、GET /api/trendの一回あたりの平均が0.920と群を抜いて大きく、改善の余地がないか注目すると、このエンドポイントに対応する処理ではデータは一個しか返さないにも関わらず SQL クエリの中でLIMIT 1が指定されていないことがわかるので、修正しました。

+--------+--------+--------------------------+-------+-------+----------+-------+-------+
| COUNT  | METHOD |            URI           |  MIN  |  MAX  |   SUM    |  AVG  |  P99  |
+--------+--------+--------------------------+-------+-------+----------+-------+-------+
| 373218 | POST   | /api/condition/[-a-z0-9]+| 0.004 | 0.176 | 3629.159 | 0.010 | 0.088 |
| 13253  | GET    | /api/condition/[-a-z0-9]+| 0.004 | 0.512 | 1061.814 | 0.080 | 0.248 |
| 15812  | GET    | /api/isu/.+/icon         | 0.028 | 0.420 | 700.199  | 0.044 | 0.164 |
| 535    | GET    | /api/trend               | 0.016 | 1.028 | 492.263  | 0.920 | 1.020 |
+--------+--------+--------------------------+-------+-------+----------+-------+-------+
　〜以下省略〜

テーブルの変更（→13494）

インデックスを貼ってもなお遅いGET /api/conditionについて、もう少し探ってみると、isu_conditionsテーブルの設計自体がかなり良くないことがわかります。具体的には、isu_conditionsテーブルは以下のような構成になっているのですが、

CREATE TABLE `isu_condition` (
  `id` bigint AUTO_INCREMENT,
  `jia_isu_uuid` CHAR(36) NOT NULL,
  `timestamp` DATETIME NOT NULL,
  `is_sitting` TINYINT(1) NOT NULL,
  `condition` VARCHAR(255) NOT NULL,
  `message` VARCHAR(255) NOT NULL,
  `created_at` DATETIME(6) DEFAULT CURRENT_TIMESTAMP(6),
  PRIMARY KEY(`id`)
) ENGINE=InnoDB DEFAULT CHARACTER SET=utf8mb4;

この中のconditionの中身が"is_dirty=true,is_overweight=true,is_broken=false"というように、is_dirty, is_overweight, is_broken の真偽値をカンマ区切りの文字列で持たれています。このアプリケーションでは、

3つともtrue : info
true が 1 or 2 : warning
3つともfalse : critical

と定義されていますが、例えば「criticalの条件に一致」するカラムを「5つ」取得する、という場合には、

まず最初に isu_conditions から全てのデータを取ってくる
次にアプリケーションのコード側でconditionの文字列からcriticalの条件に一致するかを判定し、一致するものが5つ見つかったらクライアントに返す

という処理になっており、最初の処理でLIMIT 5を付けられず、処理全体として遅くなってしまいます。

解決策

levelというカラム（"info" or "warning" or "critical"）を追加し、WHERE句で条件付けをできるようにテーブルを変更し、さらにLIMITをつけるようにしました。

結果・原因

期待に反してスコアが下がる結果となりました。原因を考察するために、スコアの計算の仕方の確認と、ログの確認を行います。

（原因の考察について確信がないので、ご助言等お待ちしております）

スコアの計算の仕方

今回いじった部分と関係があるところに関しては、以下の部分が該当します。

言い換えれば、

POST /api/conditionを100%処理して、最新の情報をきちんとDBに反映する
GET /api/conditionを100%処理して、得点を入れる

ができれば完璧ということになります。

ログの確認

nginx のログを alp で見てみると、以下のように、GETの2XXは約3倍ほどになっているのですが、POSTの4XXが40倍ほどに膨れ上がっていることがわかり、コンディションの更新ができていないために、せっかくデータを取得できても得点が入らないのではないかと考えられます。実際カラムを追加しているので、POSTが遅くなりタイムアウトが増える現象は理解できると思います。

Before

+--------+--------+-----+--------+-----+-----+-----+------------------------------+-------+-------+----------+-------+-------+
| COUNT  | METHOD | 1XX |  2XX   | 3XX | 4XX | 5XX |             URI              |  MIN  |  MAX  |   SUM    |  AVG  |  P99  |
+--------+--------+-----+--------+-----+-----+-----+------------------------------+-------+-------+----------+-------+-------+
| 150249 | POST   | 0   | 149695 | 0   | 554 | 0   | /api/condition/[-a-z0-9]+    | 0.004 | 0.132 | 1191.522 | 0.008 | 0.076 |
| 5620   | GET    | 0   | 4915   | 0   | 705 | 0   | /api/condition/[-a-z0-9]+    | 0.008 | 0.324 | 416.280  | 0.074 | 0.220 |
+--------+--------+-----+--------+-----+-----+-----+------------------------------+-------+-------+----------+-------+-------+

After

+--------+--------+-----+--------+-----+-------+-----+------------------------------+-------+-------+----------+-------+-------+
| COUNT  | METHOD | 1XX |  2XX   | 3XX |  4XX  | 5XX |             URI              |  MIN  |  MAX  |   SUM    |  AVG  |  P99  |
+--------+--------+-----+--------+-----+-------+-----+------------------------------+-------+-------+----------+-------+-------+
| 520954 | POST   | 0   | 500905 | 0   | 20049 | 0   | /api/condition/[-a-z0-9]+    | 0.020 | 0.272 | 6255.801 | 0.012 | 0.104 |
| 15938  | GET    | 0   | 13786  | 0   | 2152  | 0   | /api/condition/[-a-z0-9]+    | 0.004 | 1.012 | 1464.524 | 0.092 | 0.400 |
+--------+--------+-----+--------+-----+-------+-----+------------------------------+-------+-------+----------+-------+-------+

どうする？

この瞬間だけを考えたらコミットを戻した方が得点が上がるのですが、POSTが改善されれば爆発的に得点は上がると思う（つまり得点の「ポテンシャル」的なものは上がっていると思う）ので、一旦このコミットは残してみます。

nginx のパラメーターチューニング（→15434）

（細かい設定は最後の最後にやった方が良さそうなので、ここでは「ちょっと変えてみた」くらいのノリで）

nginx のパラメータをチューニングして、結果がどうなるかを見てみました。具体的には、worker_connections の値を1024から8192に変更してみました。

nginx のログを alp で見てみると、先ほどよりも改善されていることが確認できました。

+--------+--------+-----+--------+-----+------+-----+------------------------------+-------+-------+----------+-------+-------+
| COUNT  | METHOD | 1XX |  2XX   | 3XX | 4XX  | 5XX |             URI              |  MIN  |  MAX  |   SUM    |  AVG  |  P99  |
+--------+--------+-----+--------+-----+------+-----+------------------------------+-------+-------+----------+-------+-------+
| 826287 | POST   | 0   | 822595 | 0   | 3692 | 0   | /api/condition/[-a-z0-9]+    | 0.004 | 0.160 | 5392.084 | 0.007 | 0.076 |
| 31485  | GET    | 0   | 27381  | 0   | 4104 | 0   | /api/condition/[-a-z0-9]+    | 0.004 | 0.660 | 2294.319 | 0.073 | 0.248 |
+--------+--------+-----+--------+-----+------+-----+------------------------------+-------+-------+----------+-------+-------+

参考

[1] https://isucon.net/archives/56082639.html