Mac 10.8にrbenv+ruby-buildでRuby 1.9系にしてfluentdをインストールして試してみる

最近fluentdに触れる機会ができましたので備忘録としてブログに書いてみたいと思います。

fluentdタグでブログを書くのは↓以来1年振り2回目になります。
fluentdを試してみた - wyukawa’s blog

まずは環境構築です。fluentdはRuby 1.9系が前提なのですがMacにはRuby 1.8系しかないですよね。

Ruby弱者なのでよくわからないですが、こういうときはrvmかrbenvを使うみたいです。pythonでいうとpythonbrew的なもんだと思います。

rbenv+ruby-buildのほうがイマドキらしいのでこっちを使ってみます。

rbenv+ruby-buildのインストール

$ brew install rbenv ruby-build
$ echo 'eval "$(rbenv init -)"' >> ~/.bashrc

Ruby 1.9.3-p327をインストール

$ rbenv install 1.9.3-p327
$ rbenv rehash
$ rbenv local 1.9.3-p327

fluentdのインストール。今回試したのは0.10.31です。

$ gem install fluentd
$ rbenv rehash

fluentdのヘルプ

$ fluentd -h
Usage: fluentd [options]
    -s, --setup [DIR=/etc/fluent]    install sample configuration file to the directory
    -c, --config PATH                config file path (default: /etc/fluent/fluent.conf)
    -p, --plugin DIR                 add plugin directory
    -I PATH                          add library path
    -r NAME                          load library
    -d, --daemon PIDFILE             daemonize fluent process
        --user USER                  change user
        --group GROUP                change group
    -o, --log PATH                   log file path
    -i CONFIG_STRING,                inline config which is appended to the config file on-fly
        --inline-config
    -v, --verbose                    increase verbose level (-v: debug, -vv: trace)
    -q, --quiet                      decrease verbose level (-q: warn, -qq: error)

fluentdの設定ファイル生成

$ fluentd --setup ./fluent

fluentdの起動

$ fluentd -c ./fluent/fluent.conf -vv

ちなみにプロセスは2個立ち上がります。

$ ps -ef | grep fluent\[d\]
  502 35232  2164   0 12:00AM ttys001    0:00.19 /Users/wyukawa/.rbenv/versions/1.9.3-p327/bin/ruby /Users/wyukawa/.rbenv/versions/1.9.3-p327/bin/fluentd -c ./fluent/fluent.conf -vv
  502 35261 35232   0 12:00AM ttys001    0:00.08 /Users/wyukawa/.rbenv/versions/1.9.3-p327/bin/ruby /Users/wyukawa/.rbenv/versions/1.9.3-p327/bin/fluentd -c ./fluent/fluent.conf -vv

生成したfluent.confのうちコメントアウトされていない箇所を抜き出すとこんな感じになってます。今回使わないDRbの部分を除いて書くとTCP(24224), HTTP(8888) の入力を受けつけ、debug.** というタグを持ったメッセージを標準出力に出力するように設定されています。

## built-in TCP input
## $ echo <json> | fluent-cat <tag>
<source>
  type forward
</source>

# HTTP input
# http://localhost:8888/<tag>?json=<json>
<source>
  type http
  port 8888
</source>

# Listen DRb for debug
<source>
  type debug_agent
  port 24230
</source>

## match tag=debug.** and dump to console
<match debug.**>
  type stdout
</match>

fluentdを起動したものとは別のシェルから下記のようにコマンドを実行します。

echo '{"json":"message"}' | fluent-cat debug.test

するとfluentdを起動したシェルの標準出力に下記のように出力されると思います。debug.testタグがdebug.**にマッチしたので標準出力に出力されました。

2013-02-11 22:51:06 +0900 debug.test: {"json":"message"}

fluentdはinput→buffer→outputというプラグイン構造をしています。
今回使ったのはin_forwardプラグインとout_stdoutプラグインですね。どちらも標準で入っています。

in_httpプラグインを試すために下記のようにcurlコマンドでhttpリクエストを送ります。

curl  -X POST -d 'json={"action":"login","user":2}' http://localhost:8888/debug.http

すると下記のように出力されます。

2013-02-11 22:58:40 +0900 debug.http: {"action":"login","user":2}

次はRubyのアプリからログ出力してみましょう。

fluent-loggerをインストールします。

$ gem install fluent-logger

そしてこんな感じのRubyソースを書いて実行します。

require 'fluent-logger'
Fluent::Logger::FluentLogger.open(nil, host: 'localhost', port: 24224)
Fluent::Logger.post('debug.ruby', { hoge: 'fuga', foo: 'bar' })

実行結果はこんな感じになります。

2013-02-11 23:02:40 +0900 debug.ruby: {"hoge":"fuga","foo":"bar"}

さてここまでの内容だと以下の記事をrvmじゃなくてrbenvを使って書き換えただけになってしまいますので(汗 もうちょっと書きたいと思います。

Mac OS X に Fluentd をインストールして Ruby からログ出力してみる


fluentdを使っているとbuffer溢れがおこることがあります。このときログに「queue size exceeds limit」と出力されます。

fluentdのbufferはchunkという単位でキューイングされます。

chunk1 chunk2 chunk3 ...

設定ファイルで指定するbuffer_chunk_limitは1つのchunkのデータサイズでbuffer_queue_limitはchunkの数になります。

fluentdのinputプラグインはマルチスレッドで動作しどんどんbufferにキューイングするのでIO処理でブロックされてキューイングに詰まるということはないと思います。たぶん。
一方でoutputプラグインへの出力が詰まっているとbuffer溢れがおこります。

ちょっとbuffer溢れを再現させてみますね。例えばbuffering機能を使うout_fileで以下のように設定します。

<match file.**>
  type file
  path /tmp/hoge
  buffer_chunk_limit 1k
  buffer_queue_limit 1
</match>

そんでもって以下のようにして10000リクエストを並行でなげます。

for i in `seq 1 10000`
do
  curl -X POST -d 'json={"hoge":"fuga"}' http://localhost:8888/file.http &
done

そうすると以下のようにbuffer溢れがおきます。

 fluent/engine.rb:122:rescue in emit_stream: emit transaction failed  error="queue size exceeds limit"
   fluent/engine.rb:123:rescue in emit_stream: /Users/wyukawa/.rbenv/versions/1.9.3-p327/lib/ruby/gems/1.9.1/gems/fluentd-0.10.31/lib/fluent/buffer.rb:180:in `block in emit'
   fluent/engine.rb:123:rescue in emit_stream: /Users/wyukawa/.rbenv/versions/1.9.3-p327/lib/ruby/1.9.1/monitor.rb:211:in `mon_synchronize'
   fluent/engine.rb:123:rescue in emit_stream: /Users/wyukawa/.rbenv/versions/1.9.3-p327/lib/ruby/gems/1.9.1/gems/fluentd-0.10.31/lib/fluent/buffer.rb:166:in `emit'
   fluent/engine.rb:123:rescue in emit_stream: /Users/wyukawa/.rbenv/versions/1.9.3-p327/lib/ruby/gems/1.9.1/gems/fluentd-0.10.31/lib/fluent/output.rb:506:in `block in emit'
   fluent/engine.rb:123:rescue in emit_stream: /Users/wyukawa/.rbenv/versions/1.9.3-p327/lib/ruby/gems/1.9.1/gems/fluentd-0.10.31/lib/fluent/event.rb:52:in `call'
   fluent/engine.rb:123:rescue in emit_stream: /Users/wyukawa/.rbenv/versions/1.9.3-p327/lib/ruby/gems/1.9.1/gems/fluentd-0.10.31/lib/fluent/event.rb:52:in `each'
   fluent/engine.rb:123:rescue in emit_stream: /Users/wyukawa/.rbenv/versions/1.9.3-p327/lib/ruby/gems/1.9.1/gems/fluentd-0.10.31/lib/fluent/output.rb:496:in `emit'
   fluent/engine.rb:123:rescue in emit_stream: /Users/wyukawa/.rbenv/versions/1.9.3-p327/lib/ruby/gems/1.9.1/gems/fluentd-0.10.31/lib/fluent/match.rb:38:in `emit'
   fluent/engine.rb:123:rescue in emit_stream: /Users/wyukawa/.rbenv/versions/1.9.3-p327/lib/ruby/gems/1.9.1/gems/fluentd-0.10.31/lib/fluent/engine.rb:120:in `emit_stream'
   fluent/engine.rb:123:rescue in emit_stream: /Users/wyukawa/.rbenv/versions/1.9.3-p327/lib/ruby/gems/1.9.1/gems/fluentd-0.10.31/lib/fluent/engine.rb:101:in `emit'
   fluent/engine.rb:123:rescue in emit_stream: /Users/wyukawa/.rbenv/versions/1.9.3-p327/lib/ruby/gems/1.9.1/gems/fluentd-0.10.31/lib/fluent/plugin/in_http.rb:132:in `on_request'
   fluent/engine.rb:123:rescue in emit_stream: /Users/wyukawa/.rbenv/versions/1.9.3-p327/lib/ruby/gems/1.9.1/gems/fluentd-0.10.31/lib/fluent/plugin/in_http.rb:249:in `call'
   fluent/engine.rb:123:rescue in emit_stream: /Users/wyukawa/.rbenv/versions/1.9.3-p327/lib/ruby/gems/1.9.1/gems/fluentd-0.10.31/lib/fluent/plugin/in_http.rb:249:in `on_message_complete'
   fluent/engine.rb:123:rescue in emit_stream: /Users/wyukawa/.rbenv/versions/1.9.3-p327/lib/ruby/gems/1.9.1/gems/fluentd-0.10.31/lib/fluent/plugin/in_http.rb:169:in `<<'
   fluent/engine.rb:123:rescue in emit_stream: /Users/wyukawa/.rbenv/versions/1.9.3-p327/lib/ruby/gems/1.9.1/gems/fluentd-0.10.31/lib/fluent/plugin/in_http.rb:169:in `on_read'
   fluent/engine.rb:123:rescue in emit_stream: /Users/wyukawa/.rbenv/versions/1.9.3-p327/lib/ruby/gems/1.9.1/gems/cool.io-1.1.0/lib/cool.io/io.rb:108:in `on_readable'
   fluent/engine.rb:123:rescue in emit_stream: /Users/wyukawa/.rbenv/versions/1.9.3-p327/lib/ruby/gems/1.9.1/gems/cool.io-1.1.0/lib/cool.io/io.rb:170:in `on_readable'
   fluent/engine.rb:123:rescue in emit_stream: /Users/wyukawa/.rbenv/versions/1.9.3-p327/lib/ruby/gems/1.9.1/gems/cool.io-1.1.0/lib/cool.io/loop.rb:96:in `run_once'
   fluent/engine.rb:123:rescue in emit_stream: /Users/wyukawa/.rbenv/versions/1.9.3-p327/lib/ruby/gems/1.9.1/gems/cool.io-1.1.0/lib/cool.io/loop.rb:96:in `run'
   fluent/engine.rb:123:rescue in emit_stream: /Users/wyukawa/.rbenv/versions/1.9.3-p327/lib/ruby/gems/1.9.1/gems/fluentd-0.10.31/lib/fluent/plugin/in_http.rb:99:in `run'


out_fileじゃないですが僕もbuffer溢れに遭遇しました。で、この手のbuffer溢れ問題はfluentdを複数起動して回避するのが一つの手のようですね。もちろん複数CPUでCPUが余っていることが前提です。もしかしたらout_forwardをマルチスレッドで動かすようにしてoutput詰まりを回避するという方法もあるかもしれませんがこっちは試していませんね。


以下本論とはあまり関係ないですがRuby/Python弱者の独り言です。

RubyはGiant VM lock (GVL) をもっていて同時に実行される ネイティブスレッドは常にひとつなのでスレッドを有効に使えるのってIOが絡む箇所ぐらいなのかなあと思ったりしてます。なのでマルチスレッドよりはマルチプロセスなのかなと。PythonもGIL(Global Interpreter Lock) を持っていてRubyと似たような状況ですよね。この辺はPython2.6 で実装されたmultiprocessing パッケージあたりが関係してくるのかなと。multiprocessingはfabricが確か使ってましたよね。