今週土曜はISUCON予選なので、今日はひとりで private-isu をやっていました。
自分のリポジトリはこれです (INDEX貼ったりとかmy.cnfいじったりとかはサーバ上でやってるのでここに反映されていないですが)
github.com
作戦
- 各種計測ツールだけを信じる、なるべく一番重いボトルネックを順番に倒す
- 以下のような流れ
- ベンチ実行中に
top -d1 -c
を実行して負荷の様子をみつつ、go tool pprof -seconds 60 http://localhost:8080/debug/pprof/profile
も実行してプロファイル採取 - CPU userが重い時は
- mysqldの場合は
pt-query-digest
の結果をみる、必要に応じてpprof
結果も合わせてみる - appの場合は
pprof
の結果を主に見る alp
もたまに参考情報として眺める、ステータスコードの割合とか
- mysqldの場合は
- CPUのsystemが重いときは ulimit とかを確認したりする (雰囲気でやっている)
- CPUのiowait が重いときは my.cnf とか設定値を確認したりする (雰囲気でry
- ベンチ実行中に
systemでなんか食ってるときどこをどう深ぼっていけばいいかわからなくて困っているけど今回はなんとかなった。
時系列 (自力タイム)
- 10:03 初回ベンチ: 639点
- 10:07 Goに切り替えたのみ: 0点
- なぜかタイムアウトしまくるようになって減点されるように
- 10:37 pt-query-digest の一番重いクエリにINDEX適用: 19722点
ALTER TABLE comments ADD INDEX idx_post_id_created_at_desc (`post_id`, `created_at` DESC);
とかやってた
- 11:46 まだMySQLが重いので、クエリの様子をみる。無駄に全件取得してるのをLIMIT 20にした: 26162点
- getIndex limit 20 by stefafafan · Pull Request #3 · stefafafan/private-isu · GitHub
SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` ORDER BY `created_at` DESC
が遅いのをSELECT posts.id, posts.user_id, posts.body, posts.mime, posts.created_at FROM posts JOIN users ON users.id = posts.user_id WHERE users.del_flg = 0 ORDER BY posts.created_at DESC LIMIT 20
にしたけど、EXPLAINした結果まだrows
が多いので最高の状態にできなかった
- 12:06 さっき作ったクエリが重かったのでINDEXを追加: 31397点
ALTER TABLE posts ADD INDEX idx_created_at_desc (`created_at` DESC);
とかやった上で、STRAIGHT JOIN
も使ったらいい感じにINDEX使ってくれるようになった- straight joinする by stefafafan · Pull Request #4 · stefafafan/private-isu · GitHub
- 13:19 interpolateParams=trueにしたり、SetMaxOpenConnsしたり、ulimitあげたりした: 39116点
- Db params by stefafafan · Pull Request #5 · stefafafan/private-isu · GitHub
socket: too many open files
と言われてずっと競技用サーバの方のlimit色々あげてたけど、ベンチマークサーバーの問題だったので時間を無駄にした
- 15:45 DBの画像をnginxから返して304返すようにした: 71555点
- Get image by stefafafan · Pull Request #6 · stefafafan/private-isu · GitHub
- ISUCON本で読んだ覚えがあった、リクエストのたびに画像をファイルに書き出して、nginx側ではtry_filesするというのができてよかった。全部DBから一度に書き出すよりは省エネ
- とはいえ慣れてなくて結局少し時間かかっていた。ちゃんと304返せてるかは alp が確認の役に立つね
- 16:09 getPostsのほうも、11:46の頃にやったようにLIMIT 20できそうだったのでやった: 92152点
- getPostsでlimit 20 by stefafafan · Pull Request #7 · stefafafan/private-isu · GitHub
- EXPLAINの様子では rows がまだ微妙に多くていまいちかなと思ったけど、全件取得よりは良いようだった
- 16:16 makePostsのN+1が目立つけど、2位のクエリもINDEXはれそうだったのではった: 99046点
ALTER TABLE comments ADD INDEX idx_user_id (`user_id`);
とかやった。rowsが97258から100に減った
- 16:34 1-3位は全部N+1でやる気がないので、4位のクエリのINDEXだけ足す: 96271点
SELECT `id`, `user_id`, `body`, `mime`, `created_at` FROM `posts` WHERE `user_id` = 202 ORDER BY `created_at` DESC
が遅いので、ALTER TABLE posts ADD INDEX idx_user_id_created_at_desc (`user_id`, `created_at` DESC);
とかやってみた- この結果 88008点に逆に下がったが、他のクエリでこのINDEXが使われるようになった結果だったのでそっちでIndex Hint使うようにしたらことなきを得た
- 99046から96271に下がっているようにも思えるが、pt-query-digest的にはこのクエリの順位は下がったので良いと判断
- 18:16 途中休憩してアニメみたりしてたけど、いよいよN+1のmakePosts途中まで倒した: 175231点
- N plus 1 by stefafafan · Pull Request #9 · stefafafan/private-isu · GitHub
- ここで
no space left on device
とか言われるが、MySQL 8はbinlogがやばいという情報を思い出しておもむろにPURGE BINARY LOGS BEFORE NOW();
をしたり、binlog自体無効にしたりして事なきを得た
- 18:25 no space left on device解消したので再実行: 146094点
- 下がる理由ないと思うのでそういうものかと置いた
- 18:56 さっきのN+1の残りをさらに直した: 218115点
- N plus 1 2 by stefafafan · Pull Request #10 · stefafafan/private-isu · GitHub
- ここでやっと、mysqldの負荷よりもappの負荷が高くなる
- 色々計測ツールをみるけど、Goのテンプレートの負荷が一番高くでていてこれどうしたものかとなる
- このへんでMySQLやNginxのログを無効化しているけど、あまり大きな変化はなく22万点くらいかな〜という気持ちになる。
22万点超えたところで一番のボトルネックはGoのTemplateになってしまった
— すてにゃん (@stefafafan) 2022年7月18日
ISUCON本チラ見して続き
- 19:52 ISUCON本に外部コマンド呼び出しの件が書いてあって、確かにregister/loginはalp的に上がってきていて何もみていなかったことを思い出す。opensslコマンドを使うのやめた: 293051点
- 19:56 my.cnf周りあまり調整できていないことを思い出して、 innodb_buffer_pool_size, innodb_flush_method, innodb_flush_log_at_trx_commit あたりを指定: 295971点
- 20:13 MySQLとはsocket fileで接続するようにしてみた: 290641点
- 20:25 nginxとの接続もunix domain socketでやるようにしてみた: 297502点
- 21:05 Goのテンプレートを毎回ParseFilesするのは非効率という情報をネットでみかけて、一回だけやるようにした: 321967点
このあとMaxOpenConnsとか調整してみるものの、そもそもあまり多くのコネクション受け付ける余裕ないようで意味なさそうだった。
最後に再び pprof を有効化して様子みたけど、やっぱりGoのTemplateが一番重いのは変わりないんですねとテンション下がってしまった。
以下の記事を読むと最後のほうに他にやれそうなことが書いてあるけど、今日一日中やってたので諦めてしまった。
dsas.blog.klab.org
感想
- 自分1人で全部やってみるというのがやっぱり良い経験という感じがする
- ulimitどこでどうやるんだっけとか、画像ファイル304で返すのどうするんだっけとか、プロファイラの使い方のプロになるとか
- 倒す順番はあってると思うので今週末のISUCON予選もがんばりたい!