たごもりすメモ

コードとかその他の話とか。

Ruby 2.1.0-preview2 で #fluentd (というかmsgpack)は動きません

このチケット(既にclosed)の関連なんだけど。

http://bugs.ruby-lang.org/issues/9106

Ruby 2.1.0-preview2 で gem install msgpack すると、ビルド&インストールされたgemのディレクトリにおいて lib 以下にビルド済みバイナリファイル(*.so や *.bundle)がコピーされておらず、実行時にLoadErrorが出ます。手動で msgpack.so (など)をコピーすれば動きます。
Cool::IO などを試したところそっちは lib 以下にコピーされているようなので extconf あたりの書き方によるのではないかなーと思いますが、rubygemsの変更に伴うものであることも間違いありません。そこまで行くと自分にはよくわからないので誰かにどうにかしてほしいところ。

なんにしろ、注意が必要です。このまま ruby 2.1.0 がリリースされてしまうと困るなあ。動作試験もできてないし。

out_exec_filter 入出力フォーマットの変更による負荷の変化

まず前置きですが、みんな大好きFluentdがなぜ*1実用上充分なくらい高速に動作するかというとそれは内部のシリアライズ/デシリアライズフォーマットとして使われているMessagePackのおかげによるところが大きいわけですね。

ところで Fluentd の組込みプラグインのひとつに out_exec_filter というのがありまして、これは任意のプログラムを子プロセスとして実行し、そのSTDIN/STDOUTにFluentdのメッセージを通すことでどんな処理でも記述可能なフィルタとして使いましょう、というやつ。
これは当初はTSVしかサポートしてなかった*2んだが、対応フォーマットがいくつか増えていまではjsonとかmsgpackでも入出力可能になっている。もちろん外部プログラムの側でもjsonやmsgpackを読み書きするように書かれてないといけない。

さてお仕事でこの exec_filter をがっつり使っていて、いまやこいつを8プロセス動かしているサーバが10台ある。馬鹿にならない台数なので負荷が減って台数を減らせればたいへん嬉しい。負荷としては外部のフィルタプログラムと同じくらい入出力のブリッジになっているfluentdプロセスもCPUを食ってる。こいつがもうちょっと軽くならないかなあ、と思ってた。

ので、TSVでやってた処理をmsgpackでも入出力できるようフィルタプログラムのコードを改造し out_exec_filter は子プロセスへの入出力をmsgpackでやれるようにしてみた。その上でどのくらい負荷が違うのかベンチマークをとってみたのが以下のグラフ。最初の30分の山がTSVで走行したもの、次の1時間がmsgpackに変えて走行したもの。
負荷はだいぶがっつりかけた。詳細は以下のとおり。

  • サーバ:
  • ソフトウェア
  • 負荷
    • 同スペックの別サーバに立てた fluentd out_forward から上記8プロセスに対してラウンドロビン
    • Maxで 300msg/send * 15 send/sec のメッセージを送るプロセスを10プロセス起動




変わってねえ! まるで変わらん! どっちも処理のスループットは 25000 msg/sec くらいがmaxで負荷に対して追い付いておらず、ちょっと遅延が出た。にしてもmsgpackにしてもぜんぜん速くなってねえ!

topでなんとなーく見てる限りだと、fluentdプロセスの cpu usage が少し下がって、かわりに perl プロセスの cpu usage が上がり、合計としては前と変わらず、みたいに見える。これはまあ印象論に近いあたり。

メモリについては msgpack を使ったときはたぶんメモリ空間のフラグメンテーションか何かが進行してる。ベンチ終わったあとも memory used が5GB以上あるのはそのせい。msgpack v0.5 はやく使いたいなあ。

考察

exec_filter がmsgpack入出力できるといっても子プロセスに渡す前/渡した後に time/tag の処理が必要なため、chunkのmsgpackバイナリをそのまま子プロセスのパイプに書き込めるわけではない。かならずunpack/packが入る。このため期待したほどには速くなかったのかなー、と思う。*3

となるとあとはTSVとMessagePackとの比較ということになる。fluentd 側で cpu usage が下がったとすれば msgpack の力なのだろう、おそらく。
perl 側で負荷が上がったとすれば考えられることはいくつか。
TSVは行単位での入出力なので perl のI/Oバッファリングが最大限に効くが msgpack は行単位での処理が不可能なので、自分で nonblock I/O をがんばりつつ streaming unpack しなければいけない。これは効率悪いかも。またタブ区切りの処理はperlであればmsgpackと勝負できるくらい充分に速い、というのもまあ考えられる。
最後に、msgpackだとフィールド名がデータ中に含まれるため、レコードのフィールド数がそれなりに多い場合にはI/Oバイト数がTSVに較べてそれなりに増加することが考えられる。これが性能を直撃したおそれは否定できない。

ということで、まあよく考えてみればそんな高速化するばかりだったかというと、そうでもない理由もありましたね。ということがわかる結果でした。まる。

*1:ruby + TCPという従来の感覚だと「遅そう」な組合せを使っているにもかかわらず

*2:よね、確か

*3:ちょっとコードを眺めてみたが、あんまり高速化の余地もなさそうだった、ざんねん

Fluentd w/ Ruby 2.0.0-p0 のメモリ使用量 (追記: w/ msgpack v0.5.4)

いくつかFluentdのベンチマークをとらないとなー、そういえばRuby 2.0.0-p0も出ましたね、ということでベンチマーク取ろうと思ってあれこれ作業してたらなんか変なのを見付けたのでとりあえず記録。
なおベンチマークの結果については、いろいろ取りかたを考え直す必要があるのでまたこんど。

概要

Fluentd の動作環境が Ruby 2.0.0-p0 with jemalloc なケースで Ruby 1.9.3-p392 に較べて大幅に大幅にメモリを食う上、負荷を停止した時にも何かよくわからない挙動を示す。
jemalloc を使わないケースだと 1.9.3 とほとんど変わらないと思われる挙動で jemalloc の必要性が無くなったとかいうわけではない。

詳細

ベンチマークは あるサーバ(4core HT, 16GB RAM)に立てた Fluentd に対し、別のサーバ(同一サブネット、同一スイッチ下)からメッセージを大量に継続的に送り、それを送り返させる、という形で行った。また送り返す他に fluent-plugin-flowcounter により処理したメッセージのカウントも行っていた。

ソフトウェア構成は基本的に以下の通り。

  • CentOS 6.4 x86_64
  • fluentd 0.10.32
  • msgpack 0.4.7
  • jemalloc (gem) 0.1.9
  • Ruby
    • 1.9.3-p392
    • 2.0.0-p0

Ruby 1.9.3-p392 と Ruby 2.0.0-p0 を比較してベンチマークを走らせてみたときのネットワークトラフィックが以下の通り。
23時過ぎから2時過ぎまでが 1.9.3-p392 のfluentdプロセスへの負荷で、2時過ぎから5時過ぎまでが 2.0.0-p0 のfluentdプロセスへの負荷。ベンチマークなので、それぞれで段階的に負荷を高くしていったと思いねえ。両方に同じだけの負荷をかけている。

で、この時間帯のリソースモニタ(CloudForecast)の CPU usage / Load average / Memory usage のグラフがこちら。

CPUとLoadはまあいいでしょ。
問題なのがメモリ。1.9.3-p392 が動いてる間はほとんど動きがないんだが、2.0.0-p0 が働きはじめた瞬間の2時過ぎからメモリ使用率が暴れはじめてる。
更におかしいことに、負荷を停止した5時過ぎからプロセスが謎の膨張をはじめ、約1時間半後におさまってる。このときの ruby 2.0.0-p0 (fluentd) のプロセスのRSSたるや実に7.6GB。うーん、なんだこれ。

jemallocを疑う

ruby 2.0.0 ではGCに変更があったのは知っているので、そこが jemalloc とはうまく動かないようになってるのかなー。ということでjemallocを外してみたらこんなんなった。


だめそう。ていうかこれは 1.9.3 without jemalloc のときの結果といっしょですね。以下のエントリ参照。

続 #fluentd の性能・リソースに関する最近のいくつかの傾向の話 - tagomorisのメモ置き場

ということでjemalloc様のお世話にならなくて済むわけではないようだ。

MessagePackを疑う

MessagePackの新しいバージョンを使えば良くなるかも!と開発者が言うので、Fluentdの依存関係をゴニョゴニョしながら入れて ruby 2.0.0-p0 上で起動するようにしてみた。*1

  • fluentd 0.10.32
  • msgpack 0.5.3
  • ruby 2.0.0-p0

結果: 動きませんでした

https://gist.github.com/tagomoris/5167730

うーん。これはちょっと継続して調査。

追記(3/16): msgpack v0.5.4

@frsyuki が動かない原因を修正した msgpack v0.5.4 をさくっと上げてくれたので以下のふたつで再度試したら、なんとメモリ使用量がまったく増えなくなりましたよ。スゴイ!

  1. fluentd 0.10.32 + jemalloc + msgpack 0.5.4 + ruby 2.0.0-p0
  2. fluentd 0.10.32 + msgpack 0.5.4 + ruby 2.0.0-p0




メモリ使用量がぜんぜん上がらなくなった。スバラシイ!


この状況についてなにか知見をお持ちのかたはいらっしゃいませんでしょうか。

bugs.ruby-lang.org に登録すると良いというアドバイスもいただきましたが正直この状況だとなあ。rubyプロセスのメモリまわりの状態について、これこれこういう情報をとった上で bug 登録するといいよ! という話をいただけますと幸いです。

どうしますかねー。msgpack 0.4 -> msgpack 0.5 への内部実装の変更ってだいぶ大きいはずだから依存をいっきに上げるのも怖い気がしますが、自分としては上げてほしいなあ。
とりあえずこのベンチ的なのを3日くらい動かして、それで安定してたら fluentd の依存を msgpack 0.5.4 以上にしちゃうとかどうですかね。だめ?

*1:Fluentd の依存は msgpack ~> 0.4.4 なのであれこれ無理矢理変更しない限り 0.5.x は現状のfluentdといっしょには入らない

Fluentd meetup in Fukuokaにいってきた&しゃべってきた

東京以外で初となる Fluentd meetup が福岡にて行われました。

Fluentd meetup in Fukuoka on Zusaar

福岡で50人規模の勉強会はそうそう無いとのことで、fluentdすごい! という話。で、スピーカーとしてお呼ばれしたのでいってきた。旅費は(自分で滞在延長した分以外は)某TDさんに出していただきました。ありがとうございました!

しゃべってきた

"そのプラグイン、作るや作らざるや"が事前に出したタイトル。資料はこちら。英語で書きはじめたけど微妙な部分もあって日本語をけっこう混ぜた。

いまの Fluentd plugin まわりにおいて、プラグイン等がおもにどういうように分類できるか、書くときに何に注意すべきか、そもそも書くべきか書かざるべきかの判断はどうするか、書いたあとどうするか、……みたいな話。
ここ1年少しで自分があれこれ考えたことを盛り込んだつもりなので、いまプラグインをいくつか書いてみてる人とか、これからプラグインを書いてみようと思っている人は読んでみると参考になるものがあるかも。

とはいえ会場で聞いてみたところ、Fluentdを実際に使っている人もまだちょっと少ないようだったので、突っ走った内容にしすぎたかなあ、という後悔をちょっとした。もうちょっと使う方寄りの内容のほうがよかったかも。東京の勉強会の参加者層とかTwitterだけ見てると判断が偏るなあ。

とはいえ

懇親会でいろんな人としゃべったりして、福岡のこの業界がどんな感じなの、みたいな話とかをあれこれ聞いた。だいぶ興味深い。ゲームとか強いのかー、みたいな。

そして美味いもの・店をいろいろ紹介してもらったり連れてってもらったりしてあまりにも満足度が高い三日間でした。すばらしかった。主なところだけ箇条書きにするとこんな感じ。

  • 天神を歩いている人、女性がすごく多い、そして美人も超多い
  • しかし福岡に住んでいても勉強会にばかり行っていてはダメである
  • 豚骨ラーメン食べた(トキハラーメン)、薄味豚骨でうまかった
  • ビアバー「Morris」行くしかなかった
  • ランチで安くうまい天ぷらが食べられるひらお素晴らしい、渋谷にもほしい
  • もつ鍋食べた(田しゅう)、すばらしくうまかった
  • ドイツビール飲んだ(バイエルン)、ビールの種類が多く安い、すばらしい
  • 鯛煮付けなランチ650円が安過ぎる(津々浦)、いっしょに頼んだイカの姿造りがたまらないうまさ

博多明太子を大量に購入して東京に帰った。3日では胃袋が足りない……。また行きたい。

#fluentd Casual Talks #2 やってきた&fluent-plugin-secure-forwardの話

なんとなく気分が盛り上がったところで会場も見付かったのでカジュアルに企画して開催してまいりました。
Fluentd Casual Talks #2 : ATND
いつもながら大人数の入る設備完璧な会場を貸していただき、また受付などすばらしいご協力を:DeNA様にいただきました。ありがとうございました!

で、大入りでしたね。発表者だれも決まってなかったのに……w 話すほうも何も事前調整無し、talk完璧に未決定の状態から募集を開始したのに、最終的に面白い発表者、というか豪華メンバーがずらっと並びました。ありがとうございました。

どの話も大変面白かったですが、特に fluentd + esper でストリームに対してクエリを投げるというのがもう、まさにやりたいことというか弊社のIssue Trackerにも項目があってですね、あれを全部rubygemsにパッケージできると夢のCEPエンジン on Fluentdという感じで夢が広がりまくっててやばい、すばらしい、という内容でした。グレートすぎる。

面白い話が聞けたので主催した甲斐がありました。しかもなにも苦労してねえ。満足。そのうちその気になったらまたやるかもしれません。

fluent-plugin-secure-forwardの話

で、自分の話は表題のプラグインをつくったよーという話。スライドはこちら。

前々からFluentdのネットワーク転送に認証や暗号化が欲しいという話はあって、でも誰も作らないなーと思ってたので、あるときふとその気になってさくっと……というにはちょっと頑張りましたが、つくりました。ちょうど Fluentd Casual Talks #2 の話が出たときに作りはじめくらいだったのでその話をすることにして、直前に簡単に仕上げて当日壇上で rake releaseした。

Rubygems: https://rubygems.org/gems/fluent-plugin-secure-forward
Github: http://github.com/tagomoris/fluent-plugin-secure-forward
Ust録画: http://www.ustream.tv/recorded/29298222

当日のセッションでも言いましたがあくまでPoCとして作ったもので、いちおう設計はちゃんとやったつもりだし全く使えないことはないと思いますが、実運用にかけておらず、また自分自身がユーザになることは(少なくとも当面は)ありません。ので、使いたい人がいるのであれば*1その人達にメンテしてほしいなーと思ってます。引き継いでくれる人がいるならgemのリリース権もさくっとお渡しします。

このプラグインに限らずソフトウェアというのは使われて磨かれるものだし、そこで外様が延々ひきずってもしょうがないので、使う人ががんがん開発する、そうでなければさっさと渡してしまう、というような方針でさくさく進めたいですね!

*1:反応を見る限りクラウドサービスをベースにサービスを作っている人達にけっこう需要がありそう?

fluent-plugin-parser supports LTSV!

乗るしかない、このビッグウェーブに!

Labeled Tab Separated Values (LTSV) ノススメ - stanaka's blog
LTSVフォーマットなログを fluentd + GrowthForecast で料理 - naoyaのはてなダイアリー
Text::LTSV - naoyaのはてなダイアリー
LTSV が行指向な Key-Value フォーマットで捗る話 - naoyaのはてなダイアリー

ということで fluent-plugin-parser で 'format ltsv' をサポートし v0.2.0 としてリリースいたしました。

fluent-plugin-parser | RubyGems.org | your community gem host
tagomoris/fluent-plugin-parser · GitHub

あるキーがLTSVなんだ!とか、おれはもうfluent-agent-liteでしかログを収集できなくて parser はどこかでやるんだ!とか、そういう人が便利に使えるつくりになっております。ぜひご利用ください。

<match raw.sales.*>
  type parser
  tag sales
  format ltsv
  key_name sales
</match>

とかやると sales フィールド(のLTSV)がparseされ、中身がfluentdメッセージとして流れます。

FluentdでバッファつきOutputPluginを使うときのデフォルト値

なんか自分で docs.fluentd.org へのpatchを書いてて混乱してきたのでまとめる。コードを読んでも関係する設定値がいくつものモジュールに分散しており、完全に把握することが困難である。具体的には、この組合せを記憶だけで答えられる fluentd コミッタはおそらく一人もいない。

概要

対象は BufferedOutput および TimeSlicedOutput を継承している output plugin の全て*1。out_forward, out_exec や out_exec_filter も含まれる。

基本的にはいくつかの設定により flush をするタイミングを制御するパラメータ一式、およびflush対象となるデータのチャンクを溜めておく量の上限を決めることとなる。fluentd をうっかり試したときに「アイエエエ、fluent-cat してみたんだけど、設定したところにログが出力されないよ? fluentd落とすと出てくるよ? ナンデ? フルーエントディーナンデ?」っていう誰もが抱く疑問の答えはここにある。が、おそらくその全てを全output pluginの設定で執拗に指定している人はいないだろう。

またBufferedOutputとTimeSlicedOutputでは挙動がさまざまに異なりデフォルト値も違う。そしてプラグイン側でそのデフォルト値を上書きしているケースもある。まさにすべての設定値がどうなっているのか把握したい厨にとってはfluentdの闇とも言える部分である。

関係する設定項目は以下の通りである。

  • buffer_type
  • buffer_queue_limit , buffer_chunk_limit
  • flush_interval
  • buffer_path (file only)
  • time_slice_format , time_slice_wait (TimeSlicedOutput only)

また注意事項として BufferedOutput のデフォルトの buffer_type は memory であり TimeSlicedOutput のデフォルトは file である。ただしこれを上書きしているプラグインもある(out_webhdfsなど)。

ずばり表をつくってみた

設定値 BufferedOutput + memory BufferedOutput + file TimeSlicedOutput + memory TimeSlicedOutput + file
buffer_queue_limit 64 256 64 256
buffer_chunk_limit 8MB 8MB 256MB 256MB
flush_interval 60 60 nil nil
シャットダウン時 flushされる flushされない flushされる flushされない

つまり TimeSlicedOutput な出力で出力先が詰まっている場合、最大で64GBのバッファファイルが生成されたあとで詰まることになる……! って、意外に普通の数値だったな。TimeSlicedOutput + memory の場合は16GBをメモリに確保してから詰まる。

flush_interval は通常60秒。Fluentdでバッファを使用するプラグインは以下の条件のどちらかを満たした場合にバッファをflushする動作を行う。

  • バッファチャンクのサイズが buffer_chunk_limit に達した場合
  • バッファチャンクが作られてから flush_interval で指定した時間が経過した場合

ただし TimeSlicedOutput の場合は flush_interval がデフォルトで nil なので、以下のような条件のどちらかに変わる。

  • バッファチャンクのサイズが buffer_chunk_limit に達した場合
  • time_slice_format で指定される時間幅の終端に達し、そこから更に time_slice_wait で指定された時間を経過した場合

time_slice_wait のデフォルトはじつは10分(!)なので、流量の小さいデータについて1時間毎にファイルを作るつもりで設定していると、毎時10分にならないと最終的な出力は得られないということになる。

なお「time_slice_formatで指定される時間幅の終端」というのは、具体的には以下のようになる。

  • %Y だけ指定した場合、年末
  • 中略
  • %Y%m%d%H だと1時間の終わり、つまり毎時59分59秒

ただし TimeSlicedOutput なプラグインで flush_interval を指定した場合は time_slice_format および time_slice_wait の影響が無視される挙動になる。ので以下。

  • バッファチャンクのサイズが buffer_chunk_limit に達した場合
  • バッファチャンクが作られてから flush_interval で指定した時間が経過した場合

また表にも入れたが fluentd 終了時の挙動として buffer_type file の場合にはflushされないが buffer_type memory の場合はflushされるという違いもある。このため memory のプラグインもシャットダウン時にいきなりデータロストするわけではない、が、出力処理が失敗した場合はバッファチャンク内のデータは失われる。逆に buffer_type file の場合はバッファチャンクファイルのまま残ることとなり flush されないので、これはこれで戸惑うことがあるかもしれない。

ところで拙作 fluent-plulgin-file-alternative や fluent-plugin-file-webhdfs などの PlainTextFormatterMixin を使った出力プラグインでは time_slice_format を個別に指定する必要はなく path から自動的に時刻プレースホルダを拾って time_slice_format を生成する。たいへん便利*2

プラグインでのデフォルト設定の上書き

たとえば out_exec_filter はBufferedOutputを継承しているが flush_interval を 1s で上書きしている。
また拙作 out_webhdfs はTimeSlicedOutputを継承しているが buffer_type のデフォルトは memory で上書きしている。

このような罠が世の中にはあるので注意が必要である。

buffer_path の話

out_file や out_file_alternative はローカルディスクへの書き込みを行うプラグインであり、バッファもデフォルトの buffer_type file のままであれば書き込み先ファイルと同じディレクトリに少し違うファイル名で書かれる。このパスは設定内の path パラメータから適当に生成される。
ただし、この便利機能は個別のプラグイン(たとえば out_file)内で実装されているもので FileBuffer や BufferedOutput/TimeSlicedOutput などの機能として実装されているわけではない。ので、各々のプラグインで buffer_type file を使う(あるいは TimeSlicedOutput を継承したプラグインを使う)ときには注意が必要である。

たとえば out_webhdfs は書き込み先 path が分散ファイルシステム上のものとなるため、ローカルパスの適当なところを指定できない。デフォルトでは buffer_type memory なので気にはならないが、自分で buffer_type file を指定する場合には buffer_path も指定しなければならない。*3

See Also

out_forward 特有の事情や round-robin などの話をまじえたエントリは過去に書いてた。
Fluentd out_forward における最適化パラメータいくつかの話 - tagomorisのメモ置き場

まとめ

以上のようなことを全て把握しなくてもなんとなく使っていればなんとなく使えるので、たぶん問題は起きない。

*1:おそらくファイルやDBやその他のものにデータを書き出すプラグインのほとんど全て

*2:個別に指定してもいいけど

*3:まで書いて同じく TimeSlicedOutput なプラグイン out_exec を読んでみたら tmpfile 使ってどうにかしてるなあ。こう直してもいいなー。デフォルトは memory のままでいいと思うんだけど。