🪑

ISUCON2023備忘録

2023/11/29に公開

Ruby

ISUCON

tech

新卒同期のfumi, zakiとrubyでISUCON2023に参加したのでやったことなどを備忘録として残します！

リポジトリ: https://github.com/tnb23-ayataka/isucon13

結果

結果としては、11,298点で694チーム中211位でした。
このチームでISUCON初参加は自分以外の二人で、自分でも10,000点を超えたのは初めてだったのでとても嬉しかったです。
（チーム名はayataka）

当日

10:00

初動の役割分担は以下のようにしました。

otyamura: レギュレーション読み、デプロイスクリプト作成
fumi: gitへの初期実装push、alp設定
zaki: ruby実装への切り替え、datadog導入

上記の初期の作業を終了させ、実際の作業を各々が開始し始めるまで1時間かからずにできたと思います。
最初に走らせたベンチは3,102点でした。
ただ、サーバ３台のうち、ベンチに成功したサーバが１台しかなくて少し焦りました。
原因としては、内部のdnsサーバが返すIPが違ったためで、当日マニュアルに載っていたコマンドを打つことで直りました

$ pdnsutil delete-zone u.isucon.dev
$ sudo rm -f /opt/aws-env-isucon-subdomain-address.sh.lock
$ sudo reboot # 再起動します

11:00

ここら辺から各自でalpの結果を見たり、pt-query-digestの結果を見たりして、エンドポイントごとに高速化を始めました。

alpの結果

+-------+--------+---------------------------------+--------+--------+--------+---------+
| COUNT | METHOD |               URI               |  MIN   |  AVG   |  MAX   |   SUM   |
+-------+--------+---------------------------------+--------+--------+--------+---------+
| 195   | GET    | /api/livestream/\w+/livecomment | 0.004  | 0.879  | 3.248  | 171.440 |
| 227   | GET    | /api/livestream/\w+/reaction    | 0.004  | 0.668  | 3.360  | 151.580 |
| 35    | GET    | /api/livestream/\w+             | 0.012  | 4.115  | 12.096 | 144.016 |
| 6     | GET    | /api/user/\w+/statistics        | 3.596  | 14.533 | 20.000 | 87.196  |
| 14    | POST   | /api/livestream/\w+/moderate    | 0.352  | 5.787  | 13.664 | 81.024  |
| 252   | POST   | /api/livestream/\w+/livecomment | 0.008  | 0.214  | 0.400  | 53.916  |
| 216   | POST   | /api/register                   | 0.004  | 0.231  | 0.616  | 50.004  |
| 72    | POST   | /api/livestream/\w+             | 0.004  | 0.659  | 1.720  | 47.440  |
| 1740  | GET    | /api/user/\w+/icon              | 0.004  | 0.017  | 0.120  | 29.956  |
| 185   | POST   | /api/livestream/\w+/reaction    | 0.012  | 0.105  | 0.316  | 19.368  |
| 32    | GET    | /api/livestream/\w+/statistics  | 0.000  | 0.491  | 7.692  | 15.720  |
| 1     | POST   | /api/initialize                 | 11.008 | 11.008 | 11.008 | 11.008  |
| 211   | POST   | /api/icon                       | 0.012  | 0.047  | 0.212  | 9.972   |
| 48    | GET    | /api/livestream                 | 0.016  | 0.095  | 0.592  | 4.540   |
| 15    | GET    | /api/livestream/\w+/report      | 0.004  | 0.250  | 1.756  | 3.744   |
| 220   | POST   | /api/login                      | 0.004  | 0.013  | 0.060  | 2.844   |
| 52    | GET    | /api/tag                        | 0.004  | 0.015  | 0.204  | 0.804   |
| 12    | GET    | /api/livestream/\w+/ngwords     | 0.008  | 0.065  | 0.152  | 0.780   |
| 23    | POST   | /api/livestream/\w+/enter       | 0.008  | 0.023  | 0.064  | 0.532   |
| 13    | DELETE | /api/livestream/\w+/exit        | 0.008  | 0.020  | 0.044  | 0.260   |
| 5     | GET    | /api/user/\w+/theme             | 0.004  | 0.029  | 0.048  | 0.144   |
| 4     | GET    | /api/user/me                    | 0.004  | 0.006  | 0.008  | 0.024   |
| 1     | GET    | /api/user/test                  | 0.004  | 0.004  | 0.004  | 0.004   |
| 1     | GET    | /api/payment                    | 0.004  | 0.004  | 0.004  | 0.004   |
+-------+--------+---------------------------------+--------+--------+--------+---------+

pt-query-digestの結果

# Profile
# Rank Query ID                      Response time  Calls R/Call V/M   Ite
# ==== ============================= ============== ===== ====== ===== ===
#    1 0xF7144185D9A142A426A36DC5... 305.4246 35.7%  6374 0.0479  0.02 SELECT livestream_tags
#    2 0x84B457C910C4A79FC9EBECB8... 125.1188 14.6% 12151 0.0103  0.02 SELECT icons
#    3 0xF1B8EF06D6CA63B24BFF433E...  82.0603  9.6%  6391 0.0128  0.03 SELECT users livestreams livecomments
#    4 0xDB74D52D39A7090F224C4DEE...  76.8844  9.0%  6391 0.0120  0.03 SELECT users livestreams reactions
#    5 0x4ADE2DC90689F1C4891749AF...  56.5055  6.6% 29361 0.0019  0.00 DELETE SELECT livecomments
#    6 0x38BC86A45F31C6B1EE324671...  40.6553  4.7% 10035 0.0041  0.01 SELECT themes
#    7 0xFBC5564AE716EAE82F20BFB4...  30.7470  3.6% 23004 0.0013  0.00 SELECT tags
#    8 0x59F1B6DD8D9FEC059E55B3BF...  30.2672  3.5%   583 0.0519  0.01 SELECT reservation_slots
#    9 0xFFFCA4D67EA0A788813031B8...  18.9011  2.2%  4548 0.0042  0.01 COMMIT
#   10 0x64CC8A4E8E4B390203375597...  11.0376  1.3%   272 0.0406  0.02 SELECT ng_words
#   11 0xEA1E6309EEEFF9A6831AD2FB...  10.4642  1.2%  9793 0.0011  0.00 SELECT users
#   12 0x859BBB7E9D760686137A9444...   8.3773  1.0%   236 0.0355  0.01 DELETE records
#   13 0xA3401CA3ABCC04C3AB221DB8...   8.0636  0.9%    76 0.1061  0.06 UPDATE reservation_slots
#   14 0xD6032FE08E1FE706A928B8B7...   5.6248  0.7%  5340 0.0011  0.01 SELECT livestreams
#   15 0xFD38427AE3D09E3883A680F7...   4.8282  0.6% 14992 0.0003  0.00 SELECT livestreams livecomments
# MISC 0xMISC                         41.4600  4.8% 36360 0.0011   0.0 <76 ITEMS>

zakiがreactionテーブルにindexを貼る

その後、initilizeでindexが既にある旨のエラーが出るようになったのでdropするように追加

(indexにif existみたいな構文が欲しい…)

zaki,reactionテーブルにもindex

fumi,livecommentsにindex

otyamura,livestream_tagsにindex

この時点で4534点くらいだったらしい

otyamura, livestreamsにindex

点はほとんど変化なしで4149点

12:00

alp

特に変化なし（ちょっとだけSUMが減っている）

+-------+--------+---------------------------------+--------+--------+--------+---------+
| COUNT | METHOD |               URI               |  MIN   |  AVG   |  MAX   |   SUM   |
+-------+--------+---------------------------------+--------+--------+--------+---------+
| 299   | GET    | /api/livestream/\w+/livecomment | 0.004  | 0.522  | 2.104  | 155.952 |
| 332   | GET    | /api/livestream/\w+/reaction    | 0.004  | 0.440  | 2.160  | 146.032 |
| 53    | GET    | /api/livestream/\w+             | 0.008  | 1.901  | 4.708  | 100.768 |
| 8     | GET    | /api/user/\w+/statistics        | 2.824  | 11.195 | 20.000 | 89.564  |
| 14    | POST   | /api/livestream/\w+/moderate    | 0.340  | 5.911  | 13.132 | 82.748  |
| 142   | POST   | /api/register                   | 0.004  | 0.526  | 0.948  | 74.648  |
| 2365  | GET    | /api/user/\w+/icon              | 0.004  | 0.028  | 0.304  | 65.520  |
| 331   | POST   | /api/livestream/\w+/livecomment | 0.012  | 0.171  | 0.392  | 56.516  |
| 96    | POST   | /api/livestream/\w+             | 0.004  | 0.492  | 1.312  | 47.200  |
| 280   | POST   | /api/livestream/\w+/reaction    | 0.008  | 0.102  | 0.420  | 28.672  |
| 2     | POST   | /api/initialize                 | 12.560 | 12.754 | 12.948 | 25.508  |
| 2     | GET    | /api/livestream/\w+/statistics  | 4.920  | 4.922  | 4.924  | 9.844   |
| 140   | POST   | /api/icon                       | 0.024  | 0.067  | 0.324  | 9.348   |
| 48    | GET    | /api/livestream/\w+/report      | 0.004  | 0.088  | 1.024  | 4.216   |
| 148   | POST   | /api/login                      | 0.004  | 0.023  | 0.200  | 3.472   |
| 97    | GET    | /api/livestream                 | 0.004  | 0.032  | 0.468  | 3.108   |
| 30    | GET    | /api/livestream/\w+/ngwords     | 0.008  | 0.075  | 0.160  | 2.260   |
| 75    | GET    | /api/tag                        | 0.004  | 0.026  | 0.148  | 1.964   |
| 33    | POST   | /api/livestream/\w+/enter       | 0.012  | 0.033  | 0.216  | 1.088   |
| 23    | DELETE | /api/livestream/\w+/exit        | 0.008  | 0.029  | 0.080  | 0.656   |
| 2     | GET    | /api/user/hyoshida0/livestream  | 0.160  | 0.214  | 0.268  | 0.428   |
| 1     | GET    | /api/user/ryohei000/livestream  | 0.256  | 0.256  | 0.256  | 0.256   |
| 2     | GET    | /api/payment                    | 0.008  | 0.118  | 0.228  | 0.236   |
| 6     | GET    | /api/user/\w+/theme             | 0.008  | 0.030  | 0.060  | 0.180   |
| 1     | GET    | /api/user/jshimizu0/livestream  | 0.128  | 0.128  | 0.128  | 0.128   |
| 3     | GET    | /api/user/me                    | 0.004  | 0.004  | 0.004  | 0.012   |
| 1     | GET    | /api/user/test                  | 0.004  | 0.004  | 0.004  | 0.004   |
+-------+--------+---------------------------------+--------+--------+--------+---------+

13:00

otyamura, reactionのN+1を修正

このあたりからベンチマーカーがトラブルで動かなくなってきて、デバッグがしづらく停滞し気味に

14:00

ベンチが動いてない間にindexを貼ってくれていた

fumi, iconにindexを追加

fumi, themesにindexを追加

fumi, livestream_viewers_historyにindexを追加

15:00

fumi, livecommentのn+1を修正

otyamura, reactionのn+1を修正

多分このあたりでだいぶ点数が上がって8375点が出ていた

そしてだいぶalpに変化が出てきて、livecommentとreactionが上位を占めなくなってきていた

+-------+--------+---------------------------------+--------+--------+--------+---------+
| COUNT | METHOD |               URI               |  MIN   |  AVG   |  MAX   |   SUM   |
+-------+--------+---------------------------------+--------+--------+--------+---------+
| 54    | GET    | /api/livestream/search          | 0.084  | 3.081  | 8.116  | 166.356 |
| 4206  | GET    | /api/user/\w+/icon              | 0.004  | 0.030  | 0.804  | 127.732 |
| 9     | GET    | /api/user/\w+/statistics        | 2.772  | 12.060 | 18.796 | 108.536 |
| 147   | POST   | /api/register                   | 0.004  | 0.604  | 1.188  | 88.808  |
| 506   | GET    | /api/livestream/\d+/reaction    | 0.004  | 0.171  | 0.828  | 86.632  |
| 487   | POST   | /api/livestream/\d+/livecomment | 0.008  | 0.176  | 0.548  | 85.880  |
| 11    | POST   | /api/livestream/\d+/moderate    | 0.344  | 7.240  | 10.980 | 79.640  |
| 439   | POST   | /api/livestream/\d+/reaction    | 0.008  | 0.127  | 0.452  | 55.692  |
| 118   | POST   | /api/livestream/reservation     | 0.004  | 0.438  | 1.196  | 51.676  |
| 469   | GET    | /api/livestream/\d+/livecomment | 0.004  | 0.069  | 0.312  | 32.324  |
| 146   | POST   | /api/icon                       | 0.016  | 0.090  | 1.668  | 13.088  |
| 1     | POST   | /api/initialize                 | 10.788 | 10.788 | 10.788 | 10.788  |
| 2     | GET    | /api/livestream/\d+/statistics  | 5.112  | 5.186  | 5.260  | 10.372  |
| 151   | POST   | /api/login                      | 0.004  | 0.026  | 0.180  | 3.956   |
| 76    | GET    | /api/livestream                 | 0.004  | 0.045  | 0.652  | 3.392   |
| 39    | GET    | /api/livestream/\d+/report      | 0.004  | 0.072  | 1.192  | 2.804   |
| 101   | GET    | /api/tag                        | 0.004  | 0.019  | 0.212  | 1.952   |
| 48    | POST   | /api/livestream/\d+/enter       | 0.008  | 0.038  | 0.304  | 1.828   |
| 25    | GET    | /api/livestream/\d+/ngwords     | 0.008  | 0.072  | 0.300  | 1.804   |
| 5     | GET    | /api/user/\w+/livestream        | 0.168  | 0.318  | 0.668  | 1.588   |
| 41    | DELETE | /api/livestream/\d+/exit        | 0.008  | 0.030  | 0.100  | 1.244   |
| 8     | GET    | /api/user/\w+/theme             | 0.004  | 0.032  | 0.104  | 0.256   |
| 1     | GET    | /api/payment                    | 0.208  | 0.208  | 0.208  | 0.208   |
| 1     | GET    | /api/livestream/\d+             | 0.008  | 0.008  | 0.008  | 0.008   |
| 3     | GET    | /api/user/me                    | 0.004  | 0.003  | 0.004  | 0.008   |
| 1     | GET    | /api/user/test                  | 0.004  | 0.004  | 0.004  | 0.004   |
| 1     | GET    | /favicon.ico                    | 0.000  | 0.000  | 0.000  | 0.000   |
| 2     | GET    | /ws/btcusdt@depth@0ms           | 0.000  | 0.000  | 0.000  | 0.000   |
+-------+--------+---------------------------------+--------+--------+--------+---------+

16:00

fumiとotyamuraは引き続きアプリ側を担当して、zakiがインフラ側の調整をし始めてくれていた

zaki, nginx.confの設定

zaki, mysql.confの設定

17:00

fumi, iconをmysqlから毎回持ってこないようにキャッシュさせるようにしてくれた

ここで10,390までのびる

アプリケーション側はもういじらないようにして、appとdbで分散する設定をし始める

17:45 ~

app側とdbを分離したりdatadogを削除したりしてなんとか17:49で設定が終わる
この時点で11,462点

思ったより伸びなくてなんでだろうという疑問はあったが、再起動試験を行なっていなかったので急いで再起動を行う

すると、iconのキャッシュで、initializeの時に画像を全て消しておかないとエラーが発生してしまうことに気づき、急いで修正を行なった
この時点で17:52

めちゃくちゃ焦っていたが、すぐにinit.shに追記し事なきを得る

無事に再起動試験も通ってそうだったので、app側でなんとなくhtopをしてみるとapp側なのにmysqlがcpu 80%くらいの負荷を持っていることに気づく

この時で17:58くらい

DBのみ動かしているサーバ側にもきちんと負荷がかかっており、appとdbを分けられているだろうとは思っていた。
しかしここで、PowerDNSがmysqlを使っていることを思い出し、検索をかける。

arch wikiでmysql-hostを変更できることを知る。https://wiki.archlinux.jp/index.php/PowerDNS

この時で17:59

流石に設定変更は無理だと思い、諦めて終了。

反省・感想

もっとしっかりレギュレーションや本番マニュアルと向き合うべきだった
サーバ分散は最後に突貫工事でやるべきではなかった
railsに頼って純粋にrubyを書く力が足りないと思った
- 検索とかしちゃうので特にスピード
alpやdatadogを見ながらは非常にやりやすかった
ちゃんと気づいておけば少なくともDNSのmysqlを分散させるはできた気がするから本当に悔しい
後々見たらチームで使ってたslackチャンネルに貼っていたpt-query-digestの結果に思いっきりSELECT recordsがslow-queryとして上がっていた

# Profile
# Rank Query ID                      Response time Calls R/Call V/M   Item
# ==== ============================= ============= ===== ====== ===== ====
#    1 0x42EF7D7D98FBCC9723BF896E... 99.4866 16.5% 14141 0.0070  0.01 SELECT records
#    2 0x3D83BC87F3B3A00D571FFC81... 58.6921  9.8% 10335 0.0057  0.01 SELECT records
#    3 0x84B457C910C4A79FC9EBECB8... 55.9355  9.3% 25739 0.0022  0.01 SELECT icons
#    4 0xDFFCC1D78939C4D781C7C583... 41.3090  6.9% 10000 0.0041  0.00 INSERT users
#    5 0x59F1B6DD8D9FEC059E55B3BF... 40.1903  6.7%  1812 0.0222  0.02 SELECT reservation_slots
#    6 0xD2A0864774622BA36F655749... 39.3184  6.5% 10310 0.0038  0.00 INSERT themes
#    7 0xFFFCA4D67EA0A788813031B8... 26.2600  4.4% 12003 0.0022  0.01 COMMIT
#    8 0xF1B8EF06D6CA63B24BFF433E... 24.4865  4.1% 20925 0.0012  0.01 SELECT users livestreams livecomments
#    9 0x64CC8A4E8E4B390203375597... 24.4816  4.1%   725 0.0338  0.01 SELECT ng_words
#   10 0x8F7679D452333ED3C7D60D22... 19.6688  3.3% 52857 0.0004  0.01 ADMIN RESET STMT
#   11 0x38BC86A45F31C6B1EE324671... 18.5819  3.1% 19129 0.0010  0.01 SELECT themes
#   12 0xDB74D52D39A7090F224C4DEE... 15.5716  2.6% 20925 0.0007  0.00 SELECT users livestreams reactions
#   13 0x22279D81D51006139E0C7640... 14.6305  2.4% 17092 0.0009  0.01 SELECT domains domainmetadata
#   14 0x4ADE2DC90689F1C4891749AF... 13.9403  2.3% 31538 0.0004  0.00 DELETE SELECT livecomments
#   15 0xA3401CA3ABCC04C3AB221DB8... 11.5916  1.9%   238 0.0487  0.04 UPDATE reservation_slots
#   16 0xFBC5564AE716EAE82F20BFB4... 11.5874  1.9% 46060 0.0003  0.00 SELECT tags
#   17 0xFD38427AE3D09E3883A680F7...  7.9467  1.3% 59968 0.0001  0.00 SELECT livestreams livecomments
#   18 0xC499D81D570D361DB61FC43A...  7.5111  1.2% 59968 0.0001  0.00 SELECT livestreams reactions
#   19 0xD03788039658A179C9D1F060...  7.1253  1.2%   469 0.0152  0.07 SELECT users themes icons
#   20 0x7F9C0C0BA9473953B723EE16...  6.9406  1.2%   240 0.0289  0.02 SELECT reservation_slots
# MISC 0xMISC                        56.2307  9.3% 93089 0.0006   0.0 <96 ITEMS>

pryとか使ってdebugもしたけどベンチ動かして見落としたコードのエラーとか結構あるからgo使いたい気持ちもちょっと出てきた
- でもrubyは書き慣れてきたし好きではあるので惜しい
- 力が足りない…力が欲しい…あと5000兆円も…