ISUCON12予選素振りログ

はじめに

素敵な夜ですね。ISUCON13の参加に向けてISUCON12の素振りを行った。ログを記す。

概要

10時間かかって0点（FAILED）であった。

おわりに

ISUCON13参加ログや今年の環境構築も書いているので、そちらもぜひお願いします。

ログ全文

start
初ベンチマークスコア2807
印象としては離脱があんまり多くなく、純粋になにか重いのがありそう

120
ディレクトリの様子見はdu
ステージング中のファイル一覧はgit ls-files
プロセッサはuname -m
alias brefresh="source ~/.bashrc"

170
nginxログとalp導入

alias alp="sudo ~/bin/alp ltsv --file=/var/log/nginx/access.log -r -m '\
/api/player/player/[0-z]+,\
/api/organizer/player/[0-z]+/disqualified,\
/api/player/competition/[0-z]+/ranking,\
/api/admin/tenants/billing,\
/api/organizer/players/add,\
/api/organizer/competition/[0-z]+/score,\
/api/organizer/competition/[0-z]+/finish,\
/api/organizer/billing,\
/initialize,\
/api/organizer/competitions/add\
'"
alias alpsum="alp --sort=sum"
alias alpavg="alp --sort=avg"
alias nginxconfig="sudo vim /etc/nginx/nginx.conf"
alias nginxrefresh="sudo mv /var/log/nginx/access.log /var/log/nginx/access.log.`date +%m%d%H%M` && sudo systemctl restart nginx.service"
alias isurefresh="sudo systemctl daemon-reload && sudo systemctl restart isuports.service"
alias isulog="journalctl -u isuports.service -n 100"

230
sqliteはスロークエリログがないようなので、pt-queryは省略

231
チューニングに入れた。
まず露払いが必要。
/api/player/competition/[0-z]+/rankingと/api/player/player/[0-z]+が重い。なんかある。
一旦ドキュメントを読む。
「反映までの猶予時間」は、キャッシュしてもいいという意味な気がする。
「429 Too Many Requests」は、おそらくベンチマークのレベルが上がってからの問題な気がする。
「ベンチマーカーの認証について」は謎。何かありそうだが。ベンチマーカー側がJWTを作ってくれる？　なにか仕込めるのか。
「スコア計算」は気にかかるが、ぱっと見傾向はわからない。デフォルトで重いやつは得点にならない事はわかるが。
とりあえず/api/player/competition/[0-z]+/rankingと/api/player/player/[0-z]+を露払いしよう以外の結論はない。

241
ぱっと調べた限りsqliteにいい感じのログ機能はないようだった。
スロークエリログがないのはキツイ。思いつく案もない。goのログ機能とかで統計取ったりできるんだろうか。

251
/api/player/competition/[0-z]+/rankingのクエリを全部見る。
retrieveCompetitionはidで絞る。sqliteのプライマリキーにデフォでインデックスがあるか怪しいが、一旦あるとする。
とりあえず" WHERE tenant_id = ? AND competition_id = ? ORDER BY row_num DESC"の複合インデックスは必要。
（※ただ、キャッシュとかにできそうでなんとも言えないが…）
「player_scoreが同一player_id内ではrow_numの降順でソートされているので」怪しい、sortedset化とか要求？　今は関係ないか？

275
specification.mdに遅まきながら気づく。
うーん、謎。JWTのexpが24hというのをなにかに使うんだろうか？
他に今のところ気づきはないが、定期チェックが必要か。

276
とりあえず" WHERE tenant_id = ? AND competition_id = ? ORDER BY row_num DESC"の複合インデックスは必要。
ぱっとインデックスを付けたが、再起動はどうやってやればいいんだろう？
systemctl list-unit-files --type=serviceで一覧を見てみたが見つからない。
マニュアルを読んだらPOST /initializeでinit.shの内容が実行されるようだ。
しかしそうなると、sqliteのDBはただコピーされるだけのようだ。
makefile製のデータ生成機を見つけたので実行してみる。うまく実行できない。go？ ポート番号？ dockerを使う？
sqliteの初期データを無理やり変更すると、整合性チェックに通らなくなった。
インデックスを外してもう一度作っても、整合性チェックに落ちる。
終了。

8h経過。参加者ブログ閲覧を解禁。参加者ブログをすべて見るのはまだ。

416
データ生成機はユーザ側がいじるものではなかったようだ。
for db in *.db; do echo "create index tenant_compe_rownum_idx on player_score(tenant_id, competition_id,row_num)" | sqlite3 $db; doneを実行。
create index tenant_compe_rownum_idx on player_score(tenant_id, competition_id,row_numを10_schema.sqlにも仕込む。
ベンチマークスコア3189。何度繰り返しても3000を超えるのは僅かだったので、微増と考えていいだろうか、でも微すぎる。
ボトルネックではなかったようだ。

466
fl.Close()の処理がdefer任せになっている事に着目。クエリ実行後即座に閉じるようにしたが、無意味だったようだ。
ベンチマークスコア微減、ロールバックした。

467
N+1を見つけたので、直してみる。
systemctlのログを出してひたすらデバッグ。
log.Printf("%+v\n", pseach)
in句がうまく働かない問題を最後まで解決できなかったが、in句を取っ払っておそらく問題ないだろうという形に帰結。
だが、ベンチマークスコア変わらず。見当違いだったようだ。
見当がつかない。クエリログはやはり必要だ。

468
めちゃくちゃ今更ながらsqliteのクエリログを出力する設定を発見する。
JSONで取れたところでどうなるのかと思っていたが、JSONをsqlite使って集計するソフトがあるとの事。

別日
docker-compose.ymlの接続先を変え、sshをマウントし、ssh接続し、DBの分割に成功。なお、一切スコアは変わらない。初期状態で分割しても意味がないのは収穫だったか。

別日
ALTER TABLE visit_history ADD INDEX idx_all_cover (tenant_id, competition_id, player_id, created_at);
をつけようとするが何をどうやってもつかないのでmysqlのコマンドで直接叩く。
確かにtopで見るmysqldは落ち着いているが、スコアは微増にとどまる。ここで練習が終わった。