ISUCONをRuby, Sinatraでいい感じに戦うためのツール
以前書いたとおり最近は学生にISUCONを教えるプロジェクトやっていて今日は模試第4回を僕が管理するギークハウス沖縄で行いました。プロジェクト開始から4ヶ月、彼らもちゃくちゃくと実力を着けていってます。
ISUCON模試第4回@ギークハウス沖縄、今回はISUCON6予選 pic.twitter.com/fY4D0LBZX2
— さぼ@ギークハウス沖縄 (@saboyutaka) 2017年8月22日
今回は6予選を題材に行いました。いつも通り学生チーム(4人)対1人でやりました。今回は1人では実装時間足りず、1箇所ドハマリしてしまって思うようにスコアが出せず残念な感じになってしまいました…
さて、プロジェクトを通してこれまで4回模試を行ってきてある程度使うツールが決まってきたので知見を残しておこうと思います。
ISUCONでは時間が有限なので出来る限り、計測しながらボトルネックを探していく手法が有効になります。そのために使うツールを紹介したいと思います。
想定するユーザーは
です。
サーバー周り
sshrc
GitHub - Russell91/sshrc: bring your .bashrc, .vimrc, etc. with you when you ssh
sshrcはsshする際に手元にあるファイルを持っていくことができるツールです。
# ~/.sshrc cp $SSHHOME/.sshrc.d/.aliases $HOME cp $SSHHOME/.sshrc.d/.bashrc $HOME cp $SSHHOME/.sshrc.d/.vimrc $HOME cp $SSHHOME/.sshrc.d/.gitconfig $HOME source $HOME/.aliases source $HOME/.bashrc
自分の環境ではこのように .aliases, .bashrc, .vimrc, .gitconfig などをどのサーバーに入るときも持っていくようにしていていつも通り作業ができるようにしてます。サーバー上ではvimを使って作業することが多いので.vimrcがあると便利です。また.gitconfigを持っていくことでサーバー上でコミットしてもユーザー名やemailがおかしくなることがないので便利です。変なaliaseを作るのをよくやっているので.aliasesも必須です。いつも使ってるツールを持っていきましょう。
htop
htop - an interactive process viewer for Unix
topのもうちょっとグラフィカルな感じのやつ。
$ sudo apt-get install htop
なんかでいけます。
CPUのコア数・各CPUの使用率、メモリのサイズ・使用率、スワップのサイズ・使用率、ロードアベレージの量、CPUを専有しているプロセス、メモリを専有しているプロセスなどはこちらですべて監視します。ここを見てどこがボトルネックなのかをだいたい推測します。CPUバウンドなのか、IOバウンドなのか、アプリケーションヘビーなのか、DBヘビーなのか、などです。
上の図を見るとunicornのCPU専有が支配的なのでRubyの処理に何か問題がありそうです。
Makefile
なんども使うコマンドはmakefileに記述し再利用できるようにしてます。ruby, mysql, nginxの再起動、ログのtail、benchmarkへのリクエストなど。こちらは大部分は予め作っておきます。
.DEFAULT_GOAL := help restart: ## copy configs from repository to conf @sudo cp config/nginx.conf /etc/nginx/ @sudo cp config/my.cnf /etc/ @make -s nginx-restart @make -s db-restart @make -s ruby-restart ruby-log: ## log Server @sudo journalctl -u isuxi.ruby ruby-restart: ## Restart Server @sudo systemctl daemon-reload @cd ruby; bundle 1> /dev/null @sudo systemctl restart isuxi.ruby @echo 'Restart isu-ruby' nginx-restart: ## Restart nginx @sudo systemctl restart nginx @echo 'Restart nginx' nginx-log: ## tail nginx access.log @sudo tail -f /var/log/nginx/access.log nginx-error-log: ## tail nginx error.log @sudo tail -f /var/log/nginx/error.log alp: ## Run alp @alp -f /var/log/nginx/access.log --sum -r --aggregates '/profile/\w+, /diary/entry/\d+, /diary/entries/\w+, /diary/comment/\d+, /friends/\w+' --start-time-duration 5m db-restart: ## Restart mysql @sudo systemctl restart mysql @echo 'Restart mysql' db-log: ## tail mysql.log @sudo tail -f /var/log/mysql/mysql.log myprofiler: ## Run myprofiler @myprofiler -user=isucon -password=isucon .PHONY: help help: @grep -E '^[a-z0-9A-Z_-]+:.*?## .*$$' $(MAKEFILE_LIST) | sort | awk 'BEGIN {FS = ":.*?## "}; {printf "\033[36m%-30s\033[0m %s\n", $$1, $$2}'
だいたいこんな感じで使ってます。
Makefileを自己文書化する、こちらが便利そうなのでまねしてます。
nginx周り
alp
GitHub - tkuchiki/alp: Access Log Profiler
ISUCON 5でalpを使ってNginxのログを解析した話を参考に使い始めました。nginx.conf
のログフォーマットを変更すると使えます。
SUMの降順でソートし、正規表現で同じようなリクエストをまとめています。これを見ることでボトルネックがほぼ一発でわかります。この表だと /
, /keyword/.+
あたり。そのほかは優先順位低いので、ソースコードを見る必要すらない場合もあります。静的ファイルが上がってくる場合は、nginxでキャッシュさせるといいです。
チューニングを進めていくたびにalpを実行し、どこが一番時間がかかっているかを確認するために使います。alpめっちゃ大事。
Ruby, Sinatra周り
rack-mini-profiler
これから紹介するrack-mini-profiler, rack-lineprofなどは基本的にはローカルにアプリケーションをcloneしてきて使います。Gemfile
のdevelopment group
あたりに入れて使うといいです。
一つ目の用途は1リクエストでいくつのSQL文が発行されているかを見るのに使います。N+1を見つけやすくなります。
2つ目は、flamegraph gemと合わせて flamegraphの表を出します。
x軸はcall stack, y軸は全体に対してかかる時間の比率です。y軸を見ることで時間がかかっている処理を見つけるのに役に立ちます。
上の表だと水色の処理が支配的でカーソルをあわせてみるとRubyの処理で htmlify
が遅いのがわかります。
rack-lineprof
GitHub - kainosnoema/rack-lineprof: Rack middleware for easy line-by-line profiling using rblineprof
1リクエスト投げたときに1行ごとにかかった時間と実行された回数、処理に時間がかかっている箇所が赤く表示されて、どの行が遅いかが分かります。
先程、flamegraphで htmlify が遅いのがわかりましたが、rack-lineprof を使うことでさらに gsub で正規表現マッチしているところが遅いのがわかりました。このアプリケーションで一番重いのがここなので、最優先タスクがここの高速化だというのがわかりました。
rack-lineprof
は標準出力に表示されるので、ローカルで開発する際は手軽な rackup
コマンドでsinatraを立ち上げるようにしてます。
MySQL周り
SequelPro
基本的にはGUI使うの好きなので、Sequel Proを使います
sshでトンネリングして接続するとmysqlのportを外に開く必要がなく、楽に入れます。
indexの作成は2クリックぐらいで貼ることができます。後述しますが、これは試しにやったりする程度でmigration残したほうがいいです。
定義変更を実行後にコンソールをクリックすると発行されたSQLが見れるのでこれをコピペできます。(ALTER TABLEあまり覚えてないマン)
あとは、普通にクエリ発行したりして、アプリケーションコードのSQLを変更する前にこちらで試したりします。実行時間を見て、さてはおめぇインデックス貼ってねぇな、とか気づけます。
goose
DBのmigrationツールはなんでもいいのですが、Golang製のgooseを使っています。個人的にはシンプルなところが気に入ってます。
DBの変更を直接行うと、他のメンバーにその更新履歴を共有するのが難しくなるのでやっぱりgitで管理したいということでmigrationツールを使うことをおすすめします。
SequelProで試しに実行して、コンソールからコピーして、migration fileに貼り付ける感じでやります。
$ goose create create_star_table sql
のようにSQL形式でmigration fileを作成し、
-- +goose Up -- SQL in section 'Up' is executed when this migration is applied CREATE TABLE `star` ( `id` bigint(20) unsigned NOT NULL AUTO_INCREMENT, `keyword` varchar(191) COLLATE utf8mb4_bin NOT NULL, `user_name` varchar(191) COLLATE utf8mb4_bin NOT NULL, `created_at` datetime DEFAULT NULL, PRIMARY KEY (`id`) ) ENGINE=InnoDB AUTO_INCREMENT=3 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin; -- +goose Down -- SQL section 'Down' is executed when this migration is rolled back DROP TABLE `star`
みたいな感じにします。テーブルを別のDBから違うDBに以降しようとする時に作ったものですが、 CREATE TABLE
文はSequelProの情報タブに書いてある文をコピペしました。
あとは、
$ goose up
でmigrationが走ります。RailsやLaravelとかやってたらいつもどおりですね。
gem で sinatra-activerecord がありますが、やりたいことに対して複雑すぎるので使ってません。
myprofiler
GitHub - KLab/myprofiler: Sampling profiler for MySQL
DSAS開発者の部屋 pixiv private isucon 2016 攻略 (1/5) などで紹介されていたので使ってみてます。
デフォルトでは1秒に一回のインターバルの間に終了しなかったSQLの数をカウントします。これを使ってslowクエリを見つけたりします。ただ最近はrack-mini-profilerとrack-lineprofでおおよその検討はつくのであまり使わなくなりました。
general log, slow query log
mysqlの機能でgeneral log, slow logの機能をアクティブにして使います。
[mysqld] general_log general_log_file=/var/log/mysql/mysql.log slow_query_log slow_query_log_file = /var/log/mysql/slow.log
general_logでSQLの発行回数やどんなクエリが発行されているかを確認し、slow_query_logでスロークエリが発生しているかを確認します。slow_query_logはmyprofilerとかぶっているところがあるのでどちらかでいいかもです。
まとめ
基本的には
- alpで全体を把握
- rack-mini-profiler, rack-lineprofで深掘り
- チューニング
- 1に戻る
を繰り返すことでいい感じにスピードアップできるんじゃないでしょうか。ISUCON、ウェブの総合的な学習にとてもいい感じで教えるのがとても楽しいのでいいですねー。教えてる学生が予選突破してくれるといいなぁと思ってます。沖縄県内の学生でやりたい人いたらまた来年やろうかなと思うので連絡ください🙌
P. S.
最初は学生に教えるだけで自分は出る予定なかったけど、教えるにつれてどんどん自分も出たくなって来てます😟
しかしいまだメンバーおらずフリーなのでどこか拾ってくれる方いたらチーム入れてください!😭😭😭