ISUCON5予選でスコア19450出しました

サーバチューニングの勉強になればとISUCON5の予選に参加してみたところ、予想外に予選通過できてしまいました。 初めてISUCON参加してみての感想を一言で言うと、めちゃくちゃ疲れるけど楽しかったです。 参考までに、僕が行った作業内容を書いてみます。

ベンチマークの実行を成功させる

まずベンチマークを実行できるところまで持っていきます。ここまではなんとかがんばるしかないですね。

mysql, nginx,unicornの設定チューニングする

前回参加者のブログを参考に、あらかじめ準備していたチートシート通りに設定しました。 systemdの使い方がわからなくてサービスを再起動方法をググったりして、わりと手間がかかりました。

設定内容は以下のとおり。

my.cnf

innodb_buffer_pool_size = 2G
innodb_flush_log_at_trx_commit = 2

nginx.conf

worker_processes  5;
worker_rlimit_nofile  4096;

  log_format  ltsv  'host:$remote_addr\t'
                    'vhost:$http_host\t'
                    'port:$server_port\t'
                    'time:$time_iso8601\t'
                    'method:$request_method\t'
                    'uri:$request_uri\t'
                    'protocol:$server_protocol\t'
                    'status:$status\t'
                    'size:$body_bytes_sent\t'
                    'referer:$http_referer\t'
                    'ua:$http_user_agent\t'
                    'forwardedfor:$http_x_forwarded_for\t'
                    'forwardedproto:$http_x_forwarded_proto\t'
                    'apptime:$upstream_response_time\t'
                    'reqtime:$request_time';

  #access_log off;
  access_log /var/log/nginx/access.log ltsv;

unicorn

プロセス数を5に

プロセス数はあとで増やすなど試してみたんですが、効果がなかったので5に戻しました。 ログ解析をするために、ltsv形式で出力しようというのは事前に決めてました。

ここまでである程度スコアが上がったのを確認して、次に戦略を立てるためにログ解析の準備をしました。

ログ解析の準備をしてログ解析する

sonotsさんが前回のISUCONでltsvのログをスクリプトで整形しと書いてたので、このアイデアをそのまま使わせてもらいました。

https://gist.github.com/sonots/9ae0167d31d7f4b42c9a

実際の作業ではボトルネックになってる箇所を見やすいように、URLをグループごとに見れるように、スクリプトを調整しました。

あとはアクセスログを退避してクリアするスクリプトも作っておきました。 これでベンチマークを動かすごとに、詳細なログ解析が得られるようになりました。 これを見てると / へのアクセスの処理にほとんどの時間がかかってて、静的ファイルへのアクセスはほとんど影響してないことがわかりました。なので今回の問題は、静的ファイルを素早くさばくことよりアプリケーションの処理を高速化するのが効果的だろうと判断しました。 このログ解析の仕組みは最後までチューニング方針の決定に役立ってくれたので、準備しておいたかいがありました。

アプリケーションのチューニング内容

アプリケーションのチューニングでやったことは、とくに大きな構成の変更はせず、参考実装のボトルネックを潰していった感じです。 N+1問題を潰したり、mysqlのindexを追加して行ったりしたら順調にスコアが上がっていってくれました。 今回の課題はアプリケーションのボトルネックを潰すのがメインだったので、アプリケーションエンジニアの自分にとっては普段やってる仕事と同じような感じで作業していけました。

反省点

• shellやエディタが普段の環境とちがうまま作業してしまって非効率でした。dotfileをgithubに置いておいて適用したほうがよかった。
• N+1問題が起こってるところをgrepで見つけていたのが良くなかったので、N+1問題を検出する仕組みを準備しておくべきだった。
• kazeburoの術によるとnginx設定はまだ足りないものがある感じ。( https://gist.github.com/sonots/62179703d429d36b1a57 )本選までに勉強しておこう。

良かった点

• ログ解析ツールが役に立った stat.rbは役に立った。実行結果を分析できるので、効率的にボトルネックに対処できた。
• mysql, nginxのチートシートは役に立った
• 予習したおかげで、設定ファイルの場所などで戸惑わずにすんだ。

作業ごとのスコアの遷移を掲載しておきます。 だいたいアプリケーションの修正とindexの追加に時間を使っていて、順調にスコアが上げれてましたね。

12:00くらい
初回ベンチマーク実行
=> スコア 146

12:30
* nginx worker process を5に
* unicorn worker process を 5に
=> 881

12:35
my.cnf修正
innodb_buffer_pool_size = 1G
innodb_flush_log_at_trx_commit = 2
=> 889

13:01
my.cnf修正
innodb_buffer_pool_size = 2G
=> 911


13:12
vimrcをいつも使ってるサーバからコピペ。vimプラグインは面倒なので持ってこなかった。

13:30
ログを解析したところ / に時間がかかってることがわかったので /を高速化する

13:40
footprints, relationsにindex追加
=> 2248

14:19
is_friend? をone -> anotherの向きのみ見るように修正
=> 2762

14:30
tail -f してたのをやめた
=> 2911

14:55
friend_idsを最初に取っておくように
=> 4352

15:06
comment取得にもfriend_idsを使うように
=> 4828

15:43
comment取得をsqlだけで取得するように。commentsにindex追加
=> 12413


16:04
/friends のSQLをor使わないように修正
=> 12432

16:17
/friendsをリファクタリング
=> 12480

16:26
nginx, unicornのworkerプロセスを5 -> 10に
=> 12313
効果ないので8に変更
=> 
効果ないので5に戻した

16:55
footprintのindexをuser_id, owner_id, created_at に変更
=> 12460

17:08
一部erubis => slimに変更
=> 見た目には正しく変換できてるように見えるがbenchmarkerでエラーになるので中止。

17:46
トップページでfriendsがcountしか使われてなかったので、sqlでcountを取得するように修正
=> 13145

18:06
get_userが何度もviewから呼ばれてるので、開始時に取得するように修正(途中)
=> 14468

18:17
viewからentryを何度もSQLで取得してたので、一括して取得するように修正
=> 15476

18:31
/entriesでコメント数を取るために何度もSQL実行してたのを一括して取得するように修正
=> 16704

18:45
/footprints, /friendsでget_userを何度も実行してたのを一括して取得するように修正
nginxのaccess log をoffに
=> 19450