「ISUCON11 予選問題の解説と講評」を読んで試してみた

この記事は何か?

ISUCON12予選に参加しました。そのことは別の記事で書きますが、

ISUCON12予選参加時に参考にしたのは自分のブログでした。

なので、去年やってブログに書いていなかった「"ISUCON11 予選問題の解説と講評"を読んで試したこと」を書きます。

たぶん1年後の自分が参考にすると思います。

ISUCON11 予選問題の解説と講評

ISUCON11 予選問題の解説と講評
https://isucon.net/archives/56044867.html

ISUCON11 予選問題実践攻略法
https://isucon.net/archives/56082639.html

上記の2サイトに書いてあることをやりました。

実行環境

AMIがまだなかった(?)ため、matsuuさんのVagrantfileを利用させていただいた気がします。いつもありがとうございます。

vagrant-isucon/isucon11-qualifier-standalone/Vagrantfile
https://github.com/matsuu/vagrant-isucon/blob/master/isucon11-qualifier-standalone/Vagrantfile

コミットログとスコア

初期スコア (1,402)
alp設定 (1,491)
mysqldumpslow設定 (1,458)
pprof設定 (1,386)
プライマリキー変更 (17,340)
バルクインサート (18,628)
LIMIT 1 追加 (23,848)
レベルカラム追加 (27,000)
グラフデータ条件追加 (28,630)
ログ停止 (32,770)

1 初期スコア (1,402)

https://github.com/zono/isucon11-qualify/issues/1#issue-1007352307

PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
190249 mysql     20   0 1713420 126116  11744 S  73.4   3.3   1:26.76 mysqld
212863 isucon    20   0 1372068 144984  11548 S  43.9   3.8   0:16.23 bench
212664 isucon    20   0 1526580  29908   7632 S  40.5   0.8   0:27.59 isucondition
   162 root      19  -1  303276 123968 122668 S  13.3   3.3   0:07.85 systemd-journal
188178 www-data  20   0   16616   9200   4116 S  12.6   0.2   0:09.35 nginx
188179 www-data  20   0   14728   7276   4116 S   7.0   0.2   0:03.13 nginx
   520 syslog    20   0  224500   4860   3416 S   5.6   0.1   0:03.58 rsyslogd

mysqld、対象アプリ(isucondition)、nginxがCPUを使っています。またbenchも同じサーバーで動かしていますね。

2 alp設定 (1,491)

https://github.com/zono/isucon11-qualify/issues/1#issuecomment-927283219

+-------+--------+------------------------------+-------+-------+---------+-------+-------+
| COUNT | METHOD |             URI              |  MIN  |  MAX  |   SUM   |  AVG  |  P99  |
+-------+--------+------------------------------+-------+-------+---------+-------+-------+
| 69454 | POST   | /api/condition/[-a-z0-9]+    | 0.020 | 0.232 | 706.684 | 0.010 | 0.104 |
|   403 | GET    | /api/isu                     | 0.004 | 3.000 | 342.580 | 0.850 | 1.012 |
|   530 | GET    | /api/isu/.+/icon             | 0.004 | 1.812 |  93.848 | 0.177 | 1.008 |
|   156 | GET    | /api/condition/[-a-z0-9]+    | 1.000 | 1.004 |  28.992 | 0.186 | 1.004 |
|    35 | GET    | /api/trend                   | 0.028 | 1.020 |  27.828 | 0.795 | 1.020 |
|   126 | POST   | /api/auth                    | 0.004 | 3.004 |  25.176 | 0.200 | 3.000 |
|    80 | GET    | /api/isu/.+/graph            | 1.000 | 1.004 |  14.092 | 0.176 | 1.004 |
|   130 | GET    | /api/isu/[-a-z0-9]+          | 3.004 | 3.004 |  13.328 | 0.103 | 1.000 |
|    55 | POST   | /api/isu                     | 0.004 | 0.116 |   4.208 | 0.077 | 0.116 |
|    39 | GET    | /api/user/me                 | 0.000 | 0.632 |   0.920 | 0.024 | 0.632 |
|    23 | POST   | /api/signout                 | 0.004 | 0.088 |   0.312 | 0.014 | 0.088 |
|    81 | GET    | /assets/favicon.d0f5f504.svg | 0.004 | 0.020 |   0.256 | 0.003 | 0.020 |
|    81 | GET    | /assets/vendor.ee7444dd.js   | 0.004 | 0.020 |   0.240 | 0.003 | 0.020 |
|    81 | GET    | /assets/index.23dac98b.js    | 0.004 | 0.012 |   0.196 | 0.002 | 0.012 |
|     1 | POST   | /initialize                  | 0.164 | 0.164 |   0.164 | 0.164 | 0.164 |
|    81 | GET    | /assets/index.144d8ca8.css   | 0.004 | 0.012 |   0.148 | 0.002 | 0.012 |
|    48 | GET    | /                            | 0.004 | 0.012 |   0.124 | 0.003 | 0.012 |
|    81 | GET    | /assets/logo_white.svg       | 0.000 | 0.008 |   0.104 | 0.001 | 0.008 |
|    37 | GET    | /assets/logo_orange.svg      | 0.000 | 0.008 |   0.096 | 0.003 | 0.008 |
|    21 | GET    | /?jwt=                       | 0.000 | 0.012 |   0.056 | 0.003 | 0.012 |
|    30 | GET    | /isu/........-....-.+        | 0.000 | 0.004 |   0.004 | 0.000 | 0.004 |
|     3 | GET    | /register                    | 0.000 | 0.004 |   0.004 | 0.001 | 0.004 |
+-------+--------+------------------------------+-------+-------+---------+

書き込みが多いことが分かります。解説にも以下の記載があります。

例年と違う要素として、予選では珍しい大量の書き込み処理と、書き込まれた分だけ重くなる表示処理をいかにパフォーマンスチューニングするかという要素も問題に取り入れました。

3 mysqldumpslow設定 (1,458)

https://github.com/zono/isucon11-qualify/issues/1#issuecomment-927284684

Count: 2504  Time=0.16s (405s)  Lock=0.00s (0s)  Rows_sent=1.0 (2483), Rows_examined=40767.5 (102081883), Rows_affected=0.0 (0), isucon[isucon]@localhost
  SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY `timestamp` DESC LIMIT N

Count: 1721  Time=0.08s (129s)  Lock=0.00s (0s)  Rows_sent=246.2 (423744), Rows_examined=18328.1 (31542676), Rows_affected=0.0 (0), isucon[isucon]@localhost
  SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY timestamp DESC

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

Count: 4016  Time=0.00s (11s)  Lock=0.00s (0s)  Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=0.0 (0), isucon[isucon]@localhost
  #

Count: 2304  Time=0.00s (10s)  Lock=0.00s (0s)  Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=1.0 (2304), isucon[isucon]@localhost
  INSERT INTO `isu_condition`   (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`) VALUES ('S', 'S', N, 'S', 'S')

Count: 102  Time=0.04s (4s)  Lock=0.00s (0s)  Rows_sent=91.0 (9282), Rows_examined=7201.6 (734561), Rows_affected=0.0 (0), isucon[isucon]@localhost
  SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S'  AND `timestamp` < 'S'    ORDER BY `timestamp` DESC

Count: 29  Time=0.04s (1s)  Lock=0.00s (0s)  Rows_sent=142.6 (4135), Rows_examined=7799.1 (226174), Rows_affected=0.0 (0), isucon[isucon]@localhost
  SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY `timestamp` ASC

合計405秒かかっているクエリーがあります。

4 pprof設定 (1,386)

https://github.com/zono/isucon11-qualify/issues/1#issuecomment-927287786

1109行目で1.98秒かかっています。pprof分かりやすいです。(ISUCON12予選では存在を忘れてて使いませんでした)

5 プライマリキー変更 (17,340)

https://github.com/zono/isucon11-qualify/issues/1#issuecomment-927289590

- PRIMARY KEY(`id`)
+ PRIMARY KEY(`jia_isu_uuid`, `timestamp`)

// 変更前
Count: 1877  Time=0.08s (144s)  Lock=0.00s (0s)  Rows_sent=251.8 (472671), Rows_examined=18193.5 (34149146), Rows_affected=0.0 (0), isucon[isucon]@localhost
  SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY timestamp DESC

// 変更後
Count: 4768  Time=0.00s (22s)  Lock=0.00s (0s)  Rows_sent=538.2 (2566154), Rows_examined=538.2 (2566142), Rows_affected=0.0 (0), isucon[isucon]@localhost
  SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY timestamp DESC

この発想はありませんでした。余分なインデックス作成が無くなるので良いです。

6 バルクインサート (18,628)

https://github.com/zono/isucon11-qualify/issues/1#issuecomment-927294136

var rows []IsuCondition

rows = append(rows, IsuCondition{
        JIAIsuUUID: jiaIsuUUID,
        Timestamp:  timestamp,
        IsSitting:  cond.IsSitting,
        Condition:  cond.Condition,
        Message:    cond.Message,
})

_, err = tx.NamedExec(
        "INSERT INTO `isu_condition`"+
                "       (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`)"+
                "       VALUES (:jia_isu_uuid, :timestamp, :is_sitting, :condition, :message)",
        rows)

// 変更前
Count: 1064  Time=0.00s (3s)  Lock=0.00s (0s)  Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=1.0 (1064), isucon[isucon]@localhost
  INSERT INTO `isu_condition`   (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`) VALUES ('S', 'S', N, 'S', 'S')

// 変更後
Count: 255  Time=0.00s (0s)  Lock=0.00s (0s)  Rows_sent=0.0 (0), Rows_examined=0.0 (0), Rows_affected=10.0 (2550), isucon[isucon]@localhost
  INSERT INTO `isu_condition`       (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`)       VALUES ('S', 'S', N, 'S', 'S'),('S', 'S', N, 'S', 'S'),('S', 'S', N, 'S', 'S'),('S', 'S', N, 'S', 'S'),('S', 'S', N, 'S', 'S'),('S', 'S', N, 'S', 'S'),('S', 'S', N, 'S', 'S'),('S', 'S', N, 'S', 'S'),('S', 'S', N, 'S', 'S'),('S', 'S', N, 'S', 'S')

7 LIMIT 1 追加 (23,848)

https://github.com/zono/isucon11-qualify/issues/1#issuecomment-927302335

- "SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY timestamp DESC",
+ "SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY timestamp DESC LIMIT 1",

// 変更前
Count: 4862  Time=0.00s (20s)  Lock=0.00s (0s)  Rows_sent=637.5 (3099623), Rows_examined=637.5 (3099537), Rows_affected=0.0 (0), isucon[isucon]@localhost
  SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY timestamp DESC

// 変更後
Count: 1378  Time=0.00s (4s)  Lock=0.00s (0s)  Rows_sent=1.0 (1357), Rows_examined=1.0 (1353), Rows_affected=0.0 (0), isucon[isucon]@localhost
  SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = 'S' ORDER BY timestamp DESC LIMIT N

8 レベルカラム追加 (27,000)

https://github.com/zono/isucon11-qualify/issues/1#issuecomment-927305929

ALTER TABLE `isu_condition` ADD `level` VARCHAR(8) NOT NULL DEFAULT "warning";
UPDATE `isu_condition` SET `level`="info" WHERE `condition`="is_dirty=false,is_overweight=false,is_broken=false";
UPDATE `isu_condition` SET `level`="critical" WHERE `condition`="is_dirty=true,is_overweight=true,is_broken=true";

高得点を狙うならデータ構造の変更は必ず発生する　と思ってます。(またはISUCON12予選のSQLiteからMySQLヘの変更のようにDB自体を変更することも)

9 グラフデータ条件追加 (28,630)

https://github.com/zono/isucon11-qualify/issues/1#issuecomment-927307267

- rows, err := tx.Queryx("SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY `timestamp` ASC", jiaIsuUUID)
+ rows, err := tx.Queryx("SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ?"+
+          " AND ? <= timestamp AND timestamp < ?"+
+          " ORDER BY `timestamp` ASC", jiaIsuUUID, graphDate, graphDate.Add(24*time.Hour))

これは仕様理解が必要で、ISUCON11予選は仕様理解が難しかったです。前日は仕事を休む方がいいです。(ISUCON12予選は休んだけど遊びに行きました)

10 ログ停止 (32,770)

-        c.Logger().Warnf("drop post isu condition request")

これも気づきませんでした。詰めが甘いです。

まとめ(1年前に思ったこと)

pprof便利
アプリ仕様理解するの難しい
benchのソースコード理解したい

補足 Makefile

https://github.com/zono/isucon11-qualify/blob/f9c424a0beafc719c4b4b67600c135d26f5ee532/Makefile

例: alp結果表示
$ make alp

1年間の自分は便利なツールを用意してくれたのに、ISUCON12予選では気づきませんでした。(それでは勝てません)

2022/7/30に思うこと

成長が足りません。がんばるます。(2022年にはやっている言葉です to 来年の僕)