Fusic Tech Blog

Fusion of Society, IT and Culture

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

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

岡嵜です。

先の記事 で触れた通り、私は8月に開催されたISUCON11の予選に実装言語Rubyで参加し、今年も予選で敗退しました。(悔しいので何度でも書きます...!)

そんな中、今年は ISUCON11予選問題実践攻略法 という記事が運営より公開されています。

毎年「勝てなかった」という記憶だけが残り、具体的なパフォーマンスチューニング方法がわからないまま翌年を迎えることが多かった自分にとって、これはとても嬉しい記事でした。一方、この記事はGo言語での解説となっていたので、Rubyで同じチューニングを実践した場合にどういう結果となるのか気になりますよね?

そこで今回、ISUCON11の予選問題と同等の環境を用意し、上記記事を参考にRubyでのパフォーマンスチューニングを実践してみました。仮定と結果を記事にまとめます。

前提

  • 環境は予選問題のリポジトリのREADMEに記載されている 用意されたAMIを利用する場合 を参考に、弊社のAWSアカウント上に構築しました。
  • 利用言語はRubyです。
  • 計測ツールは htop, myprofiler, 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_uuidtimestamp を用いた検索・ソートが遅いです。攻略記事だと複合プライマリキーを使っていますが、私は素直に複合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)

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

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でキューイングしたがスコアはあまり変わらなかった。

まとめ

今回、運営より攻略記事を公開いただいたことで、じっくり時間を取ってISUCONに取り組む良いきっかけになりました。 とてもありがたかったです!

Ruby以外の言語でのスコア状況も気になるところですね。

yuuu

yuuu

2018年の年明けに組込み畑からやってきた、2児の父 兼 Webエンジニアです。 mockmockの開発・運用を担当しており、組込みエンジニア時代の経験を活かしてデバイスをプログラミングしたり、簡易的なIoTシステムを作ったりしています。主な開発言語はRuby、時々Go。