フレクトのHeroku Lab

こんにちは。Heroku Meetup #6に参加してきました。

今回私はCode Consultingのプレゼンターの一人として発表させてもらいましたが(自分にとって)非常に有益な時間だったと感じています。
貴重な機会を与えてくださったHeroku社の方々に感謝します。

さて、そんな私のプレゼンですが後で懇親会で何人かの方から感想を伺ったところによると途中からよくわからなくなったという人多数。(--

あいすいません。m(_ _)m
昔から聴き手を置き去りにするプレゼンには定評があるんですが、今回は自分でも詰め込みすぎだったと思います。
また時間と同時通訳を考慮してカットした話も多いです。

なので、ここで完全版(?)の説明をお届けしたいと思います。当日使った資料は一応ここにありますが別に見なくても良いです。(^^;;;

★単純明快なシステム概要

まずネタにしたアプリですが、HTMLの装飾とかをとっぱらってシステムの骨子だけをとりだせばWEBフォームに入力するデータをDBにINSERTするだけという超単純なモノです。
例によってPlayframeworkで作りましたがサーバー側のコード自体は誰が作ってもこうなるだろう、というものでしたし別の言語を使っても似たり寄ったりだったでしょう。

はっきり言ってこれだけだとまったく箸にも棒にもかからないシロモノなわけですが、これがちょっと他と違っていたのは、そのサイトが毎年夏にやっている超有名テレビ番組から宣伝されるということです。

なので、URLがテレビに流れた直後に嘘みたいなアクセスが集中します。

★冗談みたいな性能要件

さて、このシステムをHerokuで実装するという前提で話を聞いたわけですが、割と最初の段階からボトルネックとなるのはDBのトランザクションだろうという予測がありました。

なので、「1秒に何件くらいINSERTできれば良いんですかね？」と聞いたところ最初の段階では900件という回答でした。
多めに見積もって1000件／秒と考えましたが、この時点ではそれ位はいくんじゃないかと思ってました。(以前に単純なテストでRonin * 2Dynosで200件／秒の登録ができることを確認していました)

。。。が、この数字が何故か数日後には5000件／秒になります。。。(--

どうもこの数字がユーザー数やPVと混同されたらしく、仮にPVがそれだけあってもトランザクション数はそこまでにはならない、ということをいくら説明してもとりあってもらえなかったようなんですね。

あとで別のところから聞いた話によるとテレビでURLが流れた場合、かなり高い確率で503 Service unavailabe(要するに過負荷でサーバーに接続できない)が返ってきてがっかり！となるため性能要件には神経質になっているということもあるようです。

なので結局僕のところでは秒5000でやってくれという話でおりてきました。。。(--
ちなみにこの時点で放送日まで2週間きってます。

最初から5000って言われてたらRDBは使わねーよ(--

★PostgreSQLを落とす

そんなこんなで負荷テストを開始します。
幸いなことに今回クライアントとHerokuとの契約はミートアップでも紹介されていたパッケージのさらに上位グレードの契約だったのでDynoもAddonもほぼ使い放題です。

そこでまずはPostgreSQLの限界を見極めることからテストを開始することにしました。
DBはそれほどキャッシュが必要なシステムとも思わなかったのでなんとなくIkaを選択します。

Heroku上ではPostgreSQLのconfigがMAX_CONNECTIONS=500で設定されていることはあらかじめ調べて知っていたのでとりあえずはこれを突破した時にどのような挙動になるかを確認することしにしました。
予算には余裕があるのでDynoは100台あげます。(^^;;;
Playframeworkの設定でスレッド数は50。コネクションプールは30です。

テストツールとしてはJMeterを使用して1000スレッドで100回ループさせました。(合計10万件のINSERT)

予想通りの結果ですがDriverManager#getConnectionでエラーとなります。

HerokuはWebシステムとしてはDynoを増やすことで自在にScaleしますが、DBはScaleしないので単純にDynoだけ増やしても意味がないってことですね。

PostgreSQLのconfigは一切変更不可能なので500しかないコネクションをいかに有効に使うかが勝負になります。

そこで次にDynoの数を15まで減らしてみます。Playのスレッド数とコネクションプールは変更していないので最大コネクション数は「15 * 30 = 450」となるはずです。

思ったほど数字伸びてないですね。(--;;;

★Heroku上にStressToolを実装

この時点では負荷テストのクライアントツールにローカルPC上のJMeterを使用していましたが、NewRelicで見る限りサーバー側の負荷がそれほどあがっているようには見えませんでした。にも関わらず設定をどのように変えてもあまり数字は伸びてません。

これには二つの理由が考えられます。

ネットワークレイテンシの問題

Herokuはアメリカ東海岸にあるので通信には毎回太平洋越えのネットワークレイテンシが発生します。レイテンシが平均100ms前後だとするとクライアント側で多数のスレッドがぐるぐるとループしていても各スレッドは最高でも100msに1回しかリクエストを発行していない計算になります。

クライアントリソースの問題

JMeterで1000スレッドを指定したとしてもクライアントPCの性能がそれに追いついていなければ実際に1000スレッド同時には動けません。
実際JMeterのログを検証しても早いスレッドはテストが半分完了する以前に終了していますし、最後の方は最初の競争に負けたスレッドがまとめて動いているような感じでした。
また、1000スレッド以上の負荷、例えば5000スレッド同時に動かそうとしてもクライアント側のソケット不足でまともに動かないという問題もあります。

要するにクライアント側の問題で実はHerokuにはたいして負荷がかかっていないんじゃないかというのがこの時点での推測です。

なので、ネットワークレイテンシのない東海岸からテストを実行するためにHeroku上にStressToolを作成することにしました。
ツール自体はURLをキックしたら指定個数のスレッドを起こして指定回数ループするだけのごく単純なモノです。

これをDyno100台あげて、100回キックすればHerokuルーターのラウンドロビンによっていい感じにクライアントの負荷が分散されるはずです。(^^;;;

とりあえず当初の目標は達成しましたね。(^^v

★Herokuのルーターを落とす

凶悪なStressToolを手に入れたので今度はHerokuのルーターがどこまでの負荷に耐えられるのか実験してみます。クライアントスレッド数を一気に倍の10000スレッドにしてみました。

ルーターのキューがあふれた場合はHerokuはログも吐かずに503を返すようです。
さらに負荷がかかった場合は多分接続エラーになっていると思います。(この辺はStressToolの作りが雑だったため正確には検証できてません。。。)

Webサーバーの動作としては割と一般的だと思いますが、503を返す場合はサマリだけでもログを出力してほしいですね。

ちなみにあとでログを調べたところ5000スレッドでもログサーバーは時々限界を越えているらしくところどころで「L10 - Drain buffer overflow」が記録されています。
最悪入力データをJSON化してログに書くだけにしようかとも思ったんですが、その案も没です。(そうは言っても一番多いところで秒間26000行以上のログが出力されてます。(^^;;;)

あまりに高負荷をかけるとHeroku社に怒られそうな気がするので1万スレッドでのテストは1度しかやっていません。(^^;;

★3DBでシャーディング

その後いろいろと設定を変えてテストしてみましたが、どうやっても数字はだいたい1000前後で止まります。このことから、これはもうDBがいっぱいいっぱいなんだろうと思いました。だけどDBのconfigは変えられないんですよねぇ。。。(--

そこで1DBをあきらめて複数のDBを使用して負荷分散させることを考えました。具体的には入力データの必須項目であるメールアドレスからハッシュをとってその値で使用するDBを切り替えます。
何故メアドのハッシュを使用するかというと要件の中にメアドの重複チェックだけは入っていたからです。

コネクションプールはPlayの標準のものが使えないので自前で実装。サイクリックにコネクションを使いまわしてオープンからある程度時間のたったものは破棄する単純な実装です。

DBは本当は同じグレードのものを使用するのが良いんですが、わざわざそのためだけにアプリを作るのも嫌だったので同一アプリ内でRoninとFuguを追加しました。

まったくもっていまいちです。。。(--

まず、最初に1DBの時と同じ設定ということで50スレッドと30のコネクションプールで動作させましたが、これはOutOfMemoryとなるDynoがいくつかでました。
実際にいくつのコネクションプールが作られたかはわかりませんが、最大で90個のコネクションがメモリに保持される計算になるので。
Herokuの各Dynoに割り当てられたメモリは512MB。けっして多くはありません。

そこでスレッド数やコネクションプール数を調整しながら何回か実行しましたが、結果は一番良い時で926件／秒。スループットは上がるどころか落ちてます。(--

正直この結果は予想外でしたが、結果から中で起こっていることを推測すると以下のようになります。

1. 各Dynoは1DBの時と同じくらいの仕事量をこなしている
2. 各DBの仕事量は分散によって3分の1に減っている
3. 各DBの接続数(各Dynoでのコネクションプール数)は1DBの時と同じか少ないはず
4. DBの同時トランザクション数は約3分の1のはず
5. にも関わらず各トランザクションのレスポンスタイムはあまり変わっていない？？？
6. スループット低下の原因はRonin, FuguがIkaよりもスペックが低いためと推測

いまいち5番目のレスポンスタイムの項が納得いかないですが、手持ちのデータから結果を無理やり説明しようとするとこうなります。

(他に何か説明可能な推測がありますかね？ちなみに自前のコネクションプールは1DBで使用した場合にPlay標準のコネクションプールを使用した場合よりも若干パフォーマンスが良いくらいなので多分問題ないです。)

エンジニアとして原因を追究したいという気持ちはあるんですが、これを検証しようとするのは結構難儀な作業です。
なんせ負荷テストをやっていた期間のログはほとんど5GB超。Papertrailでログのアーカイブはとっていましたが、翌日にならないとログを確認できないしそれをまともに開けるエディタもないという状況だったので。。。時間的にちと厳しい(--

まぁそれは置いておくとしても先のテストと併せて考えるとIkaの処理能力を使いきってないのでアプリの改修でスループットの向上が見込めることは間違いありません。
ただ、それも各DynoがすべてのDBに接続する可能性があるという条件の下では実装が難しくなる気がしました。
Herokuルーターが同一セッションのリクエストをどのDynoに飛ばすかは制御できないので、1Dynoが1DBにのみ接続するようなアーキテクチャもプラットフォーム側になんらかの手を入れない限り難しそうです。（今回のケースではDynoのIPアドレスからハッシュをとって接続DBを切り替えて後から重複チェックをするというのもギリギリありではあったんですが。)

先のOutOfMemoryの件もあるのでこの路線にはあまり未来が感じられずこの段階で一旦没としました。

★DATABASE_URLの削除

少し話はそれますが、この頃までにどうもConnectionErrorの発生する閾値が自分の予想よりも低いことに気が付いていました。
設定上で420コネクションしか使わないように調整してもConnectionErrorが発生することがあるのです。
PostgreSQL自体がいくらかのコネクションを予約していて500個全部が使えないのはわかるのですがなんか妙に少ない。

そこでDyno起動直後のセッション数をpg_stat_activity表から数えてみると、明らかに自アプリからの接続ではないコネクションが多数存在します。
それもDyno数に比例して増減しているようでした。

つまりパフォーマンスを求めてDyno数を増やせば増やすほど利用可能なコネクション数が減っていくという悪循環があったわけです。

これは要するにHeroku自体が裏でDBに接続して何かやっているということなんでしょうが、何をやっているのかは謎です。

試しに環境変数からDATABASE_URLを削除してみたところ謎のコネクションはなくなり、特にアプリの動作にも影響がなかったので結局削除したままで本番まで運用しました。

これで利用可能なコネクションが増えてConnectionErrorはでなくなりましたが、スループットの方にはそれほど極端な差は見られませんでした。

★Mecha出陣！

さて、もういい加減手詰まりな感があったんですがここで頼れるCTOから貴重なアドバイスが。

「EC2のラインアップを見ればPostgreSQLの各Planの土台となっているインスタンスはほぼ推測できる。
PlanによってCPUスペックがまったく違うからそれ相応のパフォーマンスアップが期待できるはず」

言われてEC2のインスタンスタイプのページを見に行くと確かにどこかで見たような数字が並んでいます。

これを見るとIkaの土台はおそらくラージインスタンス(4ECU)。
対して最上級プランのMechaの土台はハイメモリクアドラプルエクストララージインスタンス(26ECU)。
なんじゃ、そら。

Mechaは1ヵ月使うとさすがに予算オーバーなんですが、今回期間が短いので日割りにするとぎりぎりパッケージ予算内に収まります。
試しに実行してみた結果がこれ。

なんといきなりの4000件超！！！
なんじゃ、そら。

結局何度かテストを実施したところ一番良い時で4813件／秒まで行きました。 この数字はテスト全体でのスループットなので一番負荷の高いところから1秒を抜き出せば5000件／秒をクリアしています。

長々と書いてきて最終的な結論がパフォーマンスは金で買えということかと思うとかなりがっかりですが、まぁとりあえずまさかのミッションコンプリートです。

それにしてもCPUスペックは重要ですね。Heroku PostgresのページにはPlanの違いはCache sizeの違いとしか説明されてませんがCPUスペックも併記してほしいものです。

★放送当日

テレビの影響力を体感しましたがそれでも楽勝でした。(^^;;;

★質疑応答

このあとようやくメインイベントの質疑応答ですが、長くなったのでまた今度(^^;;;