ISUCON7優勝者と社内ISUCONに出て学んだ12のこと - ps aux

昨日新卒研修向けの社内ISUCONがあり、ISUCON7の優勝者であるsuzukiくんとペアを組んで去年の新卒という枠*1で出させてもらった。*2

僕のISUCONレベルは、社内ISUCONを新卒研修のときに1回やったことがある程度で、レベル5まであるとすれば僕は確実に1ですね。一度やったことがあるというだけですｗ

レベル1の僕が学んだことなので、ISUCONの常連さんには当たり前のことなのかもしれませんが、順番に書いていきたいと思います。

今回のお題
学んだ12のこと
まとめ

今回のお題

ゲームのハイスコアのランキングを記録&表示するようなアプリケーションで、ユーザの登録やログイン、ランキング等のJSON APIがありました。

初期状態では、docker compose で webapp(Ruby Sinatra) & nginx & mysql & redisが動くような構成で1台構成でした。

参加チームは全部で8チームで、新卒チームは6チーム、先輩チームは僕達のチームと別のチームが1チームありました。

学んだ12のこと

準備を爆速で終わらせる

恐らくどんなISUCONでも効率よく改良するのに必要なGitのprivateリポジトリに初期状態をpush & sshのパスワード認証なし & alp等のインストール辺りのことをを目にも留まらぬ速さで終わらせていて、びっくりしました。

何か秘伝のスクリプトを流したのでしょうか。また今度(今日?)聞いてみたいです。

これを行うことによって、効率よく開発できるようになりました。

初期ベンチ回してアタリを付ける

dstatで見ていると idle が 50とかになってるのをみて、負荷がかかってないということにすぐにsuzukiくんは気づいてました。同時に docker stats 等も見ていたようで、 webappの負荷がかかってないというのを見て*3、 unicornのworker_processes を 1から10に変えていました。

この変更で 2738 だったスコアが 23256 になりました。 *4

初期ベンチの dstat↓

  epoch   |usr sys idl wai hiq siq| 1m   5m  15m | used  buff  cach  free| read  writ| read  writ| recv  send
1524705622| 50   1  50   0   0   1|0.38 0.11 0.03| 342M 45.9M  341M 2980M| 136k    0 |6.00     0 |2162k 1496k
1524705623| 50   0  49   0   0   0|0.38 0.11 0.03| 341M 45.9M  341M 2981M| 136k    0 |6.00     0 |2453k 1696k
1524705624| 50   1  50   0   0   0|0.38 0.11 0.03| 341M 45.9M  341M 2981M|   0     0 |   0     0 | 869k  602k
1524705625| 51   0  50   0   0   0|0.43 0.13 0.04| 340M 45.9M  341M 2982M|   0    64k|   0  4.00 | 219k  155k
1524705626| 50   1  50   0   0   0|0.43 0.13 0.04| 340M 45.9M  341M 2982M|   0     0 |   0     0 |1796k 1242k
1524705627| 50   0  50   0   0   0|0.43 0.13 0.04| 340M 45.9M  341M 2982M|   0     0 |   0     0 |  19k   19k
1524705628| 50   0  50   0   0   0|0.43 0.13 0.04| 340M 45.9M  341M 2982M|   0     0 |   0     0 |7164B 7552B
1524705629| 50   0  50   0   0   1|0.43 0.13 0.04| 340M 45.9M  341M 2982M|   0     0 |   0     0 |  17k   17k
1524705630| 50   0  50   0   0   0|0.48 0.14 0.04| 340M 45.9M  341M 2982M|   0    56k|   0  4.00 | 218k  153k
1524705631| 50   0  50   0   0   0|0.48 0.14 0.04| 340M 45.9M  341M 2982M|   0     0 |   0     0 | 169k  119k
1524705632| 50   0  50   0   0   0|0.48 0.14 0.04| 341M 45.9M  341M 2982M|   0    80k|   0  4.00 | 137k   98k
1524705633| 50   0  50   0   0   0|0.48 0.14 0.04| 341M 45.9M  341M 2981M|   0     0 |   0     0 |7164B 7568B
1524705634| 50   0  50   0   0   1|0.48 0.14 0.04| 341M 45.9M  341M 2981M|  80k    0 |4.00     0 |2140k 1478k
1524705635| 50   0  50   0   0   1|0.52 0.16 0.05| 341M 45.9M  341M 2981M|   0    56k|   0  4.00 |2268k 1565k
1524705636| 50   1  50   0   0   0|0.52 0.16 0.05| 341M 45.9M  341M 2981M|   0     0 |   0     0 |1058k  732k
1524705637| 50   0  50   0   0   0|0.52 0.16 0.05| 341M 45.9M  341M 2981M|   0     0 |   0     0 |8004B 8062B
1524705638| 50   0  50   0   0   1|0.52 0.16 0.05| 341M 45.9M  341M 2981M|   0   240k|   0  46.0 |1486k 1028k
1524705639| 50   0  50   0   0   0|0.52 0.16 0.05| 341M 45.9M  341M 2981M|   0     0 |   0     0 |  20k   17k
1524705640| 49   1  49   1   0   1|0.56 0.17 0.05| 341M 46.0M  341M 2981M|   0    96k|   0  12.0 |6607k 4559k
1524705641| 50   0  49   1   0   0|0.56 0.17 0.05| 341M 46.0M  341M 2981M| 192k  544k|8.00  69.0 |2319k 1616k
1524705642| 50   1  50   0   0   0|0.56 0.17 0.05| 341M 46.0M  341M 2981M|   0   128k|   0  12.0 |  47k   39k
1524705643| 51   0  49   1   0   0|0.56 0.17 0.05| 341M 46.1M  341M 2981M|   0  1672k|   0  62.0 |  27k   24k
1524705644| 49   1  50   1   0   0|0.56 0.17 0.05| 341M 46.1M  341M 2980M|  32k  416k|2.00  57.0 | 176k  139k
1524705645| 50   0  49   1   0   0|0.59 0.18 0.06| 341M 46.2M  342M 2980M|   0  1480k|   0  30.0 |  20k   20k

静的ファイルの配信をnginxでする

当たり前といえば当たり前なのですが、Rubyで静的ファイルを配信していたようなので、suzukiくんがこの辺を秒で修正してくれました。

scoreが 23256=>39689 となりました。*5

f:id:serinuntius:20180426234916p:plain

旧スーパールーキー が僕たちのチームなのですが*6、このグラフを見るとスタートダッシュを決めています。(フラグ)

メガネ師弟が先輩のチームで、その他が新卒チームです。

分析基盤を作る

先程のsuzukiくんの作業の裏で僕はどのリクエストが遅いのかを知りたかったので、 nginxのログフォーマットを ltsvにしていました。何故かと言うと、id:tkuchiki さんのalpで分析するためです。

この変更をして、1回ベンチを回しました。特にスコアの変動はありませんでしたが、ログが取れたのでリクエストが多くてAVGが遅いリクエストを探しました。 alpの使い方は、公式README読むのが手っ取り早いです。

それが終わって、僕は更にmysqlのスロークエリログを出す準備をしていましたが、いろいろと躓き何度かのmy.cnf書き換えと再起動でやっとスロークエリログができました。

# my.cnf
slow_query_log      = 1
slow_query_log_file = /var/log/mysql/slow.log
long_query_time     = 0.1
log_queries_not_using_indexes = 1

long_query_time が 0 だと全部のクエリログを出すみたいな設定だった記憶なのですが、0じゃ出なかった気がしたので*7、 0.1に設定してとりあえずほとんど全てのクエリのログを一旦出しました。

そこで、pt-query-digestを入れて分析したかったのですが、上手く入れれず*8断念し、生のスロークエリログを見ました。これが後に仇となります。

下記のようなコマンドで、遅い時間を見つけ出し、lessで 0.765559 で検索してクエリ見るみたいなことしてました・・・。 shell芸が苦手過ぎて適当にやってたのですが、普段からもう少しshell芸をして良い感じにスロークエリログを見たかったです。

cat /var/lib/docker/volumes/webapp_mysqllog/_data/slow.log | grep time|grep -v timestamp|uniq|sort
# Query_time: 0.695324  Lock_time: 0.000125 Rows_sent: 0  Rows_examined: 666440
# Query_time: 0.695372  Lock_time: 0.000123 Rows_sent: 0  Rows_examined: 666440
# Query_time: 0.700617  Lock_time: 0.000132 Rows_sent: 0  Rows_examined: 666440
# Query_time: 0.714136  Lock_time: 0.000146 Rows_sent: 0  Rows_examined: 571408
# Query_time: 0.721184  Lock_time: 0.000145 Rows_sent: 0  Rows_examined: 666440
# Query_time: 0.730309  Lock_time: 0.000173 Rows_sent: 0  Rows_examined: 666440
# Query_time: 0.765559  Lock_time: 0.000101 Rows_sent: 0  Rows_examined: 523892

ここで、僕が犯した最大のミスは遅いクエリだけを探していた ということです。遅いクエリを探すことはもちろん大切なのですが、そのクエリがどんだけ発行されてるかもかなり重要です。

何故ならどんなに速いクエリでも10000回投げると馬鹿みたいに重くなるからです。*9

例) 10 ms/回 * 10000回 = 10sec

pt-query-digest はちゃんとその辺りのことを考慮して、発行回数と遅さを出してくれるので使うべきです。テンパって何故pt-query-digestで分析するのかを忘れていました。

ちなみに、やっとの思いで僕が見つけ出した、遅いだけのクエリはこれでした。

select user, sum(score) as score, max(created_at) as created_at from score group by user order by score desc LIMIT 5 OFFSET 0;

まぁ集計してて、重そうだなという感じですね。

適当にindex張ったらいけるんじゃないかな〜と思って、下記のようなindexを張ってみてベンチ回すとスコアが上がりました。

CREATE INDEX user_score_idx ON score(user,score);

よっしゃ〜となっていたのですが*10、前回のキャッシュが載って(?)スコアが上がっただけのようでした。このスコアの再現性はありませんでした・・・。スコアが上がった気がしたので、マージしたのですが、あとでEXPLAIN見てと全く効いてなかったので絶望しましたw (よくよく考えてみたら、どうやったらこれでindexが効いて速くなると思ったんだw)

このあたりで、時間がかかっていたので、メガネ師弟 チームに大きく差をつけられました。 f:id:serinuntius:20180426235624p:plain

静的ファイルのキャッシュ

suzukiくんが、静的ファイルのキャッシュの設定を適切に裏でサクッとやってくれたので、 scoreが76507 になりました。

f:id:serinuntius:20180427000233p:plain

ここでscoreのインフレ対策がされ今までのscoreはリセットとなりました。

ループクエリ撲滅

遅いだけのクエリよりも、同一リクエストで呼ばれているN+1のループクエリがボトルネックとなっていました。それに気づいたのが、開始2時間たったときの出題者でありISUCON7の優勝者でもある id:ken39arg さんからの下記のヒントのおかげで、わかりました。

`/scores` に関して、x/xx の研修でのxxxさんの参考実装から劣化している部分があります

実はこのWebアプリケーションは新卒研修で今まで新卒氏たちが日を追うごとに実装してきたものにISUCON要素を足したもので、ところどころAPIの追加があったりデチューンされたりしています。

ISUCON対策研修で、ループクエリは遅いよみたいなことを教えているので、出題者としては新卒氏たちにそこに気づいて欲しいみたいな感じですね。

僕は遅いだけのクエリに気を取られて、全然気づいていませんでしたが😇

そのヒントを得てテンパりながらも比較していると、APIが追加されてたりもするのですが、どう見てもヤバい箇所を発見！！

ranking = list.map do |r|
    {
      rank: s.rank(r[:score]),
      name: u.find(r[:user])[:user_id], ## ヤバい！！！
      image: r[:user] % 10 + 1,
      score: r[:score],
      created_at: r[:created_at].to_i,
    }
  end

全部のコードを公開していいのかわからないので部分的に公開するのですが、u.find とやらでループの中でクエリが呼ばれていました。参考実装では、リストの外で一括でuserが取得されているようなコードでした。

  users = u.find_all_by_ids list.map { |r| r[:user] }.uniq

出題者の優しさなのか参考実装から少しコピペしてきて修正すれば動くようになっていました。これと全く同じ施策が他のスコア系のAPIでも使えて、スコアが1500ぐらいから2421 に上がりました。

f:id:serinuntius:20180427000519p:plain

テーブルの非正規化

4の分析基盤のところで書いたような集計クエリがどうしても遅いので、suzukiくんがRedisのsorted setに入れるか非正規化するしかないみたいな提案をしてくれました。

お互いに、Redisのsorted setを使って残り時間でちゃんと実装できる自信があまりなかったので、テーブルの非正規化を進めることにしました。

ベストのスコアと、トータルのスコアを毎回集計するクエリが走っていたのですが、それをベストのときだけuserテーブルに入れる、変わったときだけトータルのスコアをuserテーブルに入れておくとすると、重い集計クエリがなくなるので良い感じです。

非正規化もISUCONやるなら当たり前のテクニックなのかもしれませんが、テーブルの構造とかロジックをゴリッと変える必要があるのでかなり勇気のいるところですし、ベテランしかたぶんやらないでしょう。

そんなベテランの手法をサラッとsuzukiくんは提案してくれるので、めっちゃ強いですし、尊敬します。

ここで作業を分担することにしました。

suzukiくん

テーブル構造変える
ベストのスコアのときはuserにベストスコアをupdateする系のロジック

僕

テーブル構造が変わると信じて、あらゆるAPIの省クエリ化を図る

そして、この手は今までの手と違いとても時間がかかるので、どんどんスコアが抜かされていきかなり焦りました・・・。

f:id:serinuntius:20180427002916p:plain

ひたすら信じてゴリゴリAPI書き換えて、ようやくお互いマージできるかなというところでマージしてみて、4回ほどエラーを修正したら上手く動くようになってベンチ回して、16時にscore2421=>5096。後1時間しかないのに、思ったようにスコアがはねませんでした。

このマージ作業が終わる直前に、僕の手が少し空いていたので、次のボトルネックになりうるところの予測をして、ロジックを先に書いておきました。これも非正規化が出来たからこそ出来る系のクエリ削減系のやつで、なんとなくこうなるだろうな〜みたいな感じでふんわり書いてました↓。

def user_score_gori(user)
    u = UserService.new db
    res = {}
    res[:best_score] = user[:best_score]
    res[:total_score] = user[:total_score]
    if res[:best_score] != 0 then
      res[:best_rank] = u.find_best_rank(user[:id], user[:best_score])
    end
    if res[:total_score] != 0 then
      res[:total_rank] = u.find_total_rank(user[:id], user[:total_score])
    end
    res
  end

この辺は頭が疲れすぎてメソッド名を考えるのも辛かったので、 user_score_gori とかいうゴリっとscoreのロジック変えちゃうメソッドを書いてましたｗｗ

u.find_best_rank と u.find_total_rank というメソッドはロジックが間違っていたので、suzukiくんに修正してもらいました。

で、これでベンチ回したら、5096 => 495925 ！！！！！

f:id:serinuntius:20180427004056p:plain

自分が想像していたボトルネックの箇所が修正されて、スコアが跳ねたときの脳汁具合はたまりません！！*11

たぶん、僕の最大の貢献はここの修正箇所で、次のボトルネックになりそうなところを探しておいて大正解でした！！

ボトルネック以外を修正する意味の薄さ

追記 2018年4月30日

パスワードのストレッチングは重い処理だという風に聞いていたので、bcryptのストレッチングのコストをデフォルトの10*12から1とかにすればscoreがあがるのでは？~~と思ったのですが、まだそこはボトルネックではなかったみたいで、全くscoreが上がりませんでした。~~

訂正です。同時並行で他の施策を打っていたので、こちらの効果がなかったように感じていたのですが、どうやらめちゃくちゃ効果があったようです。これをやらないと、40万点~60万点ぐらいしか行かないようですが、これのおかげで100万点のラインに乗るとのこと！

BCrypt::Password.create(password, :cost => 1)

ISUCONはボトルネックじゃないところを修正してもあまり意味がないっていうのが面白いところですよね！*13

最終ベンチでFailしたらダメ！！！

最後の5分ぐらいで気づくのですが、実際のWebアプリケーションを見てみるとスコアのページネーションのロジックを間違えていて、

1位
2位
3位
4位
5位
6位
7位
8位
9位
10位
[もっとみる] # 押すとさらにそれよりしたのスコアが出て来る
1位
2位
3位
.
.
.

みたいな感じになっていて、11位となって欲しいところが1位に戻ってしまってました。

これはベンチマーカにもエラーで怒られていたのですが、最後の方だったのでなんか出てる〜ぐらいでスコアがめっちゃ下がったりはしていなかったのですが、これはレビュレーション違反で、

rankが正しく動作しない場合は失格です

という条件があるので、失格というオチでしたｗｗ目視チェックが最後にあってバレましたｗちなみに最後のscoreは370166 でした。

なので、結局先輩チームのメガネ師弟チームが優勝でした。先輩の面目のために書いておきますと、先輩のチームは1人の方が途中MTGで退出するなど僕らとは同じ条件で戦ってなかったのです。

お互いを信じる!!

これは終わってからsuzukiくんと話してたことなんですが、7のテーブルの非正規化のところでお互いを信じてアプリをゴリゴリ書いて、マージするときにお互いにちょっとミスってるところとかサクッと指摘してマージ出来たのが最高でした。

もしここでお互いを信じていなければ、ゴリッと作戦は失敗だったでしょうし、このスコアは残せなかったでしょう！！

助けられてばっかりでしたが、 suzukiくんありがとうございました!!! suzukiくんのおかげで、ISUCONの楽しさを味わうことができました！

MySQL(RDBMS)遅くない!

これは僕が学生のころに勝手に思ってたことなんですが、RDBMSは遅くて、KVSは速い！みたいにずっと思ってました。

しかし、これはほとんどの場合そうではなくて、吐かれているクエリやテーブル設計、インデックスが適切じゃないので、RDBMSが遅く感じてしまうのです。

なので、今回Redisのsorted set作戦は取りませんでしたが、ちゃんと結果は出せてますし、何よりRedisに消えたら困るようなものを入れちゃダメなのです。

Dockerがネックになってくる

競技終了後もいろいろやっていって最終的にscore1000000ぐらいまで行ったのですが、suzukiくん曰く、Dockerがネックになってきているらしいです。 dstatみてるとsys側に負荷がかかってきて、docker stats で Nginxの負荷がかなりあがって来てて、Dockerを剥がせばもう少し伸びそう。

僕はこのあたりの知識も全くないので、やっぱりsuzukiくんはすごい。

追記 2018年4月30日

ISUCON7優勝者と社内ISUCONに出て学んだ12のこと - ps aux | grep serinuntius
[MySQL]
[isucon]

簡易なものならmysqldumpslowというものがMySQLのパッケージについてきてるからpt-query-digestが使えないならおすすめです。slowlogは0で良いです。docker ネックは本当にそうなのかが気になります
2018/04/27 13:28

b.hatena.ne.jp

こちらのコメントありがとうございます。MySQLの設定は僕のミスですね。

Dockerがネックになっているのは本当で、suzukiくんがisucon終了後「Dockerから全部剥がす」という施策の検証を行ってくれましたが、剥がすだけで100万点 => 140万点になったようです。

その後は、ボトルネックがMySQLに変わったそうです。

ISUCON7優勝者と社内ISUCONに出て学んだ12のこと - ps aux | grep serinuntius https://t.co/tfnvd3HCVg
dockerが本当にボトルネックなのかという質問（？）があったので検証してみました。結果としてはdockerから剥がすだけで100万点から144万点に上がりました。
— 🚀GRIMM・ZOU🐘 (@jet_zousan) 2018年4月27日

まとめ

運営の方、新卒の方、suzukiくん、お疲れ様でした！

ISUCONは楽しい
ISUCONは最高
ISUCONは脳汁がヤバい
MySQLの負荷が支配的じゃなくなったときの嬉しさ

弊社は、やっぱりISUCONの文化が根付いていて、優勝者が近くにたくさんいるのが強い。 7回中4回優勝してるってすごすぎるよな〜。

去年はISUCON出れなかったけど、今年は出たいと思います。そして、頑張って本選行きたいｗ

suzukiくんに助けてもらってばっかりの社内ISUCONでしたが、本当に最高でした。お疲れ様でした。

*1:1年で学んだことを魅せつけてやれ！みたいな役割ですね

*2:恐ろしいことにsuzukiくんはISUCON本選で優勝してるけど僕と同期なんです！！！

*3:たしか

*4:最初のベンチマークはちょっとインフレしすぎるので、後でインフレ対策が行われました。

*5:これもインフレ対策前

*6:先輩が勝手に命名してくれた

*7:ただ焦ってちゃんと反映して再起動できなてなかっただけかも

*8:焦ってたからかな・・・

*9:ループクエリとかは典型的なパターン

*10:俺も1年でindexぐらい学んだぜｷﾘｯみたいな感じでした・・・。何も学んでなかったｗ

*11:結局suzukiくんに手伝ってもらいましたがw

*12:ちなみにこの10っていうのは10回ストレッチングするということではなく、2の10乗回ストレッチング処理をするという意味です。

*13:後でそこがボトルネックになって効いてくる可能性はあります