Yuhei Okazaki

Ruby版・ISUCON11 予選問題実践攻略法を試してみた

#Ruby #ISUCON #パフォーマンス #チューニング

2021/10/06

Table of Contents

前提
諸々セットアップ+初期スコアを確認
conditionのPOSTを一定割合受け入れる(POST /api/condition/:jia_isu_uuid)
検索やソートが遅い問題を改善
conditionのPOSTをすべて受け入れる(POST /api/condition/:jia_isu_uuid)
不要な行を取得するクエリの改善(GET /api/trend)
conditionのPOSTをパフォーマンス改善(POST /api/condition/:jia_isu_uuid)
アプリケーション行っているフィルタリングをSQLで行う(GET /api/condition/:jia_isu_uuid)
グラフに表示するデータをSQLで絞り込む(GET /api/isu/:jia_isu_uuid/graph)
複数台構成にする
サーバーごとの責務を見直す
サーバーごとの責務をさらに微調整
DBのチューニング
感想
まとめ

前提

環境は予選問題のリポジトリのREADMEに記載されている用意されたAMIを利用する場合を参考に、弊社のAWSアカウント上に構築しました。
利用言語はRubyです。
計測ツールは htop, myprofiler, estackprofを利用しています
- Estackprofについての詳細はこちらの記事を参照ください
基本的には上記記事を参考に進めていますが、きちんと計測をした上で一定の根拠を以て修正を加えていくようにしています。
- このため、公式の攻略法とは違う順番でチューニングしていたり、記載されている攻略法を一部適用していない場合があります。

諸々セットアップ+初期スコアを確認

環境を構築し、サーバーにSSHログインします。初期状態ではGo言語のアプリが動いているので、それを停止し代わりにRubyのアプリを起動します。

この時点でのスコアは 2708 です。

作業記録: https://github.com/yuuu/isucon11-qualify-test/issues/1#issuecomment-925545370

conditionのPOSTを一定割合受け入れる(POST /api/condition/:jia_isu_uuid)

htop

アプリケーションをRubyとした場合、初期実装の時点でCPUが若干余っているように見えました。アプリケーションのソースコードにて、conditionのPOSTを一定割合ドロップしている状態なので、最初にこれを0.9→0.4に変更しました。(公式の攻略記事では最後に行っています)

これでCPUを100％使用している状態となり、スコアは 7932 に上がりました。

作業記録: https://github.com/yuuu/isucon11-qualify-test/issues/1#issuecomment-926171410

検索やソートが遅い問題を改善

htop

myprofiler

##  2021-09-24 06:13:02.72 +0900
  69 SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = S ORDER BY timestamp DESC
   3 SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = S ORDER BY `timestamp` DESC LIMIT N
   2 SELECT * FROM `isu` WHERE `character` = S
   1 COMMIT
   1 INSERT INTO `isu_condition` (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`) VALUES (S, S, TRUE, S, S)
   1 SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = S ORDER BY `timestamp` ASC

CPUはMySQL(厳密にはMariaDB)が100%に貼り付いています。

攻略記事に書いてある通り、isu_condition テーブルに対して jia_isu_uuid と timestamp を用いた検索・ソートが遅いです。攻略記事だと複合プライマリキーを使っていますが、私は素直に複合Indexを追加しました。

スコアは 9833 まで上がりましたが、攻略記事によるとこの時点で2万点を超えるとのことで、実装言語による違いが既に生じていそうです。

作業記録: https://github.com/yuuu/isucon11-qualify-test/issues/1#issuecomment-926185310

conditionのPOSTをすべて受け入れる(POST /api/condition/:jia_isu_uuid)

htop

またしてもCPUが余っているように見えたので、リクエストを全て受け入れるようにしました。

ただ、冷静に数字を見るとpumaが100%に貼り付いていましたね。良くないチューニングだったかもしれません。

スコアは若干上がり 10088 となりました。

作業記録: https://github.com/yuuu/isucon11-qualify-test/issues/1#issuecomment-926185645

不要な行を取得するクエリの改善(GET /api/trend)

htop

myprofiler

##  2021-09-24 06:46:28.61 +0900
  13 COMMIT
   6 INSERT INTO `isu_condition` (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`) VALUES (S, S, TRUE, S, S)
   2 SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = S ORDER BY `timestamp` ASC
   1 SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = S ORDER BY timestamp DESC
   1 INSERT IGNORE INTO user (`jia_user_id`) VALUES (S)
   1 INSERT INTO `isu_condition` (`jia_isu_uuid`, `timestamp`, `is_sitting`, `condition`, `message`) VALUES (S, S, FALSE, S, S)

ボトルネックはアプリケーションと判断し、ここからは alp と Estackprof も併用して、ボトルネックを探します。

alp

+-------+-----+------+-----+-------+-----+--------+---------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+
| COUNT | 1XX | 2XX  | 3XX |  4XX  | 5XX | METHOD |            URI            |  MIN  |  MAX  |   SUM    |  AVG  |  P90  |  P95  |  P99  | STDDEV | MIN(BODY) | MAX(BODY)  |  SUM(BODY)   | AVG(BODY) |
+-------+-----+------+-----+-------+-----+--------+---------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+
|     1 |   0 |    1 |   0 |     0 |   0 | POST   | /initialize               | 0.196 | 0.196 |    0.196 | 0.196 | 0.196 | 0.196 | 0.196 |  0.000 |    19.000 |     19.000 |       19.000 |    19.000 |
|     3 |   0 |    3 |   0 |     0 |   0 | GET    | /register                 | 0.004 | 0.004 |    0.008 | 0.003 | 0.004 | 0.004 | 0.004 |  0.002 |   528.000 |    528.000 |     1584.000 |   528.000 |
|    50 |   0 |   50 |   0 |     0 |   0 | GET    | /isu/[a-z0-9-]+           | 0.000 | 0.004 |    0.016 | 0.000 | 0.000 | 0.004 | 0.004 |  0.001 |   528.000 |    528.000 |    26400.000 |   528.000 |
|    51 |   0 |   30 |   0 |    21 |   0 | POST   | /api/signout              | 0.076 | 0.628 |    6.200 | 0.122 | 0.160 | 0.236 | 0.628 |  0.088 |    21.000 |     21.000 |      441.000 |     8.647 |
|    55 |   0 |   51 |   0 |     4 |   0 | POST   | /api/isu                  | 0.004 | 0.188 |    5.864 | 0.107 | 0.152 | 0.164 | 0.188 |  0.041 |    15.000 |    170.000 |     7738.000 |   140.691 |
|    82 |   0 |   39 |   0 |    43 |   0 | GET    | /api/trend                | 0.020 | 1.004 |   69.692 | 0.850 | 1.000 | 1.004 | 1.004 |  0.288 |     0.000 |   4533.000 |   160543.000 |  1957.841 |
|    85 |   0 |   38 |   0 |    47 |   0 | GET    | /api/user/me              | 0.008 | 1.000 |   14.176 | 0.167 | 0.308 | 0.568 | 1.000 |  0.174 |    21.000 |     35.000 |     2172.000 |    25.553 |
|   144 |   0 |  143 |   0 |     1 |   0 | GET    | /                         | 0.004 | 0.868 |   17.508 | 0.122 | 0.244 | 0.284 | 0.344 |  0.098 |   528.000 |    528.000 |    75504.000 |   524.333 |
|   215 |   0 |  194 |   0 |    21 |   0 | GET    | /api/isu                  | 0.016 | 0.872 |   32.676 | 0.152 | 0.252 | 0.356 | 0.648 |  0.110 |     0.000 |   8058.000 |   478356.000 |  2224.912 |
|   247 |   0 |   95 |   0 |   152 |   0 | POST   | /api/auth                 | 0.016 | 0.724 |   30.364 | 0.123 | 0.192 | 0.212 | 0.540 |  0.079 |     0.000 |     19.000 |     1748.000 |     7.077 |
|   281 |   0 |  227 |   0 |    54 |   0 | GET    | /api/isu/[a-z0-9-]+       | 0.016 | 0.704 |   35.376 | 0.126 | 0.208 | 0.344 | 0.584 |  0.098 |    14.000 |    173.000 |    35180.000 |   125.196 |
|   618 |   0 |  526 |   0 |    92 |   0 | GET    | /api/isu/[a-z0-9-]+/graph | 0.044 | 1.000 |   99.949 | 0.162 | 0.240 | 0.308 | 0.516 |  0.085 |     0.000 |   7571.000 |  1763151.000 |  2852.995 |
|   869 |   0 |  365 | 504 |     0 |   0 | GET    | /assets/[a-z0-9-]+        | 0.004 | 0.888 |   71.848 | 0.083 | 0.164 | 0.228 | 0.336 |  0.085 |     0.000 | 743417.000 | 48571927.000 | 55894.047 |
|  1425 |   0 | 1348 |   0 |    77 |   0 | GET    | /api/isu/[a-z0-9-]+/icon  | 0.004 | 0.936 |  223.220 | 0.157 | 0.252 | 0.364 | 0.700 |  0.119 |     0.000 | 135259.000 | 34559164.000 | 24252.045 |
|  2289 |   0 | 2154 |   0 |   135 |   0 | GET    | /api/condition/[a-z0-9-]+ | 0.016 | 0.980 |  336.462 | 0.147 | 0.208 | 0.296 | 0.604 |  0.088 |     0.000 |   6281.000 | 10815385.000 |  4724.939 |
| 40419 |   0 | 1861 |   0 | 38558 |   0 | POST   | /api/condition/[a-z0-9-]+ | 0.004 | 0.132 | 4035.511 | 0.100 | 0.104 | 0.104 | 0.104 |  0.006 |     0.000 |     14.000 |      196.000 |     0.005 |
+-------+-----+------+-----+-------+-----+--------+---------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+

Estackprof

$ bundle exec estackprof list -f app.rb
# 省略
                                  |   582  |     # ISUの性格毎の最新のコンディション情報
                                  |   583  |     get '/api/trend' do
                                  |   584  |       character_list = db.query('SELECT `character` FROM `isu` GROUP BY `character`')
                                  |   585  | 
  213   (57.1%)                   |   586  |       res = character_list.map do |character|
    2    (0.5%)                   |   587  |         isu_list = db.xquery('SELECT * FROM `isu` WHERE `character` = ?', character.fetch(:character))
                                  |   588  |         character_info_isu_conditions = []
                                  |   589  |         character_warning_isu_conditions = []
                                  |   590  |         character_critical_isu_conditions = []
                                  |   591  | 
  210   (56.3%)                   |   592  |         isu_list.each do |isu|
  207   (55.5%)                   |   593  |           conditions = db.xquery('SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY timestamp DESC', isu.fetch(:jia_isu_uuid)).to_a
                                  |   594  |           unless conditions.empty?
                                  |   595  |             isu_last_condition = conditions.first
# 省略

conditions.first となっていることから593行目のクエリはLIMITをかけて良いことがわかりますね。

これを修正して、再度Estackprofを実行してみます。

Estackprof

bundle exec estackprof list -f app.rb
# 省略
                                  |   582  |     # ISUの性格毎の最新のコンディション情報
                                  |   583  |     get '/api/trend' do
                                  |   584  |       character_list = db.query('SELECT `character` FROM `isu` GROUP BY `character`')
                                  |   585  | 
   41   (57.7%)                   |   586  |       res = character_list.map do |character|
    8   (11.3%)                   |   587  |         isu_list = db.xquery('SELECT * FROM `isu` WHERE `character` = ?', character.fetch(:character))
                                  |   588  |         character_info_isu_conditions = []
                                  |   589  |         character_warning_isu_conditions = []
                                  |   590  |         character_critical_isu_conditions = []
                                  |   591  | 
   33   (46.5%)                   |   592  |         isu_list.each do |isu|
   23   (32.4%)                   |   593  |           conditions = db.xquery('SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY timestamp DESC LIMIT 1', isu.fetch(:jia_isu_uuid)).to_a
                                  |   594  |           unless conditions.empty?
                                  |   595  |             isu_last_condition = conditions.first
# 省略

確実にCPU負荷は下がっていますが、スコアは 9848 と、あまり変わりませんでした。

おそらく、POST /api/condition/:jia_isu_uuid があまり捌けておらず、取得できるステータスの数があまり増えていないためと推測されます。

作業記録: https://github.com/yuuu/isucon11-qualify-test/issues/1#issuecomment-926193631

conditionのPOSTをパフォーマンス改善(POST /api/condition/:jia_isu_uuid)

htop

alp

+-------+-----+------+------+-------+-----+--------+---------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+
| COUNT | 1XX | 2XX  | 3XX  |  4XX  | 5XX | METHOD |            URI            |  MIN  |  MAX  |   SUM    |  AVG  |  P90  |  P95  |  P99  | STDDEV | MIN(BODY) | MAX(BODY)  |  SUM(BODY)   | AVG(BODY) |
+-------+-----+------+------+-------+-----+--------+---------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+
|     1 |   0 |    1 |    0 |     0 |   0 | POST   | /initialize               | 0.204 | 0.204 |    0.204 | 0.204 | 0.204 | 0.204 | 0.204 |  0.000 |    19.000 |     19.000 |       19.000 |    19.000 |
|     3 |   0 |    3 |    0 |     0 |   0 | GET    | /register                 | 0.000 | 0.000 |    0.000 | 0.000 | 0.000 | 0.000 | 0.000 |  0.000 |   528.000 |    528.000 |     1584.000 |   528.000 |
|    41 |   0 |   25 |    0 |    16 |   0 | POST   | /api/signout              | 0.004 | 0.212 |    5.164 | 0.126 | 0.192 | 0.208 | 0.212 |  0.057 |     0.000 |     21.000 |      336.000 |     8.195 |
|    50 |   0 |   50 |    0 |     0 |   0 | GET    | /isu/[a-z0-9-]+           | 0.000 | 0.004 |    0.012 | 0.000 | 0.000 | 0.004 | 0.004 |  0.001 |   528.000 |    528.000 |    26400.000 |   528.000 |
|    58 |   0 |   54 |    0 |     4 |   0 | POST   | /api/isu                  | 0.004 | 0.204 |    7.164 | 0.124 | 0.176 | 0.188 | 0.204 |  0.051 |    15.000 |    160.000 |     8050.000 |   138.793 |
|    69 |   0 |   32 |    0 |    37 |   0 | GET    | /api/user/me              | 0.012 | 0.228 |    8.396 | 0.122 | 0.200 | 0.220 | 0.228 |  0.059 |    21.000 |     39.000 |     1747.000 |    25.319 |
|   187 |   0 |   74 |    0 |   113 |   0 | POST   | /api/auth                 | 0.004 | 0.244 |   24.284 | 0.130 | 0.200 | 0.204 | 0.240 |  0.058 |     0.000 |     19.000 |     1288.000 |     6.888 |
|   282 |   0 |  243 |    0 |    39 |   0 | GET    | /api/isu/[a-z0-9-]+       | 0.004 | 0.268 |   34.448 | 0.122 | 0.192 | 0.208 | 0.232 |  0.053 |    14.000 |    160.000 |    36741.000 |   130.287 |
|   326 |   0 |  311 |    0 |    15 |   0 | GET    | /api/isu                  | 0.008 | 0.280 |   50.244 | 0.154 | 0.204 | 0.220 | 0.260 |  0.047 |     0.000 |   8058.000 |   631518.000 |  1937.172 |
|   555 |   0 |  488 |    0 |    67 |   0 | GET    | /api/isu/[a-z0-9-]+/graph | 0.048 | 0.404 |  100.180 | 0.181 | 0.248 | 0.276 | 0.324 |  0.060 |     0.000 |   6857.000 |  1386904.000 |  2498.926 |
|  1351 |   0 | 1258 |    0 |    93 |   0 | GET    | /api/condition/[a-z0-9-]+ | 0.004 | 0.308 |  197.256 | 0.146 | 0.200 | 0.220 | 0.256 |  0.044 |     0.000 |   6001.000 |  6064864.000 |  4489.167 |
|  1621 |   0 | 1610 |    0 |    11 |   0 | GET    | /api/trend                | 0.012 | 0.416 |  380.620 | 0.235 | 0.292 | 0.312 | 0.348 |  0.044 |     0.000 |   4637.000 |  7418193.000 |  4576.307 |
|  1687 |   0 | 1681 |    0 |     6 |   0 | GET    | /                         | 0.004 | 0.288 |  255.592 | 0.152 | 0.200 | 0.216 | 0.248 |  0.039 |     0.000 |    528.000 |   887568.000 |   526.122 |
|  1811 |   0 | 1769 |    0 |    42 |   0 | GET    | /api/isu/[a-z0-9-]+/icon  | 0.024 | 0.292 |  270.368 | 0.149 | 0.196 | 0.216 | 0.244 |  0.041 |     0.000 | 135259.000 | 52716778.000 | 29109.209 |
| 10131 |   0 |  353 | 9742 |    36 |   0 | GET    | /assets/[a-z0-9-]+        | 0.000 | 0.308 | 1559.280 | 0.154 | 0.204 | 0.220 | 0.248 |  0.045 |     0.000 | 743417.000 | 46979297.000 |  4637.183 |
| 31336 |   0 |  362 |    0 | 30974 |   0 | POST   | /api/condition/[a-z0-9-]+ | 0.008 | 0.116 | 3136.264 | 0.100 | 0.104 | 0.104 | 0.104 |  0.005 |     0.000 |     14.000 |      266.000 |     0.008 |
+-------+-----+------+------+-------+-----+--------+---------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+

POST /api/condition/:jia_isu_uuid のリクエストがダントツで多く、そして多くが 4XX をレスポンスしています。これはマニュアルにも書かれているとおり、100ms以内に処理を完了できなかったため、ベンチマーカー側がタイムアウトしているためと推測します。

より効率的にPOSTを捌くために、テーブルへのINSERTをBulk Insertで行うよう修正しました。

alp

+-------+-----+------+-------+-------+-----+--------+---------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+
| COUNT | 1XX | 2XX  |  3XX  |  4XX  | 5XX | METHOD |            URI            |  MIN  |  MAX  |   SUM    |  AVG  |  P90  |  P95  |  P99  | STDDEV | MIN(BODY) | MAX(BODY)  |  SUM(BODY)   | AVG(BODY) |
+-------+-----+------+-------+-------+-----+--------+---------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+
|     1 |   0 |    1 |     0 |     0 |   0 | POST   | /initialize               | 0.212 | 0.212 |    0.212 | 0.212 | 0.212 | 0.212 | 0.212 |  0.000 |    19.000 |     19.000 |       19.000 |    19.000 |
|     3 |   0 |    3 |     0 |     0 |   0 | GET    | /register                 | 0.004 | 0.004 |    0.004 | 0.001 | 0.004 | 0.004 | 0.004 |  0.002 |   528.000 |    528.000 |     1584.000 |   528.000 |
|    30 |   0 |   30 |     0 |     0 |   0 | GET    | /isu/[a-z0-9-]+           | 0.000 | 0.004 |    0.020 | 0.001 | 0.004 | 0.004 | 0.004 |  0.001 |   528.000 |    528.000 |    15840.000 |   528.000 |
|    45 |   0 |   29 |     0 |    16 |   0 | POST   | /api/signout              | 0.044 | 0.216 |    5.508 | 0.122 | 0.184 | 0.200 | 0.216 |  0.057 |    21.000 |     21.000 |      336.000 |     7.467 |
|    60 |   0 |   56 |     0 |     4 |   0 | POST   | /api/isu                  | 0.004 | 0.208 |    6.424 | 0.107 | 0.156 | 0.188 | 0.208 |  0.044 |    15.000 |    168.000 |     8424.000 |   140.400 |
|    80 |   0 |   39 |     0 |    41 |   0 | GET    | /api/user/me              | 0.012 | 0.228 |    9.612 | 0.120 | 0.200 | 0.204 | 0.228 |  0.057 |    21.000 |     38.000 |     2064.000 |    25.800 |
|   193 |   0 |   81 |     0 |   112 |   0 | POST   | /api/auth                 | 0.004 | 0.256 |   24.868 | 0.129 | 0.196 | 0.224 | 0.252 |  0.060 |     0.000 |     19.000 |     1288.000 |     6.674 |
|   263 |   0 |  220 |     0 |    43 |   0 | GET    | /api/isu/[a-z0-9-]+       | 0.004 | 0.232 |   30.594 | 0.116 | 0.192 | 0.208 | 0.225 |  0.055 |     0.000 |    168.000 |    33419.000 |   127.068 |
|   386 |   0 |  370 |     0 |    16 |   0 | GET    | /api/isu                  | 0.008 | 0.260 |   61.552 | 0.159 | 0.212 | 0.224 | 0.248 |  0.046 |     0.000 |   3726.000 |   565291.000 |  1464.484 |
|   472 |   0 |  405 |     0 |    67 |   0 | GET    | /api/isu/[a-z0-9-]+/graph | 0.004 | 0.396 |   84.134 | 0.178 | 0.236 | 0.248 | 0.348 |  0.058 |     0.000 |   8203.000 |  1325895.000 |  2809.100 |
|  1638 |   0 | 1544 |     0 |    94 |   0 | GET    | /api/condition/[a-z0-9-]+ | 0.004 | 0.328 |  241.470 | 0.147 | 0.204 | 0.220 | 0.264 |  0.045 |     0.000 |   6161.000 |  7649536.000 |  4670.046 |
|  1738 |   0 | 1691 |     0 |    47 |   0 | GET    | /api/isu/[a-z0-9-]+/icon  | 0.012 | 0.280 |  259.602 | 0.149 | 0.208 | 0.220 | 0.240 |  0.046 |     0.000 | 135259.000 | 51179858.000 | 29447.559 |
|  1768 |   0 | 1761 |     0 |     7 |   0 | GET    | /api/trend                | 0.008 | 0.380 |  419.160 | 0.237 | 0.296 | 0.312 | 0.352 |  0.045 |     0.000 |   4673.000 |  8159583.000 |  4615.149 |
|  1846 |   0 | 1838 |     0 |     8 |   0 | GET    | /                         | 0.004 | 0.276 |  289.821 | 0.157 | 0.208 | 0.220 | 0.248 |  0.041 |     0.000 |    528.000 |   970464.000 |   525.712 |
| 10937 |   0 |  407 | 10482 |    48 |   0 | GET    | /assets/[a-z0-9-]+        | 0.000 | 0.288 | 1709.146 | 0.156 | 0.208 | 0.220 | 0.248 |  0.044 |     0.000 | 743417.000 | 54146132.000 |  4950.730 |
| 32618 |   0 | 2183 |     0 | 30435 |   0 | POST   | /api/condition/[a-z0-9-]+ | 0.008 | 0.124 | 3238.822 | 0.099 | 0.104 | 0.104 | 0.104 |  0.007 |     0.000 |     14.000 |      168.000 |     0.005 |
+-------+-----+------+-------+-------+-----+--------+---------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+

POST /api/condition/:jia_isu_uuid の成功率は上がりましたが、スコアは 9878 とあまり変わりませんでした。

conditionの取得処理を改善して、より多くのconditionが返せるようになると、スコアも上がるはず。

作業記録: https://github.com/yuuu/isucon11-qualify-test/issues/1#issuecomment-926545240

アプリケーション行っているフィルタリングをSQLで行う(GET /api/condition/:jia_isu_uuid)

※ここは、プロファイリング結果を残し忘れました。推測は良くないですね😭

攻略記事にも書いているとおり、 GET /api/condition/:jia_isu_uuid の処理がconditionを一括取得して、アプリケーションでlevelのフィルタリングを行っています。これは効率が悪いので、テーブルにカラムを追加して POST /api/condition/:jia_isu_uuid の段階でlevelを計算し、保存するよう修正します。

これにより GET /api/condition/:jia_isu_uuid はSQLで該当するlevelのレコードのみをSELECTできるようになり、処理が効率化します。

スコアは 11448 まで伸びました。

作業記録: https://github.com/yuuu/isucon11-qualify-test/issues/1#issuecomment-926984219

グラフに表示するデータをSQLで絞り込む(GET /api/isu/:jia_isu_uuid/graph)

htop

alp

+-------+-----+------+-------+-------+-----+--------+---------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+
| COUNT | 1XX | 2XX  |  3XX  |  4XX  | 5XX | METHOD |            URI            |  MIN  |  MAX  |   SUM    |  AVG  |  P90  |  P95  |  P99  | STDDEV | MIN(BODY) | MAX(BODY)  |  SUM(BODY)   | AVG(BODY) |
+-------+-----+------+-------+-------+-----+--------+---------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+
|     1 |   0 |    1 |     0 |     0 |   0 | POST   | /initialize               | 0.240 | 0.240 |    0.240 | 0.240 | 0.240 | 0.240 | 0.240 |  0.000 |    19.000 |     19.000 |       19.000 |    19.000 |
|     3 |   0 |    3 |     0 |     0 |   0 | GET    | /register                 | 0.000 | 0.000 |    0.000 | 0.000 | 0.000 | 0.000 | 0.000 |  0.000 |   528.000 |    528.000 |     1584.000 |   528.000 |
|    50 |   0 |   50 |     0 |     0 |   0 | GET    | /isu/[a-z0-9-]+           | 0.000 | 0.004 |    0.036 | 0.001 | 0.004 | 0.004 | 0.004 |  0.002 |   528.000 |    528.000 |    26400.000 |   528.000 |
|    51 |   0 |   35 |     0 |    16 |   0 | POST   | /api/signout              | 0.052 | 0.240 |    6.580 | 0.129 | 0.208 | 0.224 | 0.240 |  0.064 |    21.000 |     21.000 |      336.000 |     6.588 |
|    73 |   0 |   69 |     0 |     4 |   0 | POST   | /api/isu                  | 0.004 | 0.248 |    8.992 | 0.123 | 0.196 | 0.212 | 0.248 |  0.053 |    15.000 |    170.000 |    10558.000 |   144.630 |
|    94 |   0 |   47 |     0 |    47 |   0 | GET    | /api/user/me              | 0.008 | 0.312 |   12.544 | 0.133 | 0.220 | 0.264 | 0.312 |  0.069 |    21.000 |     38.000 |     2541.000 |    27.032 |
|   201 |   0 |   89 |     0 |   112 |   0 | POST   | /api/auth                 | 0.016 | 0.292 |   27.292 | 0.136 | 0.252 | 0.272 | 0.288 |  0.072 |     0.000 |     19.000 |     1288.000 |     6.408 |
|   296 |   0 |  256 |     0 |    40 |   0 | GET    | /api/isu/[a-z0-9-]+       | 0.012 | 0.308 |   35.724 | 0.121 | 0.204 | 0.224 | 0.300 |  0.064 |     0.000 |    170.000 |    39230.000 |   132.534 |
|   417 |   0 |  402 |     0 |    15 |   0 | GET    | /api/isu                  | 0.012 | 0.324 |   67.548 | 0.162 | 0.228 | 0.244 | 0.292 |  0.054 |     0.000 |   8058.000 |   644892.000 |  1546.504 |
|   431 |   0 |  363 |     0 |    68 |   0 | GET    | /api/isu/[a-z0-9-]+/graph | 0.036 | 0.368 |   77.516 | 0.180 | 0.268 | 0.284 | 0.336 |  0.072 |     0.000 |   8235.000 |  1314914.000 |  3050.845 |
|  1907 |   0 | 1812 |     0 |    95 |   0 | GET    | /api/condition/[a-z0-9-]+ | 0.004 | 0.368 |  281.832 | 0.148 | 0.220 | 0.248 | 0.308 |  0.056 |     0.000 |   6181.000 |  9037342.000 |  4739.036 |
|  1936 |   0 | 1928 |     0 |     8 |   0 | GET    | /api/trend                | 0.012 | 0.484 |  482.448 | 0.249 | 0.332 | 0.360 | 0.412 |  0.060 |     0.000 |   4924.000 |  9288765.000 |  4797.916 |
|  2027 |   0 | 2020 |     0 |     7 |   0 | GET    | /                         | 0.004 | 0.364 |  345.484 | 0.170 | 0.252 | 0.272 | 0.320 |  0.059 |     0.000 |    528.000 |  1066560.000 |   526.177 |
|  2185 |   0 | 2137 |     0 |    48 |   0 | GET    | /api/isu/[a-z0-9-]+/icon  | 0.008 | 0.372 |  379.556 | 0.174 | 0.264 | 0.300 | 0.344 |  0.069 |     0.000 | 135259.000 | 55050824.000 | 25194.885 |
| 12081 |   0 |  491 | 11498 |    92 |   0 | GET    | /assets/[a-z0-9-]+        | 0.000 | 0.360 | 1968.284 | 0.163 | 0.236 | 0.260 | 0.304 |  0.057 |     0.000 | 743417.000 | 65294542.000 |  5404.730 |
| 37371 |   0 | 2835 |     0 | 34536 |   0 | POST   | /api/condition/[a-z0-9-]+ | 0.004 | 0.108 | 3705.376 | 0.099 | 0.104 | 0.104 | 0.104 |  0.007 |     0.000 |     14.000 |      196.000 |     0.005 |
+-------+-----+------+-------+-------+-----+--------+---------------------------+-------+-------+----------+-------+-------+-------+-------+--------+-----------+------------+--------------+-----------+

相変わらずアプリケーションのCPU負荷が高いです。Estackprofを使ってボトルネックを探します。

Estackprof

                                  |   371  |     # グラフのデータ点を一日分生成
                                  |   372  |     def generate_isu_graph_response(jia_isu_uuid, graph_date)
                                  |   373  |       rows = db.xquery('SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ? ORDER BY `timestamp` ASC', jia_isu_uuid)
                                  |   374  | 
                                  |   375  |       data_points = []
                                  |   376  |       start_time_in_this_hour = Time.at(0)
                                  |   377  |       conditions_in_this_hour = []
                                  |   378  |       timestamps_in_this_hour = []
                                  |   379  | 
   16   (22.5%)                   |   380  |       rows.each do |condition|
    1    (1.4%)                   |   381  |         timestamp = condition.fetch(:timestamp)
    1    (1.4%)                   |   382  |         truncated_condition_time = Time.new(timestamp.year, timestamp.month, timestamp.day, timestamp.hour, 0, 0)
    2    (2.8%)                   |   383  |         if truncated_condition_time != start_time_in_this_hour
                                  |   384  |           unless conditions_in_this_hour.empty?
    4    (5.6%)                   |   385  |             data = calculate_graph_data_point(conditions_in_this_hour)
    1    (1.4%)                   |   386  |             data_points.push(
                                  |   387  |               jia_isu_uuid: jia_isu_uuid,
                                  |   388  |               start_at: start_time_in_this_hour,
                                  |   389  |               data: data,
                                  |   390  |               condition_timestamps: timestamps_in_this_hour,
                                  |   391  |             )
                                  |   392  |           end

ここくらいしか改善できそうな箇所が見つかりませんでした。WHERE句にtimestampを追加することで、指定した範囲の時間のレコードのみをSELECTするよう修正します。

再度プロファイリングすると、当該箇所でのCPU負荷が下がっています。

Estackprof



                                  |   371  |     # グラフのデータ点を一日分生成
                                  |   372  |     def generate_isu_graph_response(jia_isu_uuid, graph_date)
                                  |   373  |       rows = db.xquery(
                                  |   374  |         'SELECT * FROM `isu_condition` WHERE `jia_isu_uuid` = ? AND `timestamp` >= ? AND `timestamp` < ? ORDER BY `timestamp` ASC',
                                  |   375  |         jia_isu_uuid,
                                  |   376  |         graph_date,
                                  |   377  |         graph_date + (3600 * 24),
                                  |   378  |       )
                                  |   379  | 
                                  |   380  |       data_points = []
                                  |   381  |       start_time_in_this_hour = Time.at(0)
                                  |   382  |       conditions_in_this_hour = []
                                  |   383  |       timestamps_in_this_hour = []
                                  |   384  | 
                                  |   385  |       rows.each do |condition|
                                  |   386  |         timestamp = condition.fetch(:timestamp)
                                  |   387  |         truncated_condition_time = Time.new(timestamp.year, timestamp.month, timestamp.day, timestamp.hour, 0, 0)
                                  |   388  |         if truncated_condition_time != start_time_in_this_hour
                                  |   389  |           unless conditions_in_this_hour.empty?
                                  |   390  |             data = calculate_graph_data_point(conditions_in_this_hour)
                                  |   391  |             data_points.push(
                                  |   392  |               jia_isu_uuid: jia_isu_uuid,
                                  |   393  |               start_at: start_time_in_this_hour,
                                  |   394  |               data: data,
                                  |   395  |               condition_timestamps: timestamps_in_this_hour,
                                  |   396  |             )
                                  |   397  |           end

しかし、スコアは 11094 と、あまり変わりませんでした。

作業記録: https://github.com/yuuu/isucon11-qualify-test/issues/1#issuecomment-927185913

複数台構成にする

1台でのチューニングはこれが限界と判断し、複数台構成に切り替えました。

サーバー2を /api/condition/* へのPOST処理、サーバー3をDB専任としています。

複数台構成にする際は、/home/isucon/env.sh を活用すると良いです。アプリケーションが接続するDBを簡単に切り替えられます。

スコアが一気に伸びることを期待したのですが 27003 でした。Go言語のようにはいかないのか...

作業記録: https://github.com/yuuu/isucon11-qualify-test/issues/1#issuecomment-927190480

サーバーごとの責務を見直す

再度、3台のサーバーそれぞれの負荷状況を確認します。

htop

サーバー1(左上)のアプリケーションのCPU使用率が相変わらず高いですね。サーバー3(左下)のDBのCPU使用率はスクリーンショットだと高いのですが、これは一時的なもので若干余力があるように見えました。

これを踏まえて、/api/trend へのリクエストのみサーバー3へプロキシするよう、Nginxの設定を見直しました。

また、Estackprofによるプロファイリングを行わないようコード修正しています。

結果、スコアは 58246 まで伸びました！5万点超え！

作業記録: https://github.com/yuuu/isucon11-qualify-test/issues/1#issuecomment-927216548

サーバーごとの責務をさらに微調整

EstackprofをOFFにしたためか、今度はサーバー1(左上)に余力が生じています。

htop

このため、サーバー2の専任としていた /api/condition/* へのリクエストを、一部サーバー1にも割り振るように修正します。これによりボトルネックはサーバー3(DB)となりました。

結果、スコアは　59434 に微増しました。

作業記録: https://github.com/yuuu/isucon11-qualify-test/issues/1#issuecomment-927217257

DBのチューニング

ここまでDBのチューニングを一切行っていなかったので、最後にDBの設定を見直します。

スコアは　63560 となりました。6万点超え！！！

作業記録: https://github.com/yuuu/isucon11-qualify-test/issues/1#issuecomment-927219712

感想

今回、公式の攻略法を見ながらのチューニングをしたが、単純にすごく良い練習になった。
- これを1回やるだけでも予選成績を大きく伸ばせる気がしている。
RubyだとGo言語のように大きくスコアを伸ばすことができなかった。
- ISUCON10ではRubyで優勝した事例もあるので、優勝が不可能であるということはない。
- 少なくともこの問題においてはGo言語とRubyでスコアの伸びが3倍ほど違う。
- Rubyは好きだけど、やはり勝ちたいので来年はGo言語で出場しようと思った。
/api/condition/* へのPOST処理をsidekiqでキューイングしたがスコアはあまり変わらなかった。
- https://github.com/yuuu/isucon11-qualify-test/tree/sidekiq
- ただし、これは1台構成でしか確認ができていないことに後で気づいた。
- 複数台構成にするともしかするとPOSTをより多く処理できるようになり、スコアが伸びるかも？