はじめに
本記事では、ISUCON9の予選問題をローカル環境で実行しながら振り返りを行います。言語はrubyで行います。
環境構築
環境構築には以下のリポジトリのVagrantfileを使用します。
https://github.com/matsuu/vagrant-isucon
本番との違いはREADME.mdにも記載のある通り、スペックと台数です。
初期実装のスコア
実装をrubyに切り替えてベンチマークを実行します。
- 実装の切り替え
$ sudo systemctl stop isucari.golang.service
$ sudo systemctl disable isucari.golang.service
$ sudo systemctl start isucari.ruby.service
$ sudo systemctl enable isucari.ruby.service
- ベンチマークの実行
ベンチマークは本番と同様にNginxを通して実行したいので、target_urlを指定して実行します。
$ ./bin/benchmarker -target-url https://127.0.0.1
実行結果は以下の通りです。
{"pass":true,"score":2010,"campaign":0,"language":"ruby","messages":[]}
アクセスログを解析する
alp v0.4.0を使用してアクセスログの解析をします。
https://github.com/tkuchiki/alp
v1.0.0もありますが、事前準備の段階でv1.0.0が上手く動かなかったため、v0.4.0を使用しました。
$ sudo wget https://github.com/tkuchiki/alp/releases/download/v0.4.0/alp_linux_amd64.zip
$ sudo unzip alp_linux_amd64.zip
$ sudo mv alp /usr/bin/
Nginxのログをalpで解析できる形式にします。
nginx.confを修正したらNginxを再起動する必要があります。
nginx.conf
log_format ltsv "time:$time_local"
"\thost:$remote_addr"
"\tforwardedfor:$http_x_forwarded_for"
"\treq:$request"
"\tstatus:$status"
"\tmethod:$request_method"
"\turi:$request_uri"
"\tsize:$body_bytes_sent"
"\treferer:$http_referer"
"\tua:$http_user_agent"
"\treqtime:$request_time"
"\tcache:$upstream_http_x_cache"
"\truntime:$upstream_http_x_runtime"
"\tapptime:$upstream_response_time"
"\tvhost:$host";
access_log /var/log/nginx/access.log ltsv;
この状態で改めてベンチマークを実行し、アクセスログを解析します。
集計の正規表現はalpの結果を見ながら適当に足して行きました。
$ sudo cat /var/log/nginx/access.log | alp --aggregates="/users/\d+.json","/items/\d+.json","/new_items/\d+.json","/upload/.+.jpg","/transactions/\d+.png"
結果は以下のように表示されます。
大きな時間を取っているGET /users/transactions.jsonやGET /new_items/\d+.jsonから対応していく方針になります。
+-------+--------+-------------------------------------+-----+------+-----+-----+-----+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+
| COUNT | METHOD | URI | 1XX | 2XX | 3XX | 4XX | 5XX | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) |
+-------+--------+-------------------------------------+-----+------+-----+-----+-----+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+
| 1 | GET | /static/js/runtime~main.a8a9905a.js | 0 | 1 | 0 | 0 | 0 | 0.008 | 0.008 | 0.008 | 0.008 | 0.008 | 0.008 | 0.008 | 0.000 | 1502.000 | 1502.000 | 1502.000 | 1502.000 |
| 34 | GET | /transactions/\d+.png | 0 | 22 | 0 | 12 | 0 | 0.004 | 0.012 | 0.124 | 0.004 | 0.000 | 0.004 | 0.000 | 0.004 | 32.000 | 626.000 | 13945.000 | 410.147 |
| 1 | GET | /reports.json | 0 | 1 | 0 | 0 | 0 | 0.012 | 0.012 | 0.012 | 0.012 | 0.012 | 0.012 | 0.012 | 0.000 | 94019.000 | 94019.000 | 94019.000 | 94019.000 |
| 1 | GET | /static/js/2.ff6e1067.chunk.js | 0 | 1 | 0 | 0 | 0 | 0.032 | 0.032 | 0.032 | 0.032 | 0.032 | 0.032 | 0.032 | 0.000 | 508459.000 | 508459.000 | 508459.000 | 508459.000 |
| 9 | POST | /items/edit | 0 | 3 | 0 | 6 | 0 | 0.004 | 0.052 | 0.092 | 0.010 | 0.004 | 0.008 | 0.012 | 0.015 | 57.000 | 92.000 | 615.000 | 68.333 |
| 1 | GET | /static/css/main.19393e92.chunk.css | 0 | 1 | 0 | 0 | 0 | 0.052 | 0.052 | 0.052 | 0.052 | 0.052 | 0.052 | 0.052 | 0.000 | 994.000 | 994.000 | 994.000 | 994.000 |
| 57 | GET | /upload/.+.jpg | 0 | 57 | 0 | 0 | 0 | 0.004 | 0.128 | 1.644 | 0.029 | 0.008 | 0.024 | 0.004 | 0.025 | 51229.000 | 130127.000 | 4362729.000 | 76539.105 |
| 13 | POST | /bump | 0 | 13 | 0 | 0 | 0 | 0.004 | 0.352 | 0.756 | 0.058 | 0.076 | 0.068 | 0.008 | 0.092 | 90.000 | 91.000 | 1171.000 | 90.077 |
| 1 | GET | /static/js/main.babc3d4d.chunk.js | 0 | 1 | 0 | 0 | 0 | 0.452 | 0.452 | 0.452 | 0.452 | 0.452 | 0.452 | 0.452 | 0.000 | 90365.000 | 90365.000 | 90365.000 | 90365.000 |
| 53 | GET | /settings | 0 | 53 | 0 | 0 | 0 | 0.012 | 0.488 | 6.173 | 0.116 | 0.048 | 0.092 | 0.000 | 0.125 | 3086.000 | 3100.000 | 163919.000 | 3092.811 |
| 2207 | GET | /items/\d+.json | 0 | 2206 | 0 | 1 | 0 | 0.005 | 0.517 | 16.024 | 0.007 | 0.008 | 0.004 | 0.012 | 0.019 | 0.000 | 4041.000 | 4840278.000 | 2193.148 |
| 61 | POST | /login | 0 | 53 | 0 | 8 | 0 | 0.060 | 0.781 | 18.730 | 0.307 | 0.124 | 0.389 | 0.060 | 0.183 | 72.000 | 266.000 | 14293.000 | 234.311 |
| 52 | POST | /sell | 0 | 34 | 0 | 18 | 0 | 0.004 | 0.820 | 5.281 | 0.102 | 0.080 | 0.000 | 0.008 | 0.204 | 12.000 | 105.000 | 1836.000 | 35.308 |
| 40 | POST | /ship_done | 0 | 22 | 0 | 18 | 0 | 0.816 | 0.824 | 19.747 | 0.494 | 0.020 | 0.000 | 0.000 | 0.392 | 28.000 | 82.000 | 1602.000 | 40.050 |
| 21 | POST | /complete | 0 | 20 | 0 | 1 | 0 | 0.004 | 0.876 | 14.621 | 0.696 | 0.008 | 0.828 | 0.832 | 0.287 | 0.000 | 33.000 | 660.000 | 31.429 |
| 38 | POST | /ship | 0 | 26 | 0 | 12 | 0 | 0.808 | 0.937 | 19.301 | 0.508 | 0.020 | 0.820 | 0.828 | 0.398 | 28.000 | 60.000 | 1944.000 | 51.158 |
| 267 | GET | /users/\d+.json | 0 | 267 | 0 | 0 | 0 | 0.008 | 1.325 | 53.977 | 0.202 | 0.168 | 0.072 | 0.120 | 0.199 | 97.000 | 23995.000 | 3711121.000 | 13899.330 |
| 51 | POST | /buy | 0 | 27 | 0 | 24 | 0 | 0.000 | 2.029 | 48.036 | 0.942 | 0.004 | 1.613 | 1.640 | 0.809 | 28.000 | 48.000 | 1809.000 | 35.471 |
| 130 | GET | /new_items.json | 0 | 130 | 0 | 0 | 0 | 0.048 | 2.045 | 51.348 | 0.395 | 0.508 | 0.097 | 0.188 | 0.320 | 23011.000 | 23940.000 | 3043699.000 | 23413.069 |
| 700 | GET | /new_items/\d+.json | 0 | 698 | 0 | 2 | 0 | 0.028 | 2.061 | 167.766 | 0.240 | 0.088 | 0.088 | 0.148 | 0.217 | 0.000 | 24044.000 | 16387888.000 | 23411.269 |
| 1 | POST | /initialize | 0 | 1 | 0 | 0 | 0 | 7.156 | 7.156 | 7.156 | 7.156 | 7.156 | 7.156 | 7.156 | 0.000 | 32.000 | 32.000 | 32.000 | 32.000 |
| 160 | GET | /users/transactions.json | 0 | 151 | 0 | 9 | 0 | 0.028 | 7.467 | 450.698 | 2.817 | 0.384 | 2.613 | 3.492 | 1.551 | 0.000 | 30441.000 | 3087209.000 | 19295.056 |
+-------+--------+-------------------------------------+-----+------+-----+-----+-----+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+
categoriesのオンメモリ化
GET /users/transactions.jsonやGET /new_items/\d+.jsonの実装を確認すると、get_user_simple_by_id()とget_category_by_id()が非常に気軽に呼ばれていることに気がつきます。
このうち、get_category_by_id()についてはcategoriesテーブルの更新が無いため、メモリに乗せることができます。
def get_category_by_id(category_id)
category = categories.find{|item| item[:id] == category_id}
return if category.nil?
parent_category_name = if category[:parent_id] != 0
parent_category = get_category_by_id(category[:parent_id])
return if parent_category.nil?
parent_category['category_name']
end
{
'id' => category[:id],
'parent_id' => category[:parent_id],
'category_name' => category[:category_name],
'parent_category_name' => parent_category_name
}
end
def categories
[
{:id => 1, :parent_id => 0, :category_name => "ソファー"},
{:id => 2, :parent_id => 1, :category_name => "一人掛けソファー"},
{:id => 3, :parent_id => 1, :category_name => "二人掛けソファー"},
{:id => 4, :parent_id => 1, :category_name => "コーナーソファー"},
{:id => 5, :parent_id => 1, :category_name => "二段ソファー"},
{:id => 6, :parent_id => 1, :category_name => "ソファーベッド"},
{:id => 10, :parent_id => 0, :category_name => "家庭用チェア"},
{:id => 11, :parent_id => 10, :category_name => "スツール"},
{:id => 12, :parent_id => 10, :category_name => "クッションスツール"},
{:id => 13, :parent_id => 10, :category_name => "ダイニングチェア"},
{:id => 14, :parent_id => 10, :category_name => "リビングチェア"},
{:id => 15, :parent_id => 10, :category_name => "カウンターチェア"},
{:id => 20, :parent_id => 0, :category_name => "キッズチェア"},
{:id => 21, :parent_id => 20, :category_name => "学習チェア"},
{:id => 22, :parent_id => 20, :category_name => "ベビーソファ"},
{:id => 23, :parent_id => 20, :category_name => "キッズハイチェア"},
{:id => 24, :parent_id => 20, :category_name => "テーブルチェア"},
{:id => 30, :parent_id => 0, :category_name => "オフィスチェア"},
{:id => 31, :parent_id => 30, :category_name => "デスクチェア"},
{:id => 32, :parent_id => 30, :category_name => "ビジネスチェア"},
{:id => 33, :parent_id => 30, :category_name => "回転チェア"},
{:id => 34, :parent_id => 30, :category_name => "リクライニングチェア"},
{:id => 35, :parent_id => 30, :category_name => "投擲用椅子"},
{:id => 40, :parent_id => 0, :category_name => "折りたたみ椅子"},
{:id => 41, :parent_id => 40, :category_name => "パイプ椅子"},
{:id => 42, :parent_id => 40, :category_name => "木製折りたたみ椅子"},
{:id => 43, :parent_id => 40, :category_name => "キッチンチェア"},
{:id => 44, :parent_id => 40, :category_name => "アウトドアチェア"},
{:id => 45, :parent_id => 40, :category_name => "作業椅子"},
{:id => 50, :parent_id => 0, :category_name => "ベンチ"},
{:id => 51, :parent_id => 50, :category_name => "一人掛けベンチ"},
{:id => 52, :parent_id => 50, :category_name => "二人掛けベンチ"},
{:id => 53, :parent_id => 50, :category_name => "アウトドア用ベンチ"},
{:id => 54, :parent_id => 50, :category_name => "収納付きベンチ"},
{:id => 55, :parent_id => 50, :category_name => "背もたれ付きベンチ"},
{:id => 56, :parent_id => 50, :category_name => "ベンチマーク"},
{:id => 60, :parent_id => 0, :category_name => "座椅子"},
{:id => 61, :parent_id => 60, :category_name => "和風座椅子"},
{:id => 62, :parent_id => 60, :category_name => "高座椅子"},
{:id => 63, :parent_id => 60, :category_name => "ゲーミング座椅子"},
{:id => 64, :parent_id => 60, :category_name => "ロッキングチェア"},
{:id => 65, :parent_id => 60, :category_name => "座布団"},
{:id => 66, :parent_id => 60, :category_name => "空気椅子"}
]
end
get_user_simple_by_idを削除
get_user_simple_by_id()もget_category_by_id()と同様に非常に多く呼ばれています。
こちらはオンメモリ化は難しいので、JOINして取得するようにします。
以下に、一例としてgetNewItemsのクエリを掲載します。
SELECT
t1.*
,t2.`account_name`
,t2.`num_sell_items`
FROM
`items` AS t1
INNER JOIN `users` AS t2 ON
t1.`seller_id` = t2.`id`
WHERE
t1.`status` IN (?, ?)
ORDER BY
t1.`created_at` DESC, t1.`id` DESC
LIMIT
#{ITEMS_PER_PAGE + 1}
getTransactionsのAPI呼び出し
ここからは当日できなかった修正です。
api_client.shipment_statusはtransaction_evidenceのstatusがdoneの時には呼び出す必要が無いそうです。
修正後のスコアは以下の通りです。
{"pass":true,"score":3740,"campaign":0,"language":"ruby","messages":[]}
この時点でのalpの結果は以下のようになります。
+-------+--------+-------------------------------------+-----+------+-----+-----+-----+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+
| COUNT | METHOD | URI | 1XX | 2XX | 3XX | 4XX | 5XX | MIN | MAX | SUM | AVG | P1 | P50 | P99 | STDDEV | MIN(BODY) | MAX(BODY) | SUM(BODY) | AVG(BODY) |
+-------+--------+-------------------------------------+-----+------+-----+-----+-----+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+
| 1 | GET | /static/js/2.ff6e1067.chunk.js | 0 | 1 | 0 | 0 | 0 | 0.016 | 0.016 | 0.016 | 0.016 | 0.016 | 0.016 | 0.016 | 0.000 | 508459.000 | 508459.000 | 508459.000 | 508459.000 |
| 1 | GET | /static/js/runtime~main.a8a9905a.js | 0 | 1 | 0 | 0 | 0 | 0.024 | 0.024 | 0.024 | 0.024 | 0.024 | 0.024 | 0.024 | 0.000 | 1502.000 | 1502.000 | 1502.000 | 1502.000 |
| 1 | GET | /reports.json | 0 | 1 | 0 | 0 | 0 | 0.032 | 0.032 | 0.032 | 0.032 | 0.032 | 0.032 | 0.032 | 0.000 | 143390.000 | 143390.000 | 143390.000 | 143390.000 |
| 50 | GET | /transactions/\d+.png | 0 | 40 | 0 | 10 | 0 | 0.008 | 0.080 | 0.544 | 0.011 | 0.008 | 0.012 | 0.012 | 0.015 | 32.000 | 623.000 | 24890.000 | 497.800 |
| 11 | POST | /items/edit | 0 | 6 | 0 | 5 | 0 | 0.004 | 0.116 | 0.304 | 0.028 | 0.028 | 0.000 | 0.048 | 0.033 | 57.000 | 92.000 | 835.000 | 75.909 |
| 56 | GET | /upload/.+.jpg | 0 | 56 | 0 | 0 | 0 | 0.004 | 0.180 | 2.994 | 0.053 | 0.084 | 0.068 | 0.008 | 0.043 | 51574.000 | 146187.000 | 4706042.000 | 84036.464 |
| 1 | GET | /static/css/main.19393e92.chunk.css | 0 | 1 | 0 | 0 | 0 | 0.192 | 0.192 | 0.192 | 0.192 | 0.192 | 0.192 | 0.192 | 0.000 | 994.000 | 994.000 | 994.000 | 994.000 |
| 1 | GET | /static/js/main.babc3d4d.chunk.js | 0 | 1 | 0 | 0 | 0 | 0.520 | 0.520 | 0.520 | 0.520 | 0.520 | 0.520 | 0.520 | 0.000 | 90365.000 | 90365.000 | 90365.000 | 90365.000 |
| 13 | POST | /bump | 0 | 13 | 0 | 0 | 0 | 0.004 | 0.529 | 1.821 | 0.140 | 0.156 | 0.028 | 0.080 | 0.164 | 89.000 | 91.000 | 1168.000 | 89.846 |
| 52 | GET | /settings | 0 | 52 | 0 | 0 | 0 | 0.008 | 0.568 | 7.472 | 0.144 | 0.044 | 0.320 | 0.040 | 0.153 | 3086.000 | 3103.000 | 160855.000 | 3093.365 |
| 60 | POST | /login | 0 | 52 | 0 | 8 | 0 | 0.100 | 0.740 | 22.886 | 0.381 | 0.576 | 0.452 | 0.184 | 0.190 | 72.000 | 269.000 | 14063.000 | 234.383 |
| 55 | POST | /ship_done | 0 | 39 | 0 | 16 | 0 | 0.004 | 0.896 | 33.709 | 0.613 | 0.016 | 0.004 | 0.853 | 0.360 | 0.000 | 82.000 | 2017.000 | 36.673 |
| 65 | POST | /sell | 0 | 50 | 0 | 15 | 0 | 0.004 | 0.936 | 8.002 | 0.123 | 0.068 | 0.016 | 0.080 | 0.208 | 12.000 | 105.000 | 1790.000 | 27.538 |
| 390 | GET | /users/\d+.json | 0 | 386 | 0 | 4 | 0 | 0.007 | 0.944 | 94.877 | 0.243 | 0.144 | 0.280 | 0.225 | 0.153 | 0.000 | 23864.000 | 5174034.000 | 13266.754 |
| 50 | POST | /ship | 0 | 40 | 0 | 10 | 0 | 0.004 | 0.948 | 31.514 | 0.630 | 0.016 | 0.829 | 0.849 | 0.361 | 28.000 | 60.000 | 2720.000 | 54.400 |
| 38 | POST | /complete | 0 | 37 | 0 | 1 | 0 | 0.008 | 1.117 | 30.578 | 0.805 | 0.192 | 0.844 | 0.888 | 0.228 | 0.000 | 33.000 | 1221.000 | 32.132 |
| 128 | GET | /new_items.json | 0 | 128 | 0 | 0 | 0 | 0.212 | 1.509 | 69.956 | 0.547 | 0.212 | 0.372 | 0.369 | 0.185 | 22988.000 | 23744.000 | 2994285.000 | 23392.852 |
| 788 | GET | /new_items/\d+.json | 0 | 785 | 0 | 3 | 0 | 0.044 | 1.857 | 214.928 | 0.273 | 0.044 | 0.112 | 0.296 | 0.148 | 0.000 | 24021.000 | 18454159.000 | 23418.984 |
| 2932 | GET | /items/\d+.json | 0 | 2932 | 0 | 0 | 0 | 0.008 | 1.857 | 37.309 | 0.013 | 0.080 | 0.004 | 0.012 | 0.040 | 1851.000 | 4052.000 | 6539101.000 | 2230.253 |
| 61 | POST | /buy | 0 | 41 | 0 | 20 | 0 | 0.076 | 1.865 | 70.834 | 1.161 | 0.040 | 1.725 | 1.657 | 0.754 | 28.000 | 48.000 | 2118.000 | 34.721 |
| 414 | GET | /users/transactions.json | 0 | 409 | 0 | 5 | 0 | 0.024 | 2.341 | 256.159 | 0.619 | 0.216 | 1.160 | 0.340 | 0.411 | 0.000 | 27197.000 | 8797561.000 | 21250.147 |
| 1 | POST | /initialize | 0 | 1 | 0 | 0 | 0 | 8.213 | 8.213 | 8.213 | 8.213 | 8.213 | 8.213 | 8.213 | 0.000 | 32.000 | 32.000 | 32.000 | 32.000 |
+-------+--------+-------------------------------------+-----+------+-----+-----+-----+-------+-------+---------+-------+-------+-------+-------+--------+------------+------------+--------------+------------+
INDEXを張る
itemsテーブルのseller_id、buyer_id、created_atにINDEXを張ってみます。
還元率を変更してみる
当日はルールへの理解が足りず着手しなかったのですが、postInitializeのレスポンスにあるcampaignの数値を変更することで負荷が上がるようです。
試しに0 → 1に変更してベンチマークを実行した結果が以下のものです。
{
"pass": true,
"score": 7240,
"campaign": 1,
"language": "ruby",
"messages": [
"GET /new_items.json: リクエストに失敗しました（タイムアウトしました）",
"GET /users/transactions.json リクエストに失敗しました (user_id: 3197)（タイムアウトしました）",
"POST /login: リクエストに失敗しました（タイムアウトしました）",
"POST /ship: リクエストに失敗しました (item_id: 50041)（タイムアウトしました）"
]
}
タイムアウトが増えますが、スコアは上がっています。
まとめ
1台構成ですが、予選通過ラインに肉薄するスコアが出るようになってきました。
本番の8時間でこれらを実施するのは大変ですが、来年は予選通過できるよう精進したいと思います。