僕のYak Shavingは終わらない

車輪の再発明をやめたらそこには壮大なYakの群れが

ISUCON2014予選でがんばってきた

去年に引き続きISUCON予選に参加しました。

チーム名は「／＾o＾＼ﾏｯﾐｮｻｰﾝ」で最終スコアは26890でした。チームメイトはid:kazupyongと@kokonokaです。

18時過ぎた時点での管理画面での順位は24位でした。

一日目チームはベンチマークツールに致命的なバグがあってそれで高スコアを出していたチームがいたみたいですが、こっちは普通にworkload 18くらいでフィニッシュしました。

言語はrubyで、今回特にミドルウェアの変更・追加は一切行いませんでした。

スコアの上がり方はこんな感じ。

score

前半はずっとinputと最初の一手の実装に時間を使ってしまっていて、全体の時間を有効に使えませんでした。このへんは完全なる実力不足ですね＞＜

やったこと

初期準備

まずはいつものように公開鍵を配ってメンバー全員がsshで入れるように。

その後bitbucketでレポジトリをつくってpush。そこからアプリケーションを眺めて全容を把握。DBの構造とapp.rbを一通り眺めてbenchを流して見るって感じ。

初期スコアは1200くらい。

それが終わったらまずはmysqlのスロークエリを出します。

my.cnf

[mysqld]
slow_query_log=ON
slow_query_log_file=/tmp/mysql-slow.log
long_query_time=0

pt-query-digestが便利なのでそれもインストール。

sudo yum -y install perl-DBI perl-DBD-MySQL perl-Time-HiRes
sudo yum -y install perl-IO-Socket-SSL
sudo rpm -ivh http://www.percona.com/redir/downloads/percona-toolkit/2.2.10/RPM/percona-toolkit-2.2.10-1.noarch.rpm
pt-query-digest /tmp/mysql-slow.log > ptqd.log

こんな感じでスロークエリを解析しました。

ヤバイやつからワーストでランキングされて見れるので機械的に上から改善して行ってもほぼ問題ないと思います。

またnginxでaccess.logも出しました。レスポンスタイム含めてLTSVで出しましたが、特にLTSVである意味はなかったと思ってます。

/etc/nginx/nginx.conf

    log_format  ltsv  'host:$remote_addr\t'
                      'user:$remote_user\t'
                      'time:$time_local\t'
                      'req:$request\t'
                      'status:$status\t'
                      'size:$body_bytes_sent\t'
                      'referer:$http_referer\t'
                      'ua:$http_user_agent\t'
                      'taken:$request_time';

    access_log  /tmp/access.log ltsv;

アクセスログのレスポンスタイムなども集計できるスクリプトをつくって以下みたいに出力してました。

NGINX REPO
sum[sec] ave[msec] count URL
40       69        591   POST/login
18       18820     1     GET/report
7        79        100   GET/mypage
4        4         1183  GET/stylesheets/bootstrap.min.css
4        4         1183  GET/images/isucon-bank.png
3        3         1183  GET/stylesheets/bootflat.min.css
3        3         1083  GET/
2        2         1183  GET/stylesheets/isucon-bank.css

count  status_code
5912   200
591    302
4      304

これを見るととりあえずlogin時のPOSTでレスポンスタイムの総時間が40秒となっていて他のページよりも割合的に時間がかかっているので、ここを修正すればいいことがわかります。 去年のISUCONと同じ集計スクリプトを使いまわしていたので楽でした。

login時のボトルネック外し

ログイン時にログイン成功・失敗の情報を毎回login_logにINSERTしていたこと、そしてそこからSELECTして過去の失敗履歴を算出しているクエリがワーストクエリだったことを受けて、まずはその部分で複雑なSELECTを実行しないように、専用のテーブルを作成しました。

ログイン失敗時にはそのテーブルにipとuser_idをINSERT or UPDATEして失敗数をCountして行き、ban or lockされているかはそのテーブルからシンプルにSELECTするだけでいいように変更していきました。 作業する度にスコアが徐々に上がり、1200→3000→4500となり、workloadをこの辺でいじり始めて7000ほどになり、最後にlogin_logが必要なくなったのでINSERTしてる部分も削除してスコアが1万を越えました。

終了2時間前くらいでやっとインデックスを貼る

別に最初から貼ってもいいですが、login_logなどは使わなくなることが戦略的にわかっていたので、無視して続けていました。

ここで自分たちで追加したbanとlockを管理するテーブルにおけるクエリが、スロークエリのランキグの上位を占めていたので、INDEXを貼ったら1万5千くらいまでになりました。

my.cnfのチューニング

id:kazupyongさんの秘伝のタレを豆乳！2000くらい寄与した気がします。

cannot assign requested address

このへんでベンチツールが悲鳴を上げるようになりました。直感的にulimitかなって思ったのですがとりあえず何も変わらず、最終的にtcpかなーって言ったらid:kazupyongさんが記事を発見して解決してくれました。さすが！

参考記事

http://d.hatena.ne.jp/download_takeshi/20091013/1255443592

http://blog.ybbo.net/2013/05/27/tcp%E3%81%AEtime_wait%E3%82%92%E7%84%A1%E3%81%8F%E3%81%99%EF%BC%81/

workload調整

workload 4くらいでずっと来ていたのを一気に12や18とかに増やして行き、いい場所を探しました。結果的にこれで2万くらいになりました。

nginxによる静的ファイルのキャッシュ化

どの時点でやったか忘れましたが、この変更では数百くらいしかスコアがあがらなかった認識です。

打つ手をなくし1時間くらいぶらぶらする

新規にテーブルを作成してカウントする方法は元々安牌で、時間があればmemcachedにしようと思っていたのですが、結果的に最後でバグるのを怖れ動けずにいました。

この時点でやったら1万くらい上がっていたかも？

またこの時点で、レスポンスタイムの総計が一番大きいのがGET /となっていたので、これを解決しようとも考えていました。

原理的にはクッキーに値を埋め込んで、nginx側でif文で振り分けURLをリライトすればnginx側だけでキャッシュしたページを捌けるので速くなるだろうと踏んでいましたが、

「え、それどう設定すればいいの(^q^)」ってなって断念。

普段からやってないことはやっぱりできないですね、、、

ラスト20分、思いつきの一手

GET /改善したい！って思って、超雑にrubyの変数を使ってerbのレンダリング結果をキャッシュするようにしました。unicornで10プロセス立ち上がっているので、正直効率悪いのですが、これとworkloadの調整で最後に20000から27000くらいまであがりました。

app.rb

     get '/' do
-      erb :index, layout: :base
+      if flash[:notice] == "This account is locked."
+        $html_l ||= erb :index, layout: :base
+      elsif flash[:notice] == "You're banned."
+        $html_b ||= erb :index, layout: :base
+      elsif flash[:notice] == "Wrong username or password"
+        $html_w ||= erb :index, layout: :base
+      elsif flash[:notice] ||= "You must be logged in"
+        $html_y ||= erb :index, layout: :base
+      else
+        $html ||= erb :index, layout: :base
+      end
     end

はぁー、nginx力あげたい。

終わりに

正直自分たちのレベルでやりたいことは全部やってしまっていて、できると思った実装は全部実現しただけでも良かったのですが、まだまだ実力不足ということを思い知らされました。

実力があれば、

  • テーブル増やしてカウントの対応をやったあと、memcached/redisでさらに高速化できた→実装速度不足
  • tcp周りで意外に時間を消費した→Linuxのカーネルパラメータ周りの設定経験不足
  • MySQLだけでもhandlersocketが使えた？→知らん、経験不足
  • nginxの設定だけで出すべきGET /を振り分け→一度でも勉強していればすぐできた
  • 他、気づいてない部分での高速化

などできたのかなと思います。

また過去の経験からhtopやdstatは使ってるとかっこいいけど、パフォーマンスを上げることについてはなんら寄与しない

って思っていましたが今回もそうでした。強いて言うならhtop叩いてcpuが暇してればworkloadの変更の時ってことくらいですね。

測定からボトルネックを探し、そこに集中して改善作業を続けるってことは完全に実践できたと思うので、あとは

  • 測定力そのものを上げる→自分たちが気づいてないボトルネックがあるはず
  • 改善力を上げる→自分たちが実装できないことがたくさんあったはず

ということで、来年へ向けて刃を研いで行きたい所存です。

運営の方へ

楽しいISUCONをありがとうございます。

来年もまた実力を上げてリベンジしたいと思います。

来年はworkloadで何も変なことが起こらないといいですね★

お疲れ様でしたm( )m