feature image

2022年8月4日 | ブログ記事

ISUCON12予選を学生チーム内1位のスコアで突破しました

ISUCON12予選に@eiya@oribe@tokiで「織時屋」として出場しました。
参考スコアは31806で、全体では12位、学生チーム内では1位となり予選を突破しました。

リポジトリ: https://github.com/oribe1115/isucon12-qualify

事前準備

Makefileの作成

@oribeが初心者向け講習会のハンズオン用に作成したMakefileをベースとして使用。
サーバーリソースの計測用にnetdataを使うようにしたり、discocatで計測データをdiscordに送れるようにした。
netdataのデフォルトのダッシュボードは情報量が多すぎてベンチマーク中に監視するには厳しいので、毎回必ず見るメトリクスをまとめたカスタムダッシュボードを作成した。

ISUCON10予選問題での練習

PISCON(部内ISUCON)でISUCON10予選問題を使ってチーム練習をした。
Makefileの醸造やチートシートの作成をしつつ、ISUCONの戦い方の復習をした。

10:00~ 初動

@oribe
環境セットアップとリポジトリ載せを担当。
やたら.dbってファイルがあるしサーバー上に言語環境ないしでビビってた。

@eiya
slow query logとalpとpprofの設定をする。
反省なんですが、この問題はlockが多いのでfgprofを用意しておくべきだった。

@toki
マニュアルを読む。エンドポイントごとの点数や遅延可能秒数などの情報をコードに書き写して整理する。

10:45 初回計測 2600~2900点くらい

CPUが50%程度しか使われていないこと、そのほとんどがMySQLであること、pprofでsqliteに関するメソッドが目立っていたことからsqliteのファイルに対するロックの問題であると推測。
@tokiがMySQLへの載せ替え作業を開始する。
@eiyaはとりあえずMySQLの負荷を下げるためにslow query logを見ていた。
SELECT visit_historyとREPLACE id_generatorが大きい。前者はindexが無い、後者はパット見UUIDか連番に出来そう。

ちなみに環境変数の設定でsqliteクエリのログ出力が可能なことは終了30分前くらいに気づいたし、sqliteにトランザクション概念はないと思い込んでいたのでflockは最後までそのままだった。
ので、以降のsqlite周りの計測はalpの結果とpprofでSelectContextなどが浮き上がっているのを見てのエスパー考察。

負荷が多すぎて捌けてないのではなくて、そもそも負荷がかかっていない気がしたので、alpはsumではなくaverageを重視して見た。
シナリオ型のベンチマーカーだと、トップページ見る -> 詳細を見る -> 何か操作をする -> トップページに戻る...みたいなのをぐるぐる回っているので、一か所でもaverageが遅いと全体の負荷(リクエスト数)が下がって点が伸び悩むことがある。
(例えば、isucon10本選(XSUCON)だと、選手は手を止めてClarの回答を待つのでClarが遅いとリクエストが来ません、と書いてある)

11:00 (@eiya) indexを張ったつもりになる

slow query logの上位。
webapp/sql/admin/10_schema.sql にindexを書いてindexを張ったつもりになったが、このファイルは実行されないので張れていなかった。
ただし、EXPLAINのために色々張りながらテストしていたので、テストのindexが残って点が上がる。

10:30 ~ 15:00 (@toki) SQLite→MySQL移行作業

最初の推測とsqlite-to-sqlという名のファイルに釣られ、MySQLへの移行作業を進める。しかしこれが罠であり、もう少ししっかり計測して推測を立てるべきであった。
最初にsqlite-to-sqlを使い直接変換しinsertを試みたが、お昼ごはん30分を挟んでも終わらなかったため断念。
次にちょっと書き換えて全てのレコードを一度にbulk insertしようとするが、1.dbが大きすぎてmax allowed packetの大きさに引っかかる。何も考えないでこれの上限を引き上げたらサーバーが応答しなくなった。ちょうど他の作業でサーバーをもう一台壊しかけていたため、スタックを再作成することに。
もう少しちゃんと書き換えて、5000件ほどずつbulk insertするようにしてようやく移行ができた。しかしベンチマークを回すと点数は半分ほどとなってしまったため、この変更を本流にマージするのはやめた。
今考えれば、MySQLをチューニングすれば移行前に近い点数になり分割も楽になったのではないかとも思えるが、チューニング周りの知識が足りなかったように思える。

その一方で、チームメンバー皆が見慣れたMySQLのslow-queryとpt-query-digestで遅いクエリの解析がtenant dbも含めてできるようになったため、これ以降は本流をこちらにマージしながら遅いクエリの解析を行ったりもした。

11:30 (@oribe) ID生成をUUIDに変更

slow query logの上位にdispenseIDのクエリが上がっていたので、ID生成の方式を見直す。
順序だったIDである必要はなさそう、ということでUUIDを使用するようにした。
文字種変更についての規定に抵触するのでは、という不安があったため生成したUUIDから-を取り除いて使用するようにした。

11:45 (@eiya) playerHandlerのn+1

pprofの上位にGetContextが居たので直す。

SELECT * FROM player_scoreが大きかったので、このn+1をjoinでまとめる。
commit

12:00 5200点くらい

12:20 (@eiya) competitionRankingHandlerのn+1

pprofの上位にいるGetContext。alpでも高い。
点は上がらなかったけど損にはならないだろうと思ってmergeした気がする。

commit

12:35 (@oribe) 2台目 3台目のセットアップ

1台目をSQLite→MySQL移行作業で使うのと、損にはならないだろうということでセットアップ。

12:40~15:40 (@eiya) visit_historyの修正を主張

slow query logはvisit_historyがネックで、alpのaverageが高いのもここ。

visit_historyは一番古いデータだけもっとくように修正すればgroup byが要らなくて嬉しいと主張する。
ここでwebapp/sql/admin/10_schema.sqlを変更するだけでは反映されないことに気が付く。

データを削除するクエリの叩き方がわからずに2時間ほど悪戦苦闘の後なんとか書き上げるも、今度はDELETEの実行が待てども待てども終わらず諦める。

過程でDELETEを叩いたりDROP COLUMNをしたため、この間@eiyaが2台目を占有することに。

13:50 (@oribe) competitionScoreHandlerでbulk insert

pprof上でcompetitionScoreHandlerのSQLiteクエリの実行が目立っていたので、bulk insertに改善。
もともとNamedExecContextが使われていたので、実装自体はごく簡単な書き換えで行えた。

13:50 12700点くらい

14:20 ごろ

試行錯誤の過程で環境が壊れてしまったので、インスタンスの再作成を実施。
設定ファイルなども全てリポジトリで管理できていたので、新インスタンスでの環境復元はかなりスムーズに行えた。

@tokiが1台目、@eiyaが2台目を占有する。

15:50 (@oribe) playerHandlerにキャッシュを実装

alpでplayerHandlerが上位に来ていたこと、player情報まわりのAPIのキャッシュを許容するような記述があったことからキャッシュを実装。
@tokiが作成したキャッシュライブラリを使用した。
キャッシュヒット率は30%くらいでスコアもあまり変わらなかったが、後で活きるかもしれないとマージ。

16:00 (@eiya) billingReportByCompetitionを直接改善

visit_historyのデータ構造の改善があまりにも上手くいかないので、別の手段を探す。

billingReportByCompetitionは

と気が付く。

そこで、

と修正
commit

16:10 21600点くらい

16:35 (@eiya) playersAddHandlerをbulk insertにする

alpのaverage上位にPOST /api/organizer/players/addが居るのでなんとかする。
pprofで見るとExecContextが多いので、bulk insertにする。

commit

16:35 23000点くらい

17:00 ~ 17:50 (@toki) 3台構成に挑戦

終盤になってきたため、そろそろ分割を試しておくかとなったので構成を考える。
テナントごとにサーバーを割り当てればよいのではという考えに至り、アプリ側でテナントのIDによって分散するプロキシを書いていく。
これが書き終わったところで、テナントの作成リクエストや、adminの全てのテナントのbillingの算出などで実装がさらに必要となることに気づく。この時点で終了20分前くらいになっており、本選出場ラインの点数は既に出ているだろうとチームで判断し、3台構成は断念。安定して点が取れるrevisionまで戻し、1台構成でフィニッシュすることにした。

17:10 (@eiya) SQLiteにindexを張る

alpでcompetitionRankingHandlerのaverageが高いので、これを直したい。

pprofではSelectContextが大きかったが、n+1を既に直した後なので、indexを張ることにする。

tenant/10_schema.sqlだけを変更しても初期データの方には反映されないので、初期データはシェルコマンドで事前にindexを張っておく。
commit

17:10 26000点くらい

17:30 (@oribe) ログをはがす準備と再起動試験

競技終了に備えて、ログをはがすブランチを作成。
ログのon/offもリポジトリで管理している設定ファイルの書き換えで行っていたため、ブランチを切り替えてデプロイするだけでログなし状態を実現できるようになっていた。
ログを全て切ると5000点くらい上がった。

再起動試験も実施して点数の最低ラインの確保をした。

17:35 (@eiya) row_numが最大なものだけselectしようとする

まだalpでcompetitionRankingHandlerのaverageが高いので、これを直したい。

tenantDB.SelectContextではrow_numが最大のもの以外は不要なので、GROUP BYでなんとかしようとする。
スコアが上がらなかったので放棄。

17:40 32000点くらい

17:50 (@eiya) visit_historyのinsertを減らそうとする

元々やるつもりだったのにすっかり忘れていた、competitionRankingHandlerのinsertを減らす作業を思い出す。

16:50に点上がりましたを主張してmainにmergeをするも、mainでfailする。
(buildし忘れた状態で確認して、誤差で点が上がっていただけだった)
残り10分だったので慌ててrevertをかける。

終了直前にバタバタしてしまったし、もっと早く思い出すべきだったと反省。

感想

序盤にリードを取れたので、予選は通過できるだろうという安心感のなか競技が出来ました。反省点は多いですが、ボトルネックを見つけて直すという基本の部分をしっかりとこなせて良かったです。

運営の皆さんありがとうございました。

oribe icon
この記事を書いた人
oribe

お絵かきする時間が欲しい

eiya icon
この記事を書いた人
eiya

プログラミングをやっています。 メイン言語はC++14 競プロ/ゲーム制作/CTF

toki icon
この記事を書いた人
toki

Java, Go, JS/TSなどをいじっています

この記事をシェア

このエントリーをはてなブックマークに追加
共有

関連する記事

2021年9月21日
ISUCON11 traP CM制作についての小話
dan_dan icon dan_dan
2022年7月24日
ISUCON12に向けてダッシュボードを自作してログを可視化しました
Ras icon Ras
2019年12月17日
部内ISUCONを開催しました
xecua icon xecua
2022年7月25日
ISUCON12予選に参加して完敗しました(mazrean)
mazrean icon mazrean
2021年8月27日
学生枠でISUCON11予選を突破しました
mazrean icon mazrean
2021年8月25日
ISUCON11予選に参加してきました!
anko icon anko
記事一覧 タグ一覧 Google アナリティクスについて