The paradigm shift

saboyutaka’s diary なんかかく(ブログn回目)

ISUCONをRuby, Sinatraでいい感じに戦うためのツール

以前書いたとおり最近は学生にISUCONを教えるプロジェクトやっていて今日は模試第4回を僕が管理するギークハウス沖縄で行いました。プロジェクト開始から4ヶ月、彼らもちゃくちゃくと実力を着けていってます。

今回は6予選を題材に行いました。いつも通り学生チーム(4人)対1人でやりました。今回は1人では実装時間足りず、1箇所ドハマリしてしまって思うようにスコアが出せず残念な感じになってしまいました…

さて、プロジェクトを通してこれまで4回模試を行ってきてある程度使うツールが決まってきたので知見を残しておこうと思います。

ISUCONでは時間が有限なので出来る限り、計測しながらボトルネックを探していく手法が有効になります。そのために使うツールを紹介したいと思います。

想定するユーザーは

  • macOSユーザー
  • Ruby, Sinatraで行う
  • ローカルで使ってコーディングする

です。

サーバー周り

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

なんかでいけます。

f:id:saboyutaka:20170823004425p:plain

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のログフォーマットを変更すると使えます。

f:id:saboyutaka:20170823004935p:plain

SUMの降順でソートし、正規表現で同じようなリクエストをまとめています。これを見ることでボトルネックがほぼ一発でわかります。この表だと /, /keyword/.+ あたり。そのほかは優先順位低いので、ソースコードを見る必要すらない場合もあります。静的ファイルが上がってくる場合は、nginxでキャッシュさせるといいです。

チューニングを進めていくたびにalpを実行し、どこが一番時間がかかっているかを確認するために使います。alpめっちゃ大事。

Ruby, Sinatra周り

rack-mini-profiler

GitHub - MiniProfiler/rack-mini-profiler: Profiler for your development and production Ruby rack apps.

これから紹介するrack-mini-profiler, rack-lineprofなどは基本的にはローカルにアプリケーションをcloneしてきて使います。Gemfiledevelopment groupあたりに入れて使うといいです。

一つ目の用途は1リクエストでいくつのSQL文が発行されているかを見るのに使います。N+1を見つけやすくなります。

f:id:saboyutaka:20170823005147p:plain

2つ目は、flamegraph gemと合わせて flamegraphの表を出します。

f:id:saboyutaka:20170823005337p:plain

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行ごとにかかった時間と実行された回数、処理に時間がかかっている箇所が赤く表示されて、どの行が遅いかが分かります。

f:id:saboyutaka:20170823005507p:plain

先程、flamegraphで htmlify が遅いのがわかりましたが、rack-lineprof を使うことでさらに gsub で正規表現マッチしているところが遅いのがわかりました。このアプリケーションで一番重いのがここなので、最優先タスクがここの高速化だというのがわかりました。

rack-lineprofは標準出力に表示されるので、ローカルで開発する際は手軽な rackup コマンドでsinatraを立ち上げるようにしてます。

MySQL周り

SequelPro

Sequel Pro

基本的にはGUI使うの好きなので、Sequel Proを使います

f:id:saboyutaka:20170823005658p:plain

sshでトンネリングして接続するとmysqlのportを外に開く必要がなく、楽に入れます。

f:id:saboyutaka:20170823005725p:plain

indexの作成は2クリックぐらいで貼ることができます。後述しますが、これは試しにやったりする程度でmigration残したほうがいいです。

f:id:saboyutaka:20170823005817p:plain

定義変更を実行後にコンソールをクリックすると発行されたSQLが見れるのでこれをコピペできます。(ALTER TABLEあまり覚えてないマン)

f:id:saboyutaka:20170823005859p:plain

あとは、普通にクエリ発行したりして、アプリケーションコードのSQLを変更する前にこちらで試したりします。実行時間を見て、さてはおめぇインデックス貼ってねぇな、とか気づけます。

goose

liamstask / goose — Bitbucket

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とかぶっているところがあるのでどちらかでいいかもです。

まとめ

基本的には

  1. alpで全体を把握
  2. rack-mini-profiler, rack-lineprofで深掘り
  3. チューニング
  4. 1に戻る

を繰り返すことでいい感じにスピードアップできるんじゃないでしょうか。ISUCON、ウェブの総合的な学習にとてもいい感じで教えるのがとても楽しいのでいいですねー。教えてる学生が予選突破してくれるといいなぁと思ってます。沖縄県内の学生でやりたい人いたらまた来年やろうかなと思うので連絡ください🙌

P. S.

最初は学生に教えるだけで自分は出る予定なかったけど、教えるにつれてどんどん自分も出たくなって来てます😟

しかしいまだメンバーおらずフリーなのでどこか拾ってくれる方いたらチーム入れてください!😭😭😭