今年も ISUCON が開催されたので予選に参加しました。
色々忙しくてブログに起こすのに時間がかかってしまいましたが、来年のためにしっかりやったことを記録しておきます。
予選までにやったこと
さくらインターネットさんが参加者にクーポンを発行してくださっていたので、VPS を使って過去問を解いたりしていました。
内容としては MySQL の slow query の設定であったり、 nginx のログフォーマットを変えて alp で解析できるようにするなど、大会開始後にやる下準備をスムーズにできるように練習したりドキュメントにまとめたりしていました。
あとは、 普段 MongoDB しか使ってないせいで MySQL の作法をほぼ覚えてないので、 index の見方や貼り方なども一通り復習してよく使うクエリとかはドキュメントにまとめたりしていました。
今年は複数台のインスタンスを活用しようと思って、インスタンスを２台立てて１台を MySQL サーバー用でもう一台をアプリケーションサーバー用にして、アプリケーションから外のMySQL に接続しにいく練習などもしました。
当日
細かい時間などは記録していなかったので、やったこと順で記述していこうと思います。
言語の切り替え
まずはセットアップを完了したら、初期設定の Go でベンチを試しました。
初期スコアを記録していませんでしたが、 3000 ちょっとくらいのスコアでした。
次に Node.js 実装に切り替えてベンチを実行しました。
一気に 2500 くらいまでスコアが下がって少し悲しくなりましたが、Node.js の名誉のためこのまま Node.js 実装で進みました。
コードのバージョン管理
まずは作業に入る前に、コードを git 管理して github 上に push しました。
github.com
DB の設定などは面倒だったので別リポジトリに分けて管理しました。
github.com
基本的に作業単位でブランチを切って PR 作成して、セルフマージするスタイルで進めていました。
visit_history のインデックス追加
alp や MySQL の slow query log の設定をしたところで、とりあえず pt-query-digest を使って slow query の集計をしてみました。
初期の状態だと、 visit_history の SELECT がかなり遅かったので、
# Profile # Rank Query ID Response time Calls R/Call V/M # ==== =================================== ============== ===== ====== === # 1 0x676347F321DB8BC7FCB05D4948FC2248 120.8258 55.1% 1311 0.0922 0.06 SELECT visit_history # 2 0x94A9E43DFAAFA029A1FC19A5563AD0F5 91.4036 41.7% 8626 0.0106 0.00 REPLACE id_generator # MISC 0xMISC 7.0060 3.2% 2393 0.0029 0.0 <11 ITEMS>
解析結果の詳細を確認しつつコードの方も見て、
# Query 1: 16.39 QPS, 1.51x concurrency, ID 0x676347F321DB8BC7FCB05D4948FC2248 at byte 1400628 # This item is included in the report because it matches --limit. # Scores: V/M = 0.06 # Time range: 2022-07-23T02:34:33 to 2022-07-23T02:35:53 # Attribute pct total min max avg 95% stddev median # ============ === ======= ======= ======= ======= ======= ======= ======= # Count 10 1311 # Exec time 55 121s 214us 563ms 92ms 230ms 76ms 65ms # Lock time 0 3ms 1us 306us 2us 2us 8us 1us # Rows sent 97 103.91k 0 199 81.16 174.84 51.71 62.76 # Rows examine 88 24.05M 0 49.19k 18.79k 49.01k 13.36k 13.78k # Query size 25 182.98k 141 144 142.92 136.99 0.73 136.99 # String: # Databases isuports # Hosts localhost # Users isucon # Query_time distribution # 1us # 10us # 100us #### # 1ms ### # 10ms ################################################################ # 100ms ###################################### # 1s # 10s+ # Tables # SHOW TABLE STATUS FROM `isuports` LIKE 'visit_history'\G # SHOW CREATE TABLE `isuports`.`visit_history`\G # EXPLAIN /*!50100 PARTITIONS*/ SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = 79 AND competition_id = '55bf3a2d2' GROUP BY player_id\G
とりあえず tenant_id と competition_id の複合index を貼りました。
結果はベンチを回すたびにばらついていましたが、2452 -> 2699 と思ったより上がりませんでした。
ただ、Count が 1311 から 2801 に上がっていたのと、 query_time distribution も 10ms の分布が一番多かったが 1ms の分布に移っていたので、結構効果自体はあると判断してそのまま先へ進みました。
# Query 2: 38.37 QPS, 0.65x concurrency, ID 0x676347F321DB8BC7FCB05D4948FC2248 at byte 2910547 # This item is included in the report because it matches --limit. # Scores: V/M = 0.34 # Time range: 2022-07-23T03:02:40 to 2022-07-23T03:03:53 # Attribute pct total min max avg 95% stddev median # ============ === ======= ======= ======= ======= ======= ======= ======= # Count 21 2801 # Exec time 34 48s 218us 2s 17ms 36ms 76ms 7ms # Lock time 0 6ms 1us 64us 1us 2us 2us 1us # Rows sent 98 329.53k 0 4.88k 120.47 174.84 367.49 80.10 # Rows examine 62 5.15M 0 78.96k 1.88k 2.76k 5.78k 1.26k # Query size 42 391.02k 141 144 142.95 136.99 0.71 136.99 # String: # Databases isuports # Hosts localhost # Users isucon # Query_time distribution # 1us # 10us # 100us ##### # 1ms ################################################################ # 10ms ########################################### # 100ms # # 1s # # 10s+ # Tables # SHOW TABLE STATUS FROM `isuports` LIKE 'visit_history'\G # SHOW CREATE TABLE `isuports`.`visit_history`\G # EXPLAIN /*!50100 PARTITIONS*/ SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = 1 AND competition_id = '547f03113' GROUP BY player_id\G
[GET] /api/player/player/[0-9a-z]+ api の改善
次に alp の結果を眺めつつ、さっと直せそうな場所を探して、
+-------+-----+-----+-----+-----+-----+--------+----------------------------------------------+-------+--------+--------+----------+--------+ | COUNT | 1XX | 2XX | 3XX | 4XX | 5XX | METHOD | URI | MIN | MAX | AVG | SUM | P99 | +-------+-----+-----+-----+-----+-----+--------+----------------------------------------------+-------+--------+--------+----------+--------+ | 537 | 0 | 498 | 0 | 39 | 0 | GET | /api/player/competition/[0-9a-z]+/ranking | 0.004 | 14.488 | 1.889 | 1014.383 | 13.556 | | 461 | 0 | 432 | 0 | 29 | 0 | GET | /api/player/player/[0-9a-z]+ | 0.004 | 15.336 | 1.679 | 774.176 | 13.724 | | 106 | 0 | 95 | 0 | 11 | 0 | GET | /api/player/competitions | 0.004 | 0.112 | 0.026 | 2.804 | 0.108 | | 55 | 0 | 47 | 0 | 8 | 0 | POST | /api/organizer/competition/[0-9a-z]+/score | 0.004 | 13.140 | 2.788 | 153.356 | 13.140 | | 38 | 0 | 37 | 0 | 1 | 0 | POST | /api/organizer/competitions/add | 0.004 | 0.064 | 0.029 | 1.096 | 0.064 | | 34 | 0 | 33 | 0 | 1 | 0 | POST | /api/organizer/competition/[0-9a-z]+/finish | 0.004 | 0.048 | 0.019 | 0.644 | 0.048 | | 24 | 0 | 24 | 0 | 0 | 0 | GET | /api/organizer/players | 0.004 | 0.032 | 0.008 | 0.184 | 0.032 | | 20 | 0 | 20 | 0 | 0 | 0 | GET | /api/organizer/billing | 0.004 | 1.168 | 0.179 | 3.584 | 1.168 | | 14 | 0 | 13 | 0 | 1 | 0 | POST | /api/organizer/player/[0-9a-z]+/disqualified | 0.004 | 0.024 | 0.016 | 0.228 | 0.024 | | 11 | 0 | 6 | 0 | 5 | 0 | POST | /api/admin/tenants/add | 0.004 | 0.092 | 0.047 | 0.520 | 0.092 | | 10 | 0 | 8 | 0 | 2 | 0 | GET | /api/admin/tenants/billing | 3.720 | 25.909 | 11.587 | 115.870 | 25.909 | | 8 | 0 | 8 | 0 | 0 | 0 | POST | /api/organizer/players/add | 2.040 | 5.964 | 4.025 | 32.200 | 5.964 | | 1 | 0 | 1 | 0 | 0 | 0 | POST | /initialize | 2.648 | 2.648 | 2.648 | 2.648 | 2.648 | | 1 | 0 | 1 | 0 | 0 | 0 | GET | /css/app.83b4c321.css | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | | 1 | 0 | 1 | 0 | 0 | 0 | GET | /js/app.3a4ec98c.js | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | | 1 | 0 | 1 | 0 | 0 | 0 | GET | /index.html | 0.000 | 0.000 | 0.000 | 0.000 | 0.000 | | 1 | 0 | 1 | 0 | 0 | 0 | GET | /api/organizer/competitions | 0.004 | 0.004 | 0.004 | 0.004 | 0.004 | +-------+-----+-----+-----+-----+-----+--------+----------------------------------------------+-------+--------+--------+----------+--------+
[GET] /api/player/player/[0-9a-z]+ が結構叩かれていて、直せそうなところがあったので改善に取り組みました。
やったことは、player の詳細情報取得 api で、その player が属する tenant の competition を全て取得後に、 大会情報と 大会毎の player_score を for...of で1個ずつ直列に取得していたので、Promise.all を使って並列実行するように直しました。
今ブログを書きながらコードを見て思ったのですが、処理の最初の方で tenant に属する competision を全て取得してるので、ここで再度competisionを取得すること自体が無駄ですね。。
スコアはなぜか 2195 と落ちてしまいましたが、
+-------+-----+-----+-----+-----+-----+--------+----------------------------------------------+-------+--------+-------+----------+--------+ | COUNT | 1XX | 2XX | 3XX | 4XX | 5XX | METHOD | URI | MIN | MAX | AVG | SUM | P99 | +-------+-----+-----+-----+-----+-----+--------+----------------------------------------------+-------+--------+-------+----------+--------+ | 533 | 0 | 503 | 0 | 30 | 0 | GET | /api/player/player/[0-9a-z]+ | 0.004 | 19.148 | 1.301 | 693.451 | 14.260 |
リクエストの Count が増えていたのと、Latency も下がってはいたので、悪くはなっていないと判断して先にすすみました。
visit_history index の修正
最初の visit_history の index を貼ったことでそれなりに改善はしましたが、 pr-query-digest でみるとまだ SELECT visit_history が遅いようだったので、再度チューニングポイントがないか確認しました。
# Profile # Rank Query ID Response time Calls R/Call V/M # ==== =================================== ============== ===== ====== === # 1 0x94A9E43DFAAFA029A1FC19A5563AD0F5 111.6499 66.4% 8822 0.0127 0.01 REPLACE id_generator # 2 0x676347F321DB8BC7FCB05D4948FC2248 48.2423 28.7% 2908 0.0166 0.25 SELECT visit_history
該当のクエリはこういうクエリで、
SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = 1 AND competition_id = '547f03113' GROUP BY player_id\G
tenant_id と competition_id の複合index を貼っているので WHERE 句は index が効いてそうでしたが、player_id で GROUP BY している部分で index が効いてなさそうでした。
そのため、tenant_id と competition_id の複合index から、 tenant_id, competition_id, player_id の複合indexへ変更しました。
before
# Query 2: 39.30 QPS, 0.65x concurrency, ID 0x676347F321DB8BC7FCB05D4948FC2248 at byte 2728622 # Scores: V/M = 0.25 # Time range: 2022-07-23T04:07:39 to 2022-07-23T04:08:53 # Attribute pct total min max avg 95% stddev median # ============ === ======= ======= ======= ======= ======= ======= ======= # Count 19 2908 # Exec time 28 48s 173us 2s 17ms 40ms 65ms 7ms # Lock time 0 6ms 1us 129us 2us 2us 3us 1us # Rows sent 98 331.91k 0 4.88k 116.88 183.58 361.27 76.28 # Rows examine 62 5.17M 0 78.96k 1.82k 2.89k 5.68k 1.20k # Query size 40 405.93k 141 144 142.94 136.99 0.69 136.99 # String: # Databases isuports # Hosts localhost # Users isucon # Query_time distribution # 1us # 10us # 100us ####### # 1ms ################################################################ # 10ms ############################################### # 100ms # # 1s # # 10s+ # Tables # SHOW TABLE STATUS FROM `isuports` LIKE 'visit_history'\G # SHOW CREATE TABLE `isuports`.`visit_history`\G # EXPLAIN /*!50100 PARTITIONS*/ SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = 1 AND competition_id = '59cb9aad2' GROUP BY player_id\G
after
# Query 2: 40.55 QPS, 0.53x concurrency, ID 0x676347F321DB8BC7FCB05D4948FC2248 at byte 2180291 # Scores: V/M = 0.17 # Time range: 2022-07-23T05:56:48 to 2022-07-23T05:58:06 # Attribute pct total min max avg 95% stddev median # ============ === ======= ======= ======= ======= ======= ======= ======= # Count 23 3163 # Exec time 24 41s 184us 872ms 13ms 31ms 47ms 6ms # Lock time 0 10ms 0 5ms 3us 1us 82us 1us # Rows sent 98 365.81k 0 4.88k 118.43 183.58 346.65 80.10 # Rows examine 64 5.72M 0 78.96k 1.85k 2.89k 5.45k 1.33k # Query size 46 441.47k 141 144 142.92 136.99 0.66 136.99 # String: # Databases isuports # Hosts localhost # Users isucon # Query_time distribution # 1us # 10us # 100us #### # 1ms ################################################################ # 10ms ################################# # 100ms # # 1s # 10s+ # Tables # SHOW TABLE STATUS FROM `isuports` LIKE 'visit_history'\G # SHOW CREATE TABLE `isuports`.`visit_history`\G # EXPLAIN /*!50100 PARTITIONS*/ SELECT player_id, MIN(created_at) AS min_created_at FROM visit_history WHERE tenant_id = 1 AND competition_id = '547f03113' GROUP BY player_id\G
結果は、 latency が少し改善されたのと、Query_time distribution で 100ms の分布が少し減って、 100us と 1ms の分布が少し増えたので、遅めのクエリが改善されたようでした。
スコアは記録を忘れていましたが、そこまで上がらず 2000 前半くらいで留まっていました。
csv upload を改善
csv upload で score を一括 upload するエンドポイント( POST /api/organizer/competition/:competition_id/score ) は、加点されるポイントが多い api だったため、改善に取り組みました。
SQLite を真面目に取り扱ったことがなかったですが、 for...of で一行ずつ直列に insert するのは明らかに良くないだろうと思い、改善してみることにしました。
調べると、bulk insert するときは transaction を貼った方が良いとのことだったので、とりあえずトランザクションを貼って、 insert を Promise.all で並列実行するように修正しました。
スコア 2642 と思ったほど上がらなかった(多分 flock のせい) ですが微増したので、マージしました。
id をライブラリで生成するように修正
当初から気になっていた、 REPLACE id_generator の方を改善みてみることにしました。
# Profile # Rank Query ID Response time Calls R/Call V/M # ==== =================================== ============== ===== ====== === # 1 0x94A9E43DFAAFA029A1FC19A5563AD0F5 111.6499 66.4% 8822 0.0127 0.01 REPLACE id_generator # 2 0x676347F321DB8BC7FCB05D4948FC2248 48.2423 28.7% 2908 0.0166 0.25 SELECT visit_history
これが何をやっているか調べてみたところ、 dispenseID というシステム全体で一意なIDを生成する関数で
REPLACE INTO id_generator (stub) VALUES ('a')\G
を実行して、 id_generateor の id を auto increment させて一意なIDとして使っているようでした。
REPLACE文 を発行してデッドロックで失敗したら再度 REPLACE 文を発行するというforループで、スピンロック的なことをやっていました。
この対応に関しては横着してしまおうと思い、 DBは使わずに uniqid という npm pacakge を使ってid生成するようにしました。
依存の無いシンプルなライブラリで node_module の管理が面倒だったので、アプリケーション内に uniqid ライブラリを内包するような形にしてしまいました。
スコアは、DBを使わなくなったぶん良くなり 2908 となりました。
その他
id_generator の対応をし終わったところで 17:00 手前でした。
残り時間もすくないため、細々とした対応でできそうなものだけやってみようといくつか取り組みました。
1つは、 MySQL のクエリキャッシュの設定をしようと思いました。
これは事前に練習していたので、設定方法などをメモっており、メモ通りに設定してみました。
ところがうまく再起動してくれません。
よくよく調べると今回は MySQL 8 が動いており、 MySQL 8 からクエリキャッシュは廃止になったそうです。。
MySQL 8 は実務でも全く使ったことがなく予習もしていなかったので、残り時間で何かするのは無理だと判断して、改善を諦めました。
2つ目は、 node cluster 対応しました。
node cluster とは、Node.js は本来シングルスレッドのイベントループを回して処理をするデザインパターンで実装されていますが、 cluster という標準モジュールを使うことで、メインプロセスから fork してワーカープロセスを起動することができます。
この機能を利用して、今回のサーバーアプリケーションをワーカー化し、複数スレッドを利用してリクエストを捌けるようにしました。
起動するワーカー数は調整してみましたが、 3個が一番スコアが高く、 3317 でした。
この対応でちょうど finish となってしました。
まとめ
下記がスコアの推移です。
Golang の初期スコアを少ししか越えられなかったのが、ちょっと敗北感を感じましたw
昨年は、あんまりできることがなくて時間を持て余していた感がありましたが、今回は全然時間たりないな〜という感じだったので、まあ去年よりは成長したかなと思いました。
あとは去年から業務で、Datadog APM とか色々ツール使って計測したりすることが増えて、計測した結果を眺める力は前より付いたなと実感しました。
ただ成績は結構イマイチだったので、また来年までしっかり業務も生かしながらスキルを伸ばしていこうと思います。
さいごに運営の皆様、今年も運営お疲れ様でした！
