fluentd を使った大規模ウェブサービスのロギング
先月行われた Fluentd meetup in Japanというイベントで発表してきました！一ヶ月前だけどエントリーにするの忘れていたので、今更ながらエントリーに。
fluentd を利用した大規模ウェブサービスのロギング
View more presentations from hotchpotch
fluentd、クックパッドではすでに100台以上のサーバに入れて各種ログを集約してますが本当に便利で。あとログ以外も最近 fluentd 経由で投げ始めたので、その辺も近々エントリーにできたらなーと思います。
プログラミングの楽しさ。オープンソースとの出会い。
が出版され、『私と Ruby と添削と』という内容で寄稿しました。私がどうプログラミング・オープンソースの楽しさを知ったかについての昔話です。公開して良い、とのことなので公開いたします。
なお、文章中に出てくる tdiarytimes.rb のコードは以下です。9年前に書いたコードなので今読み返すと恥ずかしいを通り越してもはや微笑ましいですね！！１これでも当時は、自分なりにできるだけ綺麗なコードにして公開した記憶があります。
私と Ruby と添削と
プログラミング技術の向上させるには、どういう方法があるでしょうか。プログラミングに関する書籍を読む、オープンソースで公開されているコードを読む、優秀な同僚と働くうちにテクニックが身についてくる、などなど様々な方法があるでしょう。
昔話をしましょう。私がプログラミングの楽しさを知り、プログラミングにのめり込んでいったのは大学三年生の時でした。当時プログラミングがあまり好きで無く、ほとんどコードをかけなかった私は、大学の研究室でコードを書く必要に迫られなんらかの方法でプログラミングを習得する必要がありました。
しかしながら、漠然とプログラミングを覚えようと思ってもすっと習得できるわけではありません。大学で習うプログラミングの話は、UML モデリングやオプジェクト思考の考え方で、アニマルクラスを継承して犬や猫が、といった概念的な話であったりしたため、そもそもプログラミングがよく解らない私にとってそのような高級なレイヤーの話はさっぱりでした。
そこで自分が作りたいものから作ってみようと思い、自分が使っていた日記システムに機能を増やしてみよう、と考えました。幸いにも使っていた日記システムが、プラグインで拡張可能な Ruby で書かれた日記『tDiary』であったため、そのプラグインを試行錯誤しながら書いてみました。
実際に書いてみると、常日頃から使っているものが自分が手を加えることにより変化する、という何かを創造しているような万能感が楽しく、みるみるうちにプログラミングに嵌まっていきました。
なお当時(2003年) 周りでは php や Java が流行っていましたが、周りと違ったことをしたいと思っていた自分は、当時ではまだまだマイナーだった Ruby を書ける自分カッコイイ的な中二病的な感覚に酔いしれたいと思って居たのも良い思い出です。
そんなプログラミングの楽しさが徐々に解ってきたときに、MTBlogTimes という投稿した時間帯によってバーコードのような画像にラインを刻む(画像検索するとどんなものかすぐ解ると思います) Movable Type のプラグインがシンプルでかっこよかったため、それを tDiary のプラグインとして実装した tdiarytimes.rb というライブラリを公開したところ、tDiary 作者のただただしさんの目にとまり、tDiary の CVS レポジトリの中に入れてもらえました。
自分が作ったものが本家のコードに入るなんて！と大変喜んだのですがそれだけではありませんでした。本稿で推薦している本の作者、青木峰郎さんが tdiarytimes.rb をクラス分けし継承し、クラスごとに画像の見せ方を変え、オブジェクト思考の実装を入れ、大幅にリファクタリングしてくださったのです。このリファクタリングにより、クラスの使い方、継承の概念、よりシンプルなコードの書き方など様々なプログラミングのエッセンスを学ぶことができました。
またオープンソースでコードを公開することのメリットや楽しさも知ることができ、外に出すのも恥ずかしいようなコードでもとりあえず公開しておくと、自分にとっても役立つし、誰かのためにもひょっとしたら役に立つかも、と思うようになりどんどんコードを公開するようになりました。
その後、別のイベントで青木さんにまたコードを添削していただく機会に恵まれました。昔よりはプログラミングができるようになったけど、いまいちどこを改善して良いのか解らないと思っていたいましたが、様々な箇所に指摘をもらい、またプログラミングのテクニックを学ぶことができました。
「Rubyist Magazine 出張版 正しいRubyコードの書き方講座」では、私のコード改善も含めた系6本の具体的なリファクタリング手法が載っています。実践的な内容になっており、実際のライブラリをどう改善するかというのがストーリーとして書かれており、読み物としても面白いです。リファクタリングのポイントも「コーディングスタイル」「プログラミング一般」「Rubyプログラミング一般」「オブジェクト指向プログラミング」「リフレクション(Ruby では今ではメタプログラミングという表記が一般的でしょうか)」と様々な視点が書かれており、Ruby のみならず標準的なプログラミングの考え方についても解説されています。
また、優秀なプログラマはそれぞれ、ポリシーを持ってコード書いており、たとえば空白スペースやインデント、メソッド名のつけ方一つとっても「なんでそのようなコードになってるか」一つ一つ説明できるような意味を持ってつけています。私が尊敬しているプログラマの一人である青木さんが、どんなポリシーを持ってコードを書いているかも解説されているのも嬉しいですね。
コードが書けるようになったは良いけど、どうやったらより良いコードになるか解らない、そんなプログラミング初心者は手にとって読んでみると、新しい発見があると思います。また本の内容も難しくなく「リファクタリングの本を読んでみたけど、正直よく解らなかった…」という方も読んでみてはいかがでしょうか。本自体は今風ではないですが、プログラミングのエッセンスは十分生かせる内容となっています。
プログラミング技術を向上させるには様々な方法があります。自分の場合は書籍を読んだり公開されているコードを読んだ時にも確かに技術や考え方は向上したと思うのですが、何よりも確実に向上したと思えたのが誰かに「添削」されたときでした。青木さんの添削もそうですし、同僚からのコードレビューもそうでしたし、オープンソースで公開したコードがリファクタリングされたときもそうでした。
今現在は当時とは違い、github を中心としたコミニュティベースでのソースコードの公開、添削、改善のサイクルが生まれています。あなたの公開したコードが昔よりもさらにより誰かが改善してくれやすい環境になっているでしょう。書いたコードが手元で眠っているなら、それをパブリックな場所で公開してみてはどうでしょうか。そのコードを添削してくれる誰かが現れ、よりあなたのプログラミング技術が向上するかもしれませんよ。
ちなみに本稿の話に出てきた tdiarytimes.rb、青木さんがリファクタリングされた tdiarytimes2.rb は現在も tDiary の git レポジトリに入っており、github 等から取得することができます。今見返したら tdiaritymes.rb はメソッドでもなんでもない箇所に、ベタで70行以上もコードが書いてあり歴史を感じることができました…。
例えば GC を止める・Ruby ウェブアプリケーションの高速化
最近クックパッドでは、アプリケーションサーバの大半が Rails 2.3 から Rails 3 に置き換わったのですが*1、リリース前のベンチマークの時点ではあまりパフォーマンスが出ず四苦八苦していました。具体的には Rails 2.3 の時と比べ MRI 1.8.7 だとレスポンスタムが200%ぐらい遅い結果でした。Rails 3 になって実装が Merb core を取り入れ疎結合で綺麗になった反面、より多くのオブジェクトと・メモリを利用する様になった影響かと思います。
そこで Ruby インタプリタの変更*2を行い検証をしたところ
- MRI 1.8.7
- (Rails 2.3と比べ) 約200%遅い
- MRI 1.8.7 -> Ruby Enterprise Edition 1.8.7 2011.03 (tcmalloc 無効)
- 約180%低速
- MRI 1.8.7 -> Ruby Enterprise Edition 1.8.7 2011.03 (tcmalloc 有効)
- 約140%低速
のような感じで、無視できないほど速度が遅く、これではリリースが危ぶまれました。なお、どこで速度が遅いのかというと、GC の実行でだいぶ時間を使っていました。Rails3 でオブジェクトが増えたため、より GC の実行時間がかかる様になってしまったようです。
Unicorn の導入
次にアプリケーションサーバを Apache + Passenger の組み合わせから Nginx + Unicorn の組み合わせに変更しました。Unicorn について簡単に説明すると、Rack 環境をロードした master プロセスが fork して子の worker を作るため、以下の様な特性を持ちます。
- fork による worker 生成のため、子 worker の起動が高速
- そのため再起動が高速になり、再起動時のサーバ負荷が少ない
- ただユーザからの処理を捌かない master プロセスが必ず存在するため、メモリ使用量が1プロセス分増える
- epoll / libev 等のイベントでうまく複数接続を捌くモデルでなく、worker 1プロセス1接続のため安定性が向上する
- そのため、大量のコネクションを要求する必要なウェブサービスには向かない
Unicorn の特徴について、より詳しくは以下のエントリーで述べられてます。
実際に Apache + Passenger の組み合わせから Nginx + Unicorn の組み合わせにすると、わずかにスループットが上がるなあ、といった感じで大きなパフォーマンス改善は見られませんでした。これは Unicorn の特性が高速化よりも安定性や再起動時のメリット*3、シグナルを送るだけで操作できるシンプルさに重みが置かれてるからで、Rack というインターフェイスを通して操作される Ruby アプリケーションの直接的な速度にはあまり関わってこないことを考えても納得の結果でした。
明示的な GC.start
しかし Unicorn について調べている途中、Tuning Unicorn で Unicorn::OobGC という面白いアプローチを見つけました。
これは指定のリクエスト回数アプリケーションが処理を終えたら、ユーザにコンテンツを返した後に明示的に GC.start するというアプローチです。何が良いのかというと、GC がユーザのリクエスト外で実行するため、リクエスト中の処理では GC が走りにくくなり、結果ユーザへのレスポンス返却速度が高速化されるというわけです。
これを適用したところ、140%ぐらい遅かった速度が 130%ほどへとわずかに高速化されました。たぶん小規模なアプリケーションだと効果が結構見込めそうなのですが、メモリをだいぶ食ってる大規模なアプリケーションだとこれを使っても GC が頻繁に実行され、結果あまり速くならないようでした。
GC を止める
ここでいっそ GC.disable でユーザからのリクエスト処理中は GC を止めてしまい、リクエスト外で GC をしたらどうなるか、と思いついたので試してみました。
Unicorn は worker が master から fork される特徴があり、fork した直後のプロセスに対して設定で処理を書けるので、unicorn.conf.rb の設定に
after_fork do |server, worker| GC.disable if RAILS_ENV == 'production'
の、GC.disable で GC が走らない様にする処理を入れ、OobGC のコードを GC.disable 時にも GC.start を実行できる様に変更し、その後再度 GC.disable で止める処理を入れました。
- https://github.com/defunkt/unicorn/commit/c7ba76a21c5d00fb5c173cd6aa847442bbc652cb
- unicorn の master ブランチに入ってるので、次のリリース(バージョン 4.1.2 ?) には取り込まれると思います
この GC.disable のベンチマークを結果は以下です。
赤のグラフが GC.disable しなかったサーバで、青のグラフが GC.disable するサーバです。あからさまに GC をユーザからのリクエスト処理中は無効化した方が断然高速な結果に終わりました。Rails 2.3 のサーバと比べても65%遅い、もとい150%ほど高速な結果となりました！！
GC を止める Production のアプリケーションサーバに適用
というわけで、このユーザのリクエスト処理中は GC を無効化する方法でだいぶ高速化することが解ったので、一足先に Unicorn 化していた Rails 2.3 サーバ(Ruby のバージョンは MRI 1.8.7 で Ruby Enterprise ではない)に適用したところ、それだけで 130% ほど高速化 & CPU 消費量が減る *4 という素晴らしい結果になりました。
なお Rails3 ほど顕著に高速化しなかったのは、Rails3 にくらべメモリ使用量が少ないからかと思います。その後 Rails3 に刷新後は当初の Unicorn 化する以前の Rails 2.3 アプリに比べ、最終的に 150% ほど高速化しました。
まとめ
Web アプリケーションの速度の高速化は、IO 処理の高速化を除いてしまうと、チューニングすればするほど大きく改善する方法はなくなっていくと思ってましたが、ユーザのレスポンス処理中は GC を止め、その外で実行するだけで大きくパフォーマンスが改善しました。Ruby 1.8 系統を使ってるサービスは試してみる価値があると思います。
なお今後リリースされる予定の Ruby 1.9.3 では nari3 が実装された Lazy Sweep GC が載るので、OobGC 的な事を Ruby 自体が行ってくれ、GC の最大実行時間が減ると思うので、Ruby 1.9 なサービスは 1.9.3 に変えるだけでパフォーマンス改善がされそうですね。
おまけ・運用ノウハウなど
メモリリークの対応
GC.disable している期間が長いと、GC.start したときに元のコードがメモリリークしてると、よりそのメモリーを解放できない様な感じで、どんどん Rails アプリケーションのプロセスサイズが肥大化して行ってしまいました。
Unicorn は worker プロセスに SIGQUIT を送ると、ユーザのリクエスト処理が終わった直後にプロセスが死んで、master プロセスがそれを検知してすぐに fork する仕組みがあるので、以下のユーティリティを書いて Rack レイヤーで対応しました。
use UnicornKiller::Oom, 400 * 1024 # 使用メモリが400Mを超えると自分自身に SIGQUIT use UnicornKiller::MaxRequests, 1000 # 1000 回リクエストを超えると自分自身に SIGQUIT
プロセスを終了しても即座に fork で新しい worker が作られるため、こんな感じのざっくりとした対応でも問題無く運用できてます。
Unicorn + bundler でのデプロイ時の問題
突然はまるのでちゅうい…。特に Unicorn は master プロセスへの SIGUSR2 (graceful な再起動)で再起動に失敗した場合、何事もなかったのように昔のプロセスは正常に生き続けるため、ぱっと見問題に気づきません…。
アプリケーションサーバのベンチマークとパラメータの調整
ベンチマークには最初 ab (apache bench) でいくつかの URL でベンチ、次に JMeter で本番リクエストの上位80%のリクエストをエミュレートしてベンチをとりました。環境さえ作ればあとは叩くだけなので、ab / JMeter を使いつつ、アプリケーションサーバのメモリー数、CPU の利用状況を見て Unicorn のプロセス数の調整と Ruby Enterprise Edition の GC 周りの環境変数を調整しました。
この辺はサービスごとに最適値が違うと思うので、ちまちま数字変えてやるのが良いと思います。
