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した気がする。
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は
- コンテスト終了前はSQLから持ってきたデータを捨てている
- コンテスト終了後はデータが変わら無さそう（エスパー）
と気が付く。
そこで、
- コンテスト終了前はSQLを叩かずにデータを返す
- コンテスト終了後は計算データをオンメモリキャッシュしておく
と修正
commit
16:10 21600点くらい
16:35 (@eiya) playersAddHandlerをbulk insertにする
alpのaverage上位にPOST /api/organizer/players/addが居るのでなんとかする。
pprofで見るとExecContextが多いので、bulk insertにする。
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をかける。
終了直前にバタバタしてしまったし、もっと早く思い出すべきだったと反省。
感想
序盤にリードを取れたので、予選は通過できるだろうという安心感のなか競技が出来ました。反省点は多いですが、ボトルネックを見つけて直すという基本の部分をしっかりとこなせて良かったです。
運営の皆さんありがとうございました。
