1.jpg

ベーシック アドベントカレンダー 22日目です。

社内 ISUCON 第2回目に参加し、前回に続き ISUCON 部門ではなんとか優勝することができた。正直、僅差でスコアを大幅に離すことができなかったので、優勝できたのはわりと運が良かっただけのような気がする。というわけで、社内 ISUCON の取り組みを振り返ってみる。

ちなみに今回の社内 ISUCON は ISUCON とコードコンテスト同時開催というトライアスロン大会かよと思うようなボリュームだった。

戦略

4人のチームメンバーでインフラが強いのは自分だけだったので、基本的には環境セットアップとインフラ足回りの設定を自分がやり、残りの3人はアプリケーションの仕様把握とコードリーディング、データベース周りの構造理解に時間を使うようにした。コードコンテストに関しては ISUCON の準備を午前に一通り終わらせて、午後に取り掛かろうと思っていたが結果的には戦略ミスだったような気がする。せめて問題を確認して難易度を把握しておくべきだった…。

また今回のレギュレーションで一番インパクトがあったのが**「再起動の動作保証が必要ない」**という項目。これは永続性が求められないのでキャッシュ戦争になるなと思った。通常の業務ではやらないようなダイナミックなアプローチが必要になる。

調査

まずは ISUCON のお作法的な調査。

  • まずデフォルトの状態でベンチマーカーを走らせる
  • nginx で実行時間を出力するようにして alp でリクエスト回数・処理時間がかかっているものを把握
  • MySQL の slow-query を出力するように設定
  • コードプロファイラは今回は導入しなかった（アプリケーションコードがシンプルだったので）

この時点で POST /votes へのリクエストが一番のボトルネックと判断。トップページもそれなりに処理が重そうだったけどロジックが多かったので後回しにすることに。

改善 Step1

簡単にできる改善をまずやってみる。

インフラ

  • CSS は nginx で返却するように修正
  • MySQL にメモリを潤沢に与えるように修正
  • nginx / unicorn の worker 数を CPU コア数に合わせて調整
  • cache-control ヘッダを追加

データベース

  • SlowQuery ログを見て、インデックスを追加したが、正直効果は薄かった
  • SELECT COUNT(*) や SELECT * となっている SQL をフィールドを指定
  • FOR LOCK などロック系はまったくなかったしシンプルな SQL だったので MySQL の細かいチューニングやバージョンアップなどはしないようにした

アプリケーション

  • dalli と memcached を入れてオブジェクトをキャッシュする
    • Redis にしなかったのは単純なキャッシュだけなら memcached で良いと判断したから

この時点でスコアは 9000 くらい。Ruby 初期スコアが 2200 くらいだった。

サーバが死ぬ

Swap 領域がなかったので、とりあえず作っておくか〜と適当に領域確保したら、Disk Full になってしまいサーバが死んだ。なにもできなくなった。競技終了かと思ったが再起動したら回復できた…良かった。ちゃんとディスク容量を確認しよう。

改善 Step2

ベンチマーカーの挙動を見ていると「投票」→「確認」という流れになっていた。実際のアクセスログを見ても POST しているのは最初だけで、後半は全部 GET になっていた。つまり、前半はデータ構造が変更されるが、後半はデータは固まっているということになる。つまりページ自体がキャッシュ可能になるということ。アプリケーションサーバ自体の負荷が減らせれば言語の差はだいぶなくなるはず。

そこで /candidates/:id と /political_parties/:id の詳細ページをすべて nginx で proxy cache させることにした。これでスコアが 18000 くらいになった。とはいえ同一 URL に2回以上アクセスするのはそこまでなかったが…。

また、このままだとベンチマークを2回連続で実行するとキャッシュが残っていて fail するので、/initialize リクエストされたときに nginx のキャッシュファイルを削除するようにした（同様に memcached も clear させている）。

ちなみに memcached の clear は TCPSocket を使った。

require 'socket'

socket = TCPSocket.new('127.0.0.1', '11211')
socket.write('flush_all')
socket.recv(2)

でも終わってから dalli 調べたら普通にインターフェイス用意されてた。普段使わないライブラリに対する知見のなさと焦りがこういった無駄な手順を踏むことになる…。

dalli.flush

KeepAlive してなくない？

なんかスコアが伸びないと言うか…ネットワーク周りが詰まっているような気がしたので netstat で確認したら TIME_WAIT ばかり。KeepAlive してくれないベンチマーカーなのか…？と思いつつ、スルーしてた。ここでアプリケーションが HTTPS のみということをちゃんと考えて、HTTP/2 が使えないのかを検証するべきだった…。

改善 Step3

この時点でお昼。午後の役割分担は、自分以外の3人がコードコンテンストをやって、自分は ISUCON のアプリケーションコード周りを担当。インフラは固まったので午後からはアプリケーションコードに集中しようと思っていたが、ベンチマークを実行するとなぜかスコアが 6000 程度にまで落ちてしまった。ここでもっと冷静になるべきだったかもしれないが、なぜ駄目になったのかが分からずインフラを色々いじってしまい泥沼へ。

スコアがまったく改善しないので、ダイナミックにやるしかないと決断。MySQL を捨てて全部データをメモリに乗せる方法を模索。この時点で残り3時間。キャッシュハンドリングできるかどうか分からないけど勝負へ。

メモリに乗せるまでのステップ

  • MySQL の Memory Engine が使えれば SQL そのままで速いかも
    • Memory Engine が使えたのは candidates テーブルのみだった
    • 他のテーブルはレコード数が多くてメモリに載せられなかった
  • Ruby の Singleton クラスにデータを全部ロード
    • 一通り作ったがレースコンディションを考慮していないコードだったので、集計数値が合わず fail
    • レースコンディションを回避するようなコードに仕上げるのは短時間では無理と判断
  • Redis に集計結果を突っ込む方式でいくことを決意
    • Redis はアトミックなインクリメントが可能なので一番確実と判断

INSERT 処理は1箇所しかないのに加えて、出力は基本集計されたものしか使わない。つまり votes テーブルのレコードが全部ある必要はないので POST /votes された時点で、Redis の incr を使って集計していけば良いだろうというアプローチ。

各ページで色んな集計結果を使っていたので、それぞれごとに Redis キャッシュキーを用意。

  • 候補者ごとの得票数
  • ユーザごとの投票数
  • 候補者 + メッセージごとの得票数
  • 候補者ランキング
  • ユーザランキング
  • 政党ごとの得票数
  • 性別ごとの投票数
  • 政党ランキング
  • 性別ランキング

ランキングには Redis の Sorted Set を利用した。これを使えばトップページで使われる得票数 Top10 とワーストを表示させるのも一発で取れる。

# Top10 を取得
redis.zrevrange "key", 0, 9

ちょっとつまったのは得票ランキングのワーストを取得する処理。ワーストは得票数が 0 のものも対象になる。つまりリクエストが来ないので Redis の集計データだけでは単純にはとれない。このときは焦っていて変な実装になったが、本来はシンプルに解決できたなと反省。

# 変な実装
# 集計済みの ID を根こそぎ取得
all = redis.zrevrange("key", 0, -1)
# マスタデータから NOT IN で集計されていないものを取得
query = <<SQL
SELECT id, name, political_party, sex
FROM candidates
WHERE id NOT IN (?)
order by id asc
limit 1
SQL
db.xquery(query, all).first

本来は初期化処理のときにマスターデータを元に ZADD してすべての ID を Redis に入れておくべきだった。

あとは既存の SQL に依存したコードを全部置き換えていくだけの作業。とにかくデバッグがつらく、ベンチマークを走らせても DOM 構造が違うだの、投票できないだので fail 続き。マイナス3万点くらいの状態がずっと続く。この時点で残り 30 分。もうだめ、もう無理、チームのみんなごめんという感じだった。地道に本来のロジックで出力されるデータと、自分で構築したデータの差分をプリントデバッグし続けた。pry / irb でのブレークポイントのデバッグをしたかったが readline 入れないといけなく、それすら時間が惜しかったのでスキップ。相当焦ってた。そして残り10分でなんとかベンチマークを完走するようになった。この時点でたしか 20000 弱だったかと思う。

このときの CPU 利用率では Redis が断トツトップ。次いで Ruby。nginx は普通。MySQL は空気。memcached はもう使っていないのに落とすことを忘れていた。

残り10分だと危険なことはできないので、worker 数の調整と sysctl.conf 調整を試してみた。sysctl.conf まわりのネットワーク調整は事前になんの調査もしてないし、現状のボトルネックを把握する余裕もなかったので適当に設定したらスコアが半分以下になったので、すぐ戻した。worker 数を調整することで、ようやく 20000 を少し超えたと思う。ここで試合終了。

結果、ISUCON 部門では1位がとれたが…もっとスコア伸ばせると思っていただけに、くやしい。ただ、短時間でここまでアプリケーションコードをいじれたのは結構がんばれたと思う。GitHub の変更差分を見ると…。

やりきれなかったこと

凡ミスというか忘れていたこと。

  • nginx などのログを出力しないようにするべきだった
  • Sinatra 側で生成した HTML 文字列をキャッシュして返すべきだった
  • Redis のスナップショットを生成しないようにするべきだった
  • MySQL ほとんど使ってないのでデチューンすべきだった
  • HTTP/2 を利用するべきだった

あと、相当焦ってたのか POST /votes が実は SQL をぐるぐるループして処理しているのに気が付かなかった。ここをバルクインサートにすれば Redis の処理がもっと軽くなったかもしれない（後で試したら、めちゃ負荷が下がっていい感じにスコアが伸びて 60000 くらい超えた）。

後日、反省会

ISUCON 開催後、個人的に反省会を開催。色々と試してみるとアプリケーションのスループットが上がると、ベンチマーカーが途中で死んでしまうという現象にぶち当たった。アプリケーションを遅くするとなんとか走り抜ける。仕方がないのでベンチマーカーのソースコードを読むことにした。

ちなみに AWS c4.large のサーバでスコアが 30000 を超えるとベンチマーカーが死ぬ。ベンチマーカー側で適当に標準出力に文字を出力し続けると、60000 程度までは伸びる。 ベンチマーカーの処理が抑えられて強制終了されないということなのかは謎…。 ベンチマーカーをデバッグしていくとリソース不足とかそういう類のことではなかった。これは後日改めて検証する。

ベンチマーカーの KeepAlive

ベンチマーカーは Go で書かれていてゴルーチンでリクエストを大量に処理している。HTTP/1.1 だと KeepAlive してくれなさそうな実装になっていたので、HTTP/2 に対応させないとここで詰まるっぽい。試しにレスポンスボディをすべて読みきるように実装を修正してみた（ ioutil.ReadAll(resp.Body) ）ところ多少はパフォーマンスは上がった。これは出題者の意図通りに差をつけたようだった。

反省

ISUCON チーム戦のチームたるパワーを引き出すのがぜんぜんできなかった。チームのみんな、ごめん。午前の部でみんなに調査を進めてもらっていたのは非常に有効で良い情報が手に入った。けど午後の部ではダイナミックな変更を開始してしまったので誰もヘルプに入れない状況を作ってしまった。コードレビューやデバッグを手伝ってもらうべきだったかもしれない。あとコードコンテストに関して、まったくタッチできなかったのでアドバイスをすることもできなかった。反省。結果、総合優勝ができなかった。

最後に

今回の社内 ISUCON はうまいこと立ち回れなかった部分が多かったが非常に楽しめた。運営のみなさんは準備が大変だったと思う。本当に感謝しかない。「音楽を流してほしい」とか「この音楽、集中力が…」みたいな文句ばかり言ってごめんなさい。サポートしてくれて助かりました。ありがとうございます。非常に成長できた1日でした。

Photo by Zach Reiner on Unsplash