Zenn
💪

ローカル上に構築したisucon11予選問題で2万点（初期スコアの約4倍）を超えるまでチューニングしてみる

2022/07/10に公開
Ruby
ISUCON
ptquerydigest
alp
tech

[M1Mac]isucon11予選問題の環境をローカルに構築+必要最低限のツールを導入しチューニング作業を開始できる状態まで持っていく

環境構築編は上記です。

ローカル環境にisucon11予選問題を構築できたので、少しチューニングの練習もしてみたいと思います。今回は自力で解くのではなく、

上記を参考に解説を見ながらの状態で取り組んでいきます。

ただ、学習効果を高めるために、単に上記をなぞるのではなく、極力計測を行い「なぜその点に注目したのか？」という腹落ちを得ることを意識しながら進めたいと思います。

環境

  • M1 Macbook Air
  • Ubuntuインスタンスはメモリ4GBに設定

初期benchを取る（スコア5416）

まず初期状態（厳密にはツールを入れたりしてしまいましたが）でbenchを実行します。

ubuntu
./bench -all-addresses 127.0.0.11 -target 127.0.0.11:443 -tls -jia-service-url http://127.0.0.1:4999

bench中のアプリケーションログを確認したい場合は別ターミナルで下記コマンドを叩きます。

ubuntu
journalctl -f -xe -u isucondition.ruby.service

スコアは以下でした。

ubuntu
14:57:50.995556 score: 5416(5416 - 0) : pass

各所の参戦記ブログを読んだ感じでは初期スコアは2000〜3000の印象なので、5416はやや高い気はします。厳密にやるのであれば本番同等スペックのAWS EC2インスタンスなど用意した方が良さそうです。

本記事ではこのまま進めたいと思います。

諸々を再起動/クリア+benchするスクリプトを用意

シェルスクリプト作成

コードを変更してbenchを取り直す際にやることが多いので、下記のようなシェルスクリプトを作成し、処理をまとめました。

ubuntu
cd ~/bench
touch my-bench.sh
chmod +x my-bench.sh

ファイルの内容は以下になります。

/home/isucon/bench/my-bench.sh
#!/bin/bash

# サービス再起動
sudo systemctl restart nginx
sudo systemctl restart mysqld
sudo systemctl restart isucondition.ruby.service

# ログをクリア
sudo truncate /var/lib/mysql/my-slow.log --size 0
sudo truncate /var/log/nginx/access.log --size 0

# bench
./bench -all-addresses 127.0.0.11 -target 127.0.0.11:443 -tls -jia-service-url http://127.0.0.1:4999 > /tmp/my-bench.txt

# alpログ解析結果を出力
# 素のalp出力
sudo cat /var/log/nginx/access.log | alp ltsv > /tmp/alp.txt
# 正規表現でグルーピングしたalp出力
# 合計降順
sudo cat /var/log/nginx/access.log | alp ltsv -m '/api/condition/.*,/api/isu/.*/graph,/api/isu/.*/icon,/api/isu/.*,/isu/.*/graph,/isu/.*/condition,/isu/.*' --sort sum -r > /tmp/alp-grouped-sum.txt
# 平均降順
sudo cat /var/log/nginx/access.log | alp ltsv -m '/api/condition/.*,/api/isu/.*/graph,/api/isu/.*/icon,/api/isu/.*,/isu/.*/graph,/isu/.*/condition,/isu/.*' --sort avg -r > /tmp/alp-grouped-avg.txt

# スロークエリ解析結果を出力
sudo pt-query-digest /var/lib/mysql/my-slow.log > /tmp/pt-query-digest.txt

使い方

ubuntu
cd ~/bench
./my-bench.sh

チューニング開始

drop probabilityを調節する（スコア11394）

とりあえずdrop probabilityを0.9->0にしてみます。

/home/isucon/webapp/ruby/app.rb
    post '/api/condition/:jia_isu_uuid' do
      # TODO: 一定割合リクエストを落としてしのぐようにしたが、本来は全量さばけるようにすべき
-     drop_probability = 0.9
+     drop_probability = 0

./my-bench を実行しスコアを見ます。

/tmp/my-bench.txt
16:00:45.121200 score: 11394(11396 - 2) : pass

これだけでスコアは上昇しました。ただ、初手これを行って上がるかどうかは環境のスペックにだいぶ左右されそうな気はします。

isu_conditionテーブルにインデックスを貼る（スコア11740）

早速 ./my-bench.sh を実行し、スロークエリログを見ます。

/tmp/pt-query-digest.txt
# Profile
# Rank Query ID                       Response time Calls R/Call V/M   Ite
# ==== ============================== ============= ===== ====== ===== ===
#    1 0x9C6C682008AE0D08F3E2A0049... 59.9978 37.1%  1941 0.0309  0.01 SELECT isu_condition
#    2 0x931A992E852C61FC6D46141A3... 56.3146 34.8%  2828 0.0199  0.01 SELECT isu_condition
#    3 0x8155B89FFD74A9D523D19AC40... 17.3326 10.7%   778 0.0223  0.01 SELECT isu_condition
#    4 0xFFFCA4D67EA0A788813031B8B... 16.7064 10.3%  5115 0.0033  0.00 COMMIT
#    5 0x5F580A12ADA1633C9634298BE...  8.7383  5.4%   258 0.0339  0.01 SELECT isu_condition
# MISC 0xMISC                          2.6468  1.6%   490 0.0054   0.0 <26 ITEMS>

まずは Rank 1 のクエリに注目します。さらに出力内容を追ってみると具体的なクエリは

SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = '485d9ef0-eab4-4a27-adbe-ea17f49a3373' AND `timestamp` < '2021-08-28 08:38:30' ORDER BY `timestamp` DESC

といったものであるようなので、このSelectが速くなるようにインデックスを貼ってみます。

/home/isucon/webapp/sql/0_Schema.sql
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`)
+ PRIMARY KEY(`id`),
+ INDEX `jia_isu_uuid_index` (`jia_isu_uuid`,`timestamp`)
) ENGINE=InnoDB DEFAULT CHARACTER SET=utf8mb4;

そして ./my-bench を実行しスコアを見ると、

/tmp/my-bench.txt
16:14:34.367554 score: 11740(11742 - 2) : pass

思ったほど伸びていないようです。

ただ、pt-query-digestの結果は、

/tmp/pt-query-digest.txt
# Profile
# Rank Query ID                       Response time Calls R/Call V/M   Ite
# ==== ============================== ============= ===== ====== ===== ===
#    1 0xFFFCA4D67EA0A788813031B8B...  7.2662 57.0%  2763 0.0026  0.01 COMMIT
#    2 0x931A992E852C61FC6D46141A3...  3.4482 27.0%  1895 0.0018  0.00 SELECT isu_condition
#    3 0x9C6C682008AE0D08F3E2A0049...  1.1181  8.8%   610 0.0018  0.00 SELECT isu_condition
#    4 0x5F580A12ADA1633C9634298BE...  0.5169  4.1%   262 0.0020  0.00 SELECT isu_condition
# MISC 0xMISC                          0.4025  3.2%   118 0.0034   0.0 <17 ITEMS>

となっており、 Response time ば明らかに短くなっているように見えます。

一旦次に進みます。

POST /api/conditionの改善（スコア13314）

/tmp/alp-grouped-sum.txt
+-------+-----+------+-----+-------+-----+--------+------------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+------------+
| COUNT | 1XX | 2XX  | 3XX |  4XX  | 5XX | METHOD |             URI              |  MIN  |  MAX  |   SUM    |  AVG  |  P90  |  P95  |  P99  | STDDEV | MIN(BODY) | MAX(BODY)  |  SUM(BODY)   | AVG(BODY)  |
+-------+-----+------+-----+-------+-----+--------+------------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+------------+
| 32374 |   0 | 7450 |   0 | 24924 |   0 | POST   | /api/condition/.*            | 0.004 | 0.116 | 3123.523 | 0.096 | 0.104 | 0.104 | 0.108 |  0.012 |     0.000 |     14.000 |      126.000 |      0.004 |
|  2016 |   0 | 1912 |   0 |   104 |   0 | GET    | /api/condition/.*            | 0.016 | 0.908 |  291.053 | 0.144 | 0.192 | 0.428 | 0.832 |  0.138 |     0.000 |   6221.000 |  9825484.000 |   4873.752 |
|  1114 |   0 | 1072 |   0 |    42 |   0 | GET    | /api/isu/.*/icon             | 0.004 | 0.836 |  147.013 | 0.132 | 0.200 | 0.492 | 0.660 |  0.124 |    14.000 | 135228.000 | 28854161.000 |  25901.401 |

alpの解析結果（sum降順）を見ると POST /api/condition.* が目立ちます。

そのため、このエンドポイントのコードに以下のチューニングを加えます。

  • insert処理をループで繰り返すコードになっているのでbulk insertにする
  • count は1件以上あるかどうかの判定ができれば良い変数なのでクエリに LIMIT 1 を付ける
  • 一貫性より速度を優先し、トランザクションを外す
/home/isucon/webapp/ruby/app.rb
-     db_transaction do
-       count = db.xquery('SELECT COUNT(*) AS `cnt` FROM `isu` WHERE `jia_isu_uuid` = ?', jia_isu_uuid).first
+       count = db.xquery('SELECT COUNT(*) AS `cnt` FROM `isu` WHERE `jia_isu_uuid` = ? LIMIT 1', jia_isu_uuid).first
        halt_error 404, 'not found: isu' if count.fetch(:cnt).zero?

+       q = "INSERT INTO `isu_condition` (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`) VALUES "
+       values = []
+       binds = []
        json_params.each do |cond|
          timestamp = Time.at(cond.fetch(:timestamp))
          halt_error 400, 'bad request body' unless valid_condition_format?(cond.fetch(:condition))

-         db.xquery(
-           'INSERT INTO `isu_condition` (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`) VALUES (?, ?, ?, ?, ?)',
-           jia_isu_uuid,
-           timestamp,
-           cond.fetch(:is_sitting),
-           cond.fetch(:condition),
-           cond.fetch(:message),
-         )

+         values << "(?, ?, ?, ?, ?)"
+         binds << jia_isu_uuid
+         binds << timestamp
+         binds << cond.fetch(:is_sitting)
+         binds << cond.fetch(:condition)
+         binds << cond.fetch(:message)
        end
+       db.xquery(q << values.join(','), binds)
-     end

結果、以下のスコアとなりました。

/tmp/my-bench.txt
16:53:51.843345 score: 13314(13316 - 2) : pass

alp解析結果についても

  • COUNTの増加
  • AVGの短縮

という成果を確認できました。

/tmp/alp-grouped-sum.txt
+-------+-----+-------+-----+-------+-----+--------+------------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+------------+
| COUNT | 1XX |  2XX  | 3XX |  4XX  | 5XX | METHOD |             URI              |  MIN  |  MAX  |   SUM    |  AVG  |  P90  |  P95  |  P99  | STDDEV | MIN(BODY) | MAX(BODY)  |  SUM(BODY)   | AVG(BODY)  |
+-------+-----+-------+-----+-------+-----+--------+------------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+------------+
| 34725 |   0 | 16075 |   0 | 18650 |   0 | POST   | /api/condition/.*            | 0.004 | 0.116 | 3023.877 | 0.087 | 0.104 | 0.104 | 0.108 |  0.020 |     0.000 |     14.000 |      112.000 |      0.003 |

GET /api/trend クエリにLIMIT 1を付与 （スコア18352）

今度はalpの解析結果（avg降順）を見ると、

/tmp/alp-grouped-avg.txt
+-------+-----+-------+-----+-------+-----+--------+------------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+------------+
| COUNT | 1XX |  2XX  | 3XX |  4XX  | 5XX | METHOD |             URI              |  MIN  |  MAX  |   SUM    |  AVG  |  P90  |  P95  |  P99  | STDDEV | MIN(BODY) | MAX(BODY)  |  SUM(BODY)   | AVG(BODY)  |
+-------+-----+-------+-----+-------+-----+--------+------------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+------------+
|   162 |   0 |   117 |   0 |    45 |   0 | GET    | /api/trend                   | 0.008 | 1.008 |  130.952 | 0.808 | 1.000 | 1.004 | 1.008 |  0.238 |     0.000 |   4636.000 |   514928.000 |   3178.568 |
|   433 |   0 |   356 |   0 |    77 |   0 | GET    | /api/isu/.*/graph            | 0.040 | 0.864 |   60.752 | 0.140 | 0.212 | 0.248 | 0.648 |  0.097 |     0.000 |   9900.000 |  1429425.000 |   3301.212 |
|  2345 |   0 |  2236 |   0 |   109 |   0 | GET    | /api/condition/.*            | 0.004 | 0.944 |  306.180 | 0.131 | 0.196 | 0.264 | 0.756 |  0.114 |     0.000 |   6281.000 | 11575158.000 |   4936.101 |

GET /api/trend が目立ちます。

このエンドポイントのコードを見ると 'SELECT * FROM isu_conditionWHEREjia_isu_uuid = ? ORDER BY timestamp DESC のクエリを発行している箇所があるのですが、その後の isu_last_condition = conditions.first より最初の1件しか使用しないことがわかるので、クエリに LIMIT 1 を付けて高速化することができます。

/home/isucon/webapp/ruby/app.rb
        isu_list.each do |isu|
-         conditions = db.xquery('SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY timestamp DESC', isu.fetch(:jia_isu_uuid)).to_a
+         conditions = db.xquery('SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY timestamp DESC LIMIT 1', isu.fetch(:jia_isu_uuid)).to_a

これで ./my-bench.sh を実行すると、

/tmp/my-bench.txt
17:10:40.378087 score: 18352(18352 - 0) : pass

スコアアップが確認できました。

alpの方も見てみます。

/tmp/alp-grouped-avg.txt
+-------+-----+------+------+-------+-----+--------+------------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+
| COUNT | 1XX | 2XX  | 3XX  |  4XX  | 5XX | METHOD |             URI              |  MIN  |  MAX  |   SUM    |  AVG  |  P90  |  P95  |  P99  | STDDEV | MIN(BODY) | MAX(BODY)  |  SUM(BODY)   | AVG(BODY) |
+-------+-----+------+------+-------+-----+--------+------------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+
|  3525 |   0 | 3511 |    0 |    14 |   0 | GET    | /api/trend                   | 0.008 | 0.368 |  642.029 | 0.182 | 0.236 | 0.264 | 0.316 |  0.045 |     0.000 |   5985.000 | 19714297.000 |  5592.708 |

GET /api/trend がずいぶん良くなっており、AVGが高速になったのはもちろん、COUNTが162->3525と大幅に増えています。

GET /api/trend キャッシュの仕組みを構築 （スコア19587）

さらに、同エンドポイントのキャッシュを試みます。下記のようなキャッシュテーブルを追加します。

/home/isucon/webapp/sql/0_Schema.sql
+CREATE TABLE `cache` (
+ `name` VARCHAR(255) PRIMARY KEY,
+ `value` TEXT NOT NULL
+) ENGINE=InnoDB DEFAULT CHARACTER SET=utf8mb4;

ちなみに、キャッシュにあたっては

  • RedisなどのKVSをインストールする
  • Varnishをインストールする
  • MariaDBのJSON型カラムを利用する

などの手もありそうでしたが、今回はTEXT型のvalueカラムにJSON文字列をそのまま格納するようにしました。時間があれば上記手段も試してみたいと思います。

アプリケーションコードは以下のように変更しました。

/home/isucon/webapp/ruby/app.rb
    # ISUの性格毎の最新のコンディション情報
    get '/api/trend' do
+     cache_probability = 0.7
+     if rand <= cache_probability
+       cached_trend = db.query("SELECT `value` FROM `cache` WHERE `name` = 'trend'").first
+       if !cached_trend.nil?
+         content_type :json
+         return cached_trend.fetch(:value)
+       end
+     end

      character_list = db.query('SELECT `character` FROM `isu` GROUP BY `character`')
/home/isucon/webapp/ruby/app.rb
+     res_json = res.to_json
+     db.xquery("INSERT INTO `cache` (`name`, `value`) values ('trend', ?) ON DUPLICATE KEY UPDATE `name` = 'trend'", res_json)

      content_type :json
-     res.to_json
+     res_json
    end

同アプリにすでに存在する drop_probability のアイデアを流用し、一定確率（ひとまず0.7としています）でキャッシュを返すようにしました。また、キャッシュを返さない場合は再集計した上でtrendを更新するようにしてみました。

そしてbenchを取ると、

/tmp/my-bench.txt
21:21:16.743787 score: 19587(19608 - 21) : pass

のスコアとなりました。

ただ、alpを見ると、

/tmp/alp-grouped-avg.txt
+-------+-----+-------+-----+-------+-----+--------+------------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+------------+
| COUNT | 1XX |  2XX  | 3XX |  4XX  | 5XX | METHOD |             URI              |  MIN  |  MAX  |   SUM    |  AVG  |  P90  |  P95  |  P99  | STDDEV | MIN(BODY) | MAX(BODY)  |  SUM(BODY)   | AVG(BODY)  |
+-------+-----+-------+-----+-------+-----+--------+------------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+------------+
|   326 |   0 |   220 |   0 |   106 |   0 | GET    | /api/isu/.*/graph            | 0.032 | 0.260 |   38.512 | 0.118 | 0.192 | 0.208 | 0.232 |  0.056 |     0.000 |  10574.000 |  1564022.000 |   4797.613 |
|  3327 |   0 |  3181 |   0 |   146 |   0 | GET    | /api/condition/.*            | 0.004 | 0.316 |  348.633 | 0.105 | 0.160 | 0.184 | 0.244 |  0.044 |     0.000 |   6281.000 | 16572049.000 |   4981.079 |
|     1 |   0 |     1 |   0 |     0 |   0 | POST   | /initialize                  | 0.104 | 0.104 |    0.104 | 0.104 | 0.104 | 0.104 | 0.104 |  0.000 |    19.000 |     19.000 |       19.000 |     19.000 |
|   260 |   0 |    92 |   0 |   168 |   0 | POST   | /api/auth                    | 0.004 | 0.180 |   21.852 | 0.084 | 0.144 | 0.164 | 0.180 |  0.043 |     0.000 |     19.000 |     1932.000 |      7.431 |
| 36653 |   0 | 24251 |   0 | 12402 |   0 | POST   | /api/condition/.*            | 0.000 | 0.120 | 3020.953 | 0.082 | 0.104 | 0.104 | 0.108 |  0.020 |     0.000 |     14.000 |      112.000 |      0.003 |
|   115 |   0 |   115 |   0 |     0 |   0 | GET    | /api/trend                   | 0.004 | 0.184 |    9.340 | 0.081 | 0.136 | 0.148 | 0.176 |  0.039 |  2661.000 |   4534.000 |   381165.000 |   3314.478 |
  • AVGは短縮
  • しかしCOUNTは減少

という結果が見えました。いやー、難しいですね。

drop probabilityの値を少し上げる

キリの良い2万点まであと少しというところです。何か少しの手間でスコアを上げられないかなと手探りしていたところ、

/home/isucon/webapp/ruby/app.rb
    # ISUからのコンディションを受け取る
    post '/api/condition/:jia_isu_uuid' do
      # TODO: 一定割合リクエストを落としてしのぐようにしたが、本来は全量さばけるようにすべき
-     drop_probability = 0
+     drop_probability = 0.6

上記のようにdrop probabilityの値を再度変更することで、

/tmp/my-bench.txt
21:46:12.921205 score: 21207(21228 - 21) : pass

2万点を超えました。

正直、これについてはWhyが説明できるわけではなく、

ISUCON11 予選問題の解説と講評 : ISUCON公式Blog

状況に応じて、trendの更新頻度を下げたり、dropProbabilityを上げたりすることで負荷を絞り、レスポンスタイムを速くすることも得点を稼ぐためには重要でした。

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

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

このあたりの記述を参考にしつつ試してみたら、という感じでした。モヤモヤは残りますが、一旦本件の掘り下げは後日に回したいと思います。本戦でもこういったことはありそうですね。

参考

Discussion