Zenn
Open5

ISUCON12予選練習の備忘録

ISUCON
おそらく犬おそらく犬

いざ実食

systemdで起動するサーバをgoに変更し、とりあえずbenchを回してみる

~省略~
[ADMIN] 06:33:45.439935 負荷走行を終了しました
[ADMIN] 06:33:46.440691 ScenarioScoreMap: map[string]int64{
  "AdminBilling":            6,
  "AdminBillingValidate":    65,
  "OrganizerNewTenant":      82,
  "OrganizerPeacefulTenant": 0,
  "OrganizerPopularTenant":  72,
  "Player":                  193,
  "PlayerValidate":          176,
  "TenantBillingValidate":   189,
}
[ADMIN] 06:33:46.440786 WorkerCount: map[string]int{
  "AdminBillingScenarioWorker":   1,
  "AdminBillingValidateWorker":   1,
  "NewTenantScenarioWorker":      1,
  "PlayerScenarioWorker":         26,
  "PlayerValidateScenarioWorker": 1,
  "PopularTenantScenarioWorker":  1,
  "TenantBillingValidateWorker":  1,
}
06:33:46.440812 Error 0 (Critical:0)
06:33:46.440828 PASSED: true
06:33:46.440831 SCORE: 783 (+783 0(0%))
[ADMIN] 06:33:46.440950 score.ScoreTable{
  "GET /api/admin/tenants/billing":                         9,
  "GET /api/organizer/billing":                             5,
  "GET /api/organizer/players/list":                        10,
  "GET /api/player/competition/:competition_id/ranking":    135,
  "GET /api/player/competitions":                           38,
  "GET /api/player/player/:player_name":                    138,
  "POST /api/admin/tenants/add":                            2,
  "POST /api/organizer/competition/:competition_id/finish": 9,
  "POST /api/organizer/competition/:competition_id/score":  12,
  "POST /api/organizer/competitions/add":                   14,
  "POST /api/organizer/player/:player_name/disqualified":   3,
  "POST /api/organizer/players/add":                        3,
}
[ADMIN] 06:33:46.441015 ScenarioCount: map[bench.ScenarioTag]string{
  "AdminBilling":            "count: 1 (error: 0)",
  "AdminBillingValidate":    "count: 2 (error: 0)",
  "OrganizerNewTenant":      "count: 1 (error: 0)",
  "OrganizerPeacefulTenant": "count: 0 (error: 0)",
  "OrganizerPopularTenant":  "count: 1 (error: 0)",
  "Player":                  "count: 26 (error: 0)",
  "PlayerValidate":          "count: 4 (error: 0)",
  "TenantBillingValidate":   "count: 1 (error: 0)",
}

何度か試した後の記録だがソースは触ってない
本番ではスコアしか見えないので、その想定で触っていく

おそらく犬おそらく犬

推測するな、計測せよ

とりえあず遅いリクエストを計測するためnginxの設定を済ませ、alpをインスコし、計測をした
alpのconfigは本番では当然自分で記載する必要があるが、お手軽に始めるため常連さんの設定をパクらせていただく
https://github.com/oribe1115/isucon12-qualify/blob/main/tool-config/alp/config.yml

sudo rm /var/log/nginx/access.log && sudo service nginx restart

でアクセスログ削除 & nginx再起動した後、ベンチを回し、alpで集計する

+-------+-----+--------+-----------------------------------------------+-------+--------+----------+--------+--------+
| COUNT | 5XX | METHOD |                      URI                      |  MIN  |  MAX   |   SUM    |  AVG   |  P99   |
+-------+-----+--------+-----------------------------------------------+-------+--------+----------+--------+--------+
| 281   | 0   | GET    | /api/player/competition/[0-9a-f]+/ranking     | 0.030 | 30.000 | 1024.270 | 3.645  | 30.000 |
| 22    | 0   | POST   | /api/organizer/competition/[0-9a-f]+/score$   | 0.930 | 30.000 | 201.890  | 9.177  | 30.000 |
| 7     | 0   | POST   | /api/organizer/players/add$                   | 4.150 | 30.010 | 98.310   | 14.044 | 30.010 |
| 11    | 0   | GET    | /api/admin/tenants/billing                    | 4.500 | 19.310 | 93.770   | 8.525  | 19.310 |
| 204   | 0   | GET    | /api/player/player/[0-9a-f]+$                 | 0.010 | 0.190  | 5.050    | 0.025  | 0.140  |
| 14    | 0   | POST   | /api/organizer/competitions/add$              | 0.050 | 0.830  | 2.720    | 0.194  | 0.830  |
| 1     | 0   | POST   | /initialize$                                  | 2.340 | 2.340  | 2.340    | 2.340  | 2.340  |
| 12    | 0   | POST   | /api/admin/tenants/add$                       | 0.010 | 0.490  | 1.260    | 0.105  | 0.490  |
| 5     | 0   | GET    | /api/organizer/billing$                       | 0.000 | 0.700  | 1.010    | 0.202  | 0.700  |
| 8     | 0   | POST   | /api/organizer/competition/[0-9a-f]+/finish$  | 0.020 | 0.080  | 0.300    | 0.037  | 0.080  |
| 5     | 0   | POST   | /api/organizer/player/[0-9a-f]+/disqualified$ | 0.030 | 0.040  | 0.150    | 0.030  | 0.040  |
| 28    | 0   | GET    | /api/player/competitions$                     | 0.010 | 0.020  | 0.140    | 0.005  | 0.020  |
| 8     | 0   | GET    | /api/organizer/players$                       | 0.000 | 0.010  | 0.020    | 0.003  | 0.010  |
| 1     | 0   | GET    | /css/app.83b4c321.css                         | 0.000 | 0.000  | 0.000    | 0.000  | 0.000  |
| 1     | 0   | GET    | /js/app.3a4ec98c.js                           | 0.000 | 0.000  | 0.000    | 0.000  | 0.000  |
| 1     | 0   | GET    | /index.html                                   | 0.000 | 0.000  | 0.000    | 0.000  | 0.000  |
| 1     | 0   | GET    | /api/organizer/competitions$                  | 0.000 | 0.000  | 0.000    | 0.000  | 0.000  |
+-------+-----+--------+-----------------------------------------------+-------+--------+----------+--------+--------+

とりあえずalpでの集計は出来たっぽい、明らかに遅いエンドポイントがあるのでそこから改善していく

おそらく犬おそらく犬

とりあえず GET /api/player/competition/[0-9a-f]+/rankingが重たいことが分かるのでそちらを改善していくことにする

ソースを読むと典型的なN+1なので直す。playerもplayer_scoreも幸い同じsqlite3上にあるのでJOINが使えるので1発で取ってくるSQLを書いた
ついでにMySQLに対してslow query logを出力させるように設定

ベンチ後のalp出力

cat /var/log/nginx/access.log | alp json --config config/alp.yml 
+-------+-----+--------+-----------------------------------------------+-------+--------+----------+--------+--------+
| COUNT | 5XX | METHOD |                      URI                      |  MIN  |  MAX   |   SUM    |  AVG   |  P99   |
+-------+-----+--------+-----------------------------------------------+-------+--------+----------+--------+--------+
| 251   | 0   | GET    | /api/player/competition/[0-9a-f]+/ranking     | 0.020 | 26.680 | 1404.200 | 5.594  | 26.670 |
| 28    | 0   | POST   | /api/organizer/competition/[0-9a-f]+/score$   | 2.840 | 26.650 | 233.970  | 8.356  | 26.650 |
| 185   | 0   | GET    | /api/player/player/[0-9a-f]+$                 | 0.050 | 20.760 | 154.830  | 0.837  | 20.500 |
| 7     | 0   | POST   | /api/organizer/players/add$                   | 7.340 | 21.270 | 87.590   | 12.513 | 21.270 |
| 21    | 0   | GET    | /api/admin/tenants/billing                    | 1.460 | 20.990 | 78.710   | 3.748  | 20.990 |
| 1     | 0   | POST   | /initialize$                                  | 3.280 | 3.280  | 3.280    | 3.280  | 3.280  |
| 20    | 0   | POST   | /api/organizer/competitions/add$              | 0.020 | 0.280  | 1.960    | 0.098  | 0.280  |
| 12    | 0   | POST   | /api/admin/tenants/add$                       | 0.010 | 0.190  | 1.090    | 0.091  | 0.190  |
| 7     | 0   | GET    | /api/organizer/billing$                       | 0.010 | 0.250  | 0.490    | 0.070  | 0.250  |
| 14    | 0   | POST   | /api/organizer/competition/[0-9a-f]+/finish$  | 0.020 | 0.050  | 0.380    | 0.027  | 0.050  |
| 45    | 0   | GET    | /api/player/competitions$                     | 0.010 | 0.060  | 0.350    | 0.008  | 0.060  |
| 6     | 0   | POST   | /api/organizer/player/[0-9a-f]+/disqualified$ | 0.020 | 0.040  | 0.150    | 0.025  | 0.040  |
| 13    | 0   | GET    | /api/organizer/players$                       | 0.010 | 0.030  | 0.060    | 0.005  | 0.030  |
| 1     | 0   | GET    | /js/app.3a4ec98c.js                           | 0.000 | 0.000  | 0.000    | 0.000  | 0.000  |
| 1     | 0   | GET    | /index.html                                   | 0.000 | 0.000  | 0.000    | 0.000  | 0.000  |
| 1     | 0   | GET    | /css/app.83b4c321.css                         | 0.000 | 0.000  | 0.000    | 0.000  | 0.000  |
| 1     | 0   | GET    | /api/organizer/competitions$                  | 0.000 | 0.000  | 0.000    | 0.000  | 0.000  |
+-------+-----+--------+-----------------------------------------------+-------+--------+----------+--------+--------+

何かあんまり変わってない、別にボトルネックがありそう

おそらく犬おそらく犬

SQLite側に以下のようにINDEXを貼ってみる
既存のテナントDBに対してINDEX作る作業は30秒以内で終わるっぽく、init.shに書いても間に合うっぽい
Go側でテナントDB作るときにINDEXも同時に作るようにした

CREATE INDEX competition_idx ON competition(tenant_id);
CREATE INDEX player_idx ON player(tenant_id);
CREATE INDEX player_score_idx ON player_score(tenant_id, player_id, competition_id);

その後のalp

cat /var/log/nginx/access.log | alp json --config config/alp.yml 
+-------+-----+--------+-----------------------------------------------+--------+--------+----------+--------+--------+
| COUNT | 5XX | METHOD |                      URI                      |  MIN   |  MAX   |   SUM    |  AVG   |  P99   |
+-------+-----+--------+-----------------------------------------------+--------+--------+----------+--------+--------+
| 314   | 0   | GET    | /api/player/competition/[0-9a-f]+/ranking     | 0.020  | 28.640 | 1448.010 | 4.611  | 28.640 |
| 30    | 0   | POST   | /api/organizer/competition/[0-9a-f]+/score$   | 1.990  | 28.630 | 240.100  | 8.003  | 28.630 |
| 160   | 0   | GET    | /api/player/player/[0-9a-f]+$                 | 0.010  | 16.730 | 117.740  | 0.736  | 16.700 |
| 7     | 0   | POST   | /api/organizer/players/add$                   | 7.210  | 24.250 | 99.630   | 14.233 | 24.250 |
| 20    | 0   | GET    | /api/admin/tenants/billing                    | 1.220  | 16.300 | 74.740   | 3.737  | 16.300 |
| 1     | 0   | POST   | /initialize$                                  | 13.190 | 13.190 | 13.190   | 13.190 | 13.190 |
| 20    | 0   | POST   | /api/organizer/competitions/add$              | 0.060  | 0.270  | 2.100    | 0.105  | 0.270  |
| 12    | 0   | POST   | /api/admin/tenants/add$                       | 0.020  | 0.290  | 1.750    | 0.146  | 0.290  |
| 52    | 0   | GET    | /api/player/competitions$                     | 0.010  | 0.080  | 0.610    | 0.012  | 0.080  |
| 14    | 0   | POST   | /api/organizer/competition/[0-9a-f]+/finish$  | 0.020  | 0.040  | 0.370    | 0.026  | 0.040  |
| 7     | 0   | GET    | /api/organizer/billing$                       | 0.000  | 0.140  | 0.210    | 0.030  | 0.140  |
| 7     | 0   | POST   | /api/organizer/player/[0-9a-f]+/disqualified$ | 0.010  | 0.050  | 0.190    | 0.027  | 0.050  |
| 13    | 0   | GET    | /api/organizer/players$                       | 0.010  | 0.030  | 0.090    | 0.007  | 0.030  |
| 1     | 0   | GET    | /js/app.3a4ec98c.js                           | 0.000  | 0.000  | 0.000    | 0.000  | 0.000  |
| 1     | 0   | GET    | /index.html                                   | 0.000  | 0.000  | 0.000    | 0.000  | 0.000  |
| 1     | 0   | GET    | /css/app.83b4c321.css                         | 0.000  | 0.000  | 0.000    | 0.000  | 0.000  |
| 1     | 0   | GET    | /api/organizer/competitions$                  | 0.000  | 0.000  | 0.000    | 0.000  | 0.000  |
+-------+-----+--------+-----------------------------------------------+--------+--------+----------+--------+--------+

やっぱり変わらない
計測しないとこうなるという教訓かも