毎年恒例の新卒ISUCONを行いました！

こんにちは！今年の4月にインターン生から新卒にランクアップした新谷(@euglena1215)です。新人研修の一環として行なった新卒ISUCONの様子をお知らせします。

新卒ISUCONとは？

弊社ではwebアプリケーション開発の基礎となる知識を実践的に吸収するため、新人研修の一環として新卒メンバー+CTOでISUCONを行うことが恒例になっています。

去年の新卒ISUCONの記事はこちら↓

また、今年からの試みとして以下の3つの制度を新たに導入しました。

1. 新卒ISUCON オリエンテーション
2. 競技中 30分間×2のメンターへの相談タイムの導入
3. AWSアカウントを配布して練習用EC2インスタンスを開放

EC2インスタンス開放はそのままの意味なので、1. 2. について簡単に紹介します。

新卒ISUCON オリエンテーション

今までの新卒ISUCONではGoogle CalendarにシュッとISUCONが入れられて「この日までに対策しておいてね！」というスタンスだった(?)らしいのですが、今年からは本番1週間ほど前に@south37からオリエンテーションがありました。

このオリエンテーションでは「なぜ新卒ISUCONを行うのか」「どう戦っていけばいいのか」「AWS AMIを利用してISUCONの練習環境を自分で構築してみる」などの説明がありました。

オリエンテーションのスライドはこちら↓

競技中 30分間×2のメンターへの相談タイムの導入

各チームには事前に問題を解いているメンターが付き、13:00~13:30 / 15:00~15:30に相談ができるというシステムです。

各チームは相談タイムを以下のように有効活用していました。

• 一緒にボトルネックを調査する
• ペアプロを行い実装する
• 判明している情報からのボトルネックの推定へのロジックに論理の飛躍がないか壁打ちをする

ISUCONは初期スコアからほとんど変化せずに競技終了するパターンが一番楽しくないので、そのリスクを下げることができるとても良い仕組みだと感じました。

昨年までの戦績

昨年も一昨年も新卒ISUCONという名前を冠しているのにも関わらずCTOが優勝するという事態が発生していました。

なので、今年こそ絶対に勝つ👊という強い意志を持って練習に励みました。

打倒CTO(Chief Tottemo Otonagenai)を望む声

今年のチーム編成

今年の新卒ISUCONに参加したチームは新卒ペア×3組、CTOの計4チームでした。使用言語は全チームRubyでした。業務で使っている言語を選んでくるあたり本気度が伺えます

僕は奥山さん(@spring1018)とペアを組んで参加しました。奥山さんは正確には新卒ではないですが、新卒枠ということでISUCONに参戦しています。

今年の問題

今回の新卒ISUCONではYahoo! JAPANさんが公開しているY!SUCONを利用させていただきました。面白い問題をありがとうございます！

Y!SUCONは本来1台のサーバで解くことが想定されている問題ですが、今回は3台のサーバ(c4.large)が与えられました。

Y!SUCONの問題であるIsuwitterは名前の通りTwitterっぽいアプリケーションです。
ツイート数のオーダー大きそうだなとかフォロー/フォロワーの関係をどんなデータ構造で保存してるんだろうとか色々気になりますね！

それでは競技スタートです！

競技開始

自分たちのチームが取り組んだことを書いていきます。合わせて雰囲気が伝わるように、各チームが取り組んでいた様子を写真で紹介します。

Team-C: @takose, @kamez

まずはsshでサーバにアクセスして

• ソースコードをGit管理下に置く
• kataribe, myprofiler といったプロファイリングツールのセットアップを行う
• Nginx, MySQLの設定ファイルもGit管理下に移す(MySQLじゃなくてMariaDBだった、まだ焦るときじゃない)
• DB schemaを確認してホワイトボードにまとめる

など定番の設定をシュッと済ませました。この辺りの設定は予めwikiにまとめていたので詰まらずにできました。wikiべんり

一通りプロファイリングできるようになったので計測を行いつつ、benchmarkを実行すると初期スコアが1500点であることが判明。ここからスコアを上げていきます。

kataribeの結果を見ると静的ファイルの配信が支配的すぎて、他のendpointの結果がほとんど分からない状態になっていることが分かりました。

Top 20 Sort By Total
Count   Total      Mean    Stddev    Min  ...    Max  2xx  3xx  4xx  5xx  Request
  315  59.817  0.189895  0.281739  0.000  ...  1.272  315    0    0    0  GET /js/script.js HTTP/1.1
  174  45.093  0.259155  0.321970  0.003  ...  1.250  174    0    0    0  GET / HTTP/1.1
  315  23.896  0.075860  0.162356  0.001  ...  0.980  315    0    0    0  GET /favicon.ico HTTP/1.1
  314  19.359  0.061653  0.188784  0.000  ...  1.258  314    0    0    0  GET /css/style.css HTTP/1.1
    7   8.583  1.226143  0.242832  0.840  ...  1.527    7    0    0    0  GET /hashtag/travel HTTP/1.1

なので、静的ファイルはNginxで配信するように変更してあげます。ついでに304も返すようにします。
→ Pull Request

    # こんな感じ
    location ~ \.(css|js|ico|eot|svg|ttf|woff|woff2)$ {
      expires   max;
      add_header Pragma public;
      add_header Cache-Control "public, must-revalidate, proxy-revalidate";
      etag off;
    }

    location / {
      try_files $uri @app;
    }

Nginxの変更を適用させるとスコアの変動はありませんでしたが、kataribeの結果がガラッと変わり GET / が支配的であることが分かってきました。

Top 20 Sort By Total
Count   Total      Mean    Stddev    Min  ...    Max  2xx  3xx  4xx  5xx  Request
  175  69.573  0.397560  0.374569  0.003  ...  1.362  175    0    0    0  GET / HTTP/1.1
   15   8.977  0.598467  0.403106  0.005  ...  1.237    0   15    0    0  POST /logout HTTP/1.1
   18   6.993  0.388500  0.294109  0.032  ...  1.308   18    0    0    0  GET /noriaki HTTP/1.1
    6   6.788  1.131333  0.318667  0.633  ...  1.620    6    0    0    0  GET /search?q=travel HTTP/1.1

benchmark中のCPU負荷がそこまで高くなかったのでおもむろにunicornのworker_processを1→2に上げるとスコアが1500→1700に上がり、しっかりとDBのCPU負荷がボトルネックになっていることが分かりました。なので、kataribeで得た情報と組み合わせ GET / で実行しているクエリを精査しようね、という話になりました。

Team-B: @hayaokimura, @unblee

GET / ではログインしているユーザーのフォロワーのツイートを50件返すという仕様でした。
ですが、実行されているクエリはSELECT * FROM tweets ORDER BY created_at DESC と全ツイートを取得し、アプリケーション側でフォロワー以外のツイートを弾くという無駄な実装になっていました。全ツイートは10万件あったので実際に必要なデータの2000倍取得していたことになります。無駄すぎる

これはあかんということで修正したところ、スコアが1700→3800点まで上がりました。わいわい。

さくっと修正できたように書いていますが、この修正に2時間かけてしまい修正中の僕のメンタルは地に堕ちていました。

泣きそうになりながらbinding.pry していると上長からDMが！！！

おっ、応援してくれてるのかな、ありがたいな、と思って見てみると...

自分のチームのscoreが伸びないことを喜ぶチームリーダーの図, 一番下が自分のチーム
絶対にゆるさない

kataribeをチェックするとGET / が速くなったことが確認でき、GET / , GET /search , GET /hashtag が同程度に遅いことが分かったのでこの3つのendpointの高速化を考えることにしました。

Top 20 Sort By Total
Count   Total      Mean    Stddev    Min  ...    Max  2xx  3xx  4xx  5xx  Request
   85  63.131  0.742718  0.235661  0.491  ...  1.534   85    0    0    0  GET /hashtag/*
   85  62.244  0.732282  0.213678  0.499  ...  1.579   85    0    0    0  GET /search?q=*
  421  61.022  0.144945  0.173544  0.002  ...  0.969  421    0    0    0  GET / HTTP/1.1
  210  18.781  0.089433  0.075525  0.025  ...  0.448  210    0    0    0  GET /?append=1&until=*

GET / はN+1問題が発生していたのでこれを解決すると3800→3941に。
スコアとしてはあまり変わらなかったけど、平均レスポンス速度が1.4倍と確実に速くなっているのでどんどんmergeをしていきます。

# Before
Count   Total      Mean    Stddev    Min  ...    Max  2xx  3xx  4xx  5xx  Request
  421  61.022  0.144945  0.173544  0.002  ...  0.969  421    0    0    0  GET / HTTP/1.1

# After
Count   Total      Mean    Stddev    Min  ...    Max  2xx  3xx  4xx  5xx  Request
  435  44.218  0.101651  0.135292  0.003  ...  0.610  435    0    0    0  GET / HTTP/1.1

GET /search , GET /hashtag は内部的に同じメソッドを呼んでいたため、1ヶ所修正すれば両方のendpointの高速化ができることが発覚。修正をしてbenchmarkを実行すると3941→13311とスコアが跳ね上がりました。

この修正によりCTOを引き離すことに成功しました！🎉🎉🎉
しかし、油断はできないので更なるスコアアップを狙っていきます。

Team-A: @euglena1215, @spring1018

いつものkataribeをチェックするとボトルネックがまた GET / に戻ってきています。どうやらY!SUCONは GET / を速くするバトルだったみたいです。

Top 20 Sort By Total
Count   Total      Mean    Stddev    Min  ...    Max   2xx  3xx  4xx  5xx  Request
 1466  62.976  0.042958  0.025205  0.002  ...  0.132  1466    0    0    0  GET / HTTP/1.1
  740  42.094  0.056884  0.018947  0.016  ...  0.137   740    0    0    0  GET /?append=1&until=*
  293  13.969  0.047676  0.018845  0.016  ...  0.119   293    0    0    0  GET /hashtag/*

この時点でぱっと見ボトルネックになるような箇所はなくなっていたので、CPUリソースを増やすために@spring1018には複数台構成のセットアップをお願いしていました。

が、2台目のサーバの/etc 以下が全て消え再起不能になる というアクシデントが発生し、僕たちのチームの残りライフは2になりました。

気持ちを切り替えて3台目のセットアップに取り掛かりましたが、セットアップが完了したのが競技終了間際で「これで壊れてfailしたら目も当てられないよね」と話をして1台構成で最後までやりきることを決意しました。

Team-CTO: @luvtechno

@spring1018に複数台構成をお願いしている間に他のボトルネックを見つけるためmyprofilerを眺めていると、SELECT * FROM tweets WHERE user_id = ? ORDER BY created_at DESC が突出して多いことに気付きました。

create index user_id_created_at on tweets(user_id, created_at);

そこで上記のようにuser_idとcreated_atの複合indexをtweetsテーブルに貼ってみると23914点までスコアがガッと伸びました！indexすごい

そこからはerbをerubisに置き換えて1000点アップし、Nginxのaccess logを切り、そのまま競技終了となりました。

結果発表

競技終了すぐに結果発表がありました。

優勝したのは...

ということで...

CTOを倒しました！！！🎉🎉🎉

奇跡的に勝つことができました、CTOに勝つためにちょこっと頑張って練習したので報われて良かったです。

ISUCON終了後、みんなで焼肉を食べました。ISUCONと言えば焼肉、焼肉と言えばISUCONです。

新卒Tから着替えずにチャリで目黒を駆け抜けて焼肉屋に向かったらしい

まとめ

普段はアプリケーション側ばかり書いていて、インフラのことをほとんど知らなかったので一から学ぶとても良い機会になりました！

面白い問題を提供してくださったYahoo! JAPANさん、新卒ISUCONを主催してくれた南さん、メンターを引き受けてくれた千葉さん、斎藤さんありがとうございました！

そして、

　　　CTOに勝って食べる焼肉はうまい！！！🍖

翌日

Writeup

Team-A:
@euglena1215

@spring1018

Team-C:
@ykamez