ワイワイ！Fluentd Advent Calendar１日目担当の @sonots です。
今回は、最近 Fluentd をベンチマークテストするために作った dummer というツールの紹介をします！
なにするもの？
ダミーのログを吐き出しまくるツール群です。Fluentd をベンチマークテストするのに使えます。ruby の入っている環境で
$ gem install dummer
とするとインストールできます。３つツールが入っています。
- rate (行数 / sec) を指定でき、またメッセージもランダム生成ができる dummer
- rate を指定できないシンプルな機能しかもたない dummer_simple
- お試しで yes コマンドをラップして作成した dummer_yes
rate を指定したい場合は、dummer を使用し、最大書き込みに fluentd が耐えられるのか検証する際には dummer_simple を利用すると良いです。１つずつ説明していきます。
dummer
出力する行数/秒を指定したり、出力フォーマットを定義してランダム生成することができます。conf ファイルを作成し、そこにオプションなどを記述して利用します。
試しに使ってみる
試しに使ってみましょう。以下のような dummer.conf ファイルを用意してみます。ruby の DSL として書けるようになっています。
# dummer.conf
configure 'sample' do
output "dummy.log"
rate 500
delimiter "\t"
labeled true
field :id, type: :integer, countup: true, format: "%04d"
field :time, type: :datetime, format: "[%Y-%m-%d %H:%M:%S]", random: false
field :level, type: :string, any: %w[DEBUG INFO WARN ERROR]
field :method, type: :string, any: %w[GET POST PUT]
field :uri, type: :string, any: %w[/api/v1/people /api/v1/textdata]
field :reqtime, type: :float, range: 0.1..5.0
field :foobar, type: :string, length: 8
end
実行
$ dummer -c dummer.conf
すると dummy.log ファイルに以下のようにログが延々と出力されます。
id:0422 time:[2013-11-19 02:34:58] level:INFO method:POST uri:/api/v1/textdata reqtime:3.9726677258569842 foobar:LFK6XV1N
id:0423 time:[2013-11-19 02:34:58] level:DEBUG method:GET uri:/api/v1/people reqtime:0.49912949125272277 foobar:DcOYrONH
id:0424 time:[2013-11-19 02:34:58] level:WARN method:POST uri:/api/v1/textdata reqtime:2.930590441869852 foobar:XEZ5bQsh
設定パラメータ
ちょっと長くなるので読み飛ばしてもらっても良いのですが、設定パラメータを１つずつ説明しておきます。2013/12/01 現在は以下のようなパラメータを指定可能です。
-
output
出力ファイルのパス、または IO オブジェクト(STDOUT, STDERR)を指定します
-
rate
出力する行数/秒を指定します。デフォルト: 500行/秒
-
workers
並列処理のためのプロセスの数を指定します。デフォルト: 1
-
delimiter
各フィールドの間に出力するデリミタを指定します。デフォルトはタブ文字です
-
labeled
フィールド名をラベルとして出力するかしないかを指定します。デフォルト: true
-
field
生成するデータのフィールドを定義します。
inputおよびmessageが無視されます -
input
指定したファイルの内容を読み込んで出力したい場合に利用します。先頭から読み込んで最下行にたどりついたら再度先頭行に戻ります
-
message
固定のメッセージを生成できれば充分な場合、field ではなくこちらを利用します
Filed データタイプ
field パラメータには以下のデータタイプ、およびオプションを指定可能です。
:datetime
-
:format
日付のフォーマットを
%Y-%m-%d %H:%M:%Sのように指定できます。詳しくは Time#strftime を参照してください。 -
:random
日付をランダムに生成します。デフォルトは false です(現在時間を出力します)
-
:value
固定の Time オブジェクトを指定します。固定の日付を出力したい場合に利用します。
:string
-
:any
文字列の配列を指定すると、generator はランダムにそのうちの１つを選択して出力します。
-
:length
文字列の長さを指定します。:any ではなく、文字列を完全にランダムに生成する場合に利用します。
-
:value
固定の文字列を指定します。固定の文字列を出力したい場合に利用します。
:integer
- :format
出力フォーマットを %03d のように指定できます。
- :range
-10..10 のように Interger の Range オブジェクトを指定します。generator はランダムにその範囲内の整数を選択して出力します。
- :countup
0 から順番にカウントアップするようなデータを生成したい場合に使用します。デフォルトは false です。
- :value
固定の整数を指定できます。
:float
-
:format
出力フォーマットを
%03.1fのように指定できます。 -
:range
-10.3..10.3のように Float の Range オブジェクトを指定します。generator はランダム(uniform)にその範囲内の浮動小数点数を選択して出力します。 -
:value
固定の浮動小数点数を指定できます。
コマンドラインオプション
コマンドラインオプションを追加しました。設定ファイルを上書いて実行時に変更したい場合に便利です。
-r rate や -w 並列数などが利用可能です。
$ dummer help start
Usage:
dummer
Options:
-c, [--config=CONFIG] # Config file
# Default: dummer.conf
-r, [--rate=N] # Number of generating messages per second
-o, [--output=OUTPUT] # Output file
-m, [--message=MESSAGE] # Output message
-d, [--daemonize] # Daemonize. Stop with `dummer stop`
-w, [--workers=N] # Number of parallels
[--worker-type=WORKER_TYPE]
# Default: process
-p, [--pid-path=PID_PATH]
# Default: dummer.pid
出力性能をみてみる
そもそもこのベンチマークツールの限界はどのくらいなのか、というのが気になるポイントだと思います。それ以上の Fluentd 性能は評価できない、ということになりますからね。
ということで、性能を調べておいたので結果を貼っておきます。もちろん結果は環境に依存するので、参考程度に見てください。
ランダムフィールド生成
さきほどのサンプルのように field をランダムに生成する場合で確認してみます。
# dummer.conf
configure 'sample' do
output "dummy.log"
rate 500
delimiter "\t"
labeled true
field :id, type: :integer, countup: true, format: "%04d"
field :time, type: :datetime, format: "[%Y-%m-%d %H:%M:%S]", random: false
field :level, type: :string, any: %w[DEBUG INFO WARN ERROR]
field :method, type: :string, any: %w[GET POST PUT]
field :uri, type: :string, any: %w[/api/v1/people /api/v1/textdata]
field :reqtime, type: :float, range: 0.1..5.0
field :foobar, type: :string, length: 8
end
50万行 / sec の rate で書き込んでみます。
$ dummer -r 500000 -w 1
$ awk '{print $3}' dummy.log | sort | uniq -c
23275 10:12:09
23626 10:12:10
$ dummer -r 500000 -w 30
$ awk '{print $3}' dummy.log | sort | uniq -c
202916 10:15:34
201154 10:15:35
１並列で 2.3 万行 / sec、30 並列で 20万行 /sec が限界でした。50万行/sec * 30並列 = 1500万行 / sec と指定しましたが現実は厳しいですね。これ以上 rate や worker 数を増やしても変わりませんでした。
また、top で見る限りは %wait が出ていないので i/o バウンドにはなっていない模様でした。ツールのリッチな機能にCPUを使われてシステムのI/O限界を出せていないということですね。
$ top -c
top - 22:10:03 up 14 days, 6:59, 5 users, load average: 11.59, 4.83, 2.07
Tasks: 724 total, 14 running, 710 sleeping, 0 stopped, 0 zombie
Cpu0 : 40.1%us, 16.1%sy, 0.0%ni, 43.8%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu1 : 35.3%us, 16.5%sy, 0.0%ni, 48.2%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu2 : 33.8%us, 19.0%sy, 0.0%ni, 47.2%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu3 : 37.4%us, 16.4%sy, 0.0%ni, 45.9%id, 0.0%wa, 0.0%hi, 0.3%si, 0.0%st
以下略
固定フィールド生成
field は指定するがランダム生成はしないようにして性能確認してみます。
# dummer.conf
configure 'sample' do
output "dummy.log"
delimiter "\t"
labeled true
field :time, type: :datetime, format: "%Y-%m-%d %H:%M:%S"
field :level, type: :string, value: "ERROR"
field :method, type: :string, value: "POST"
field :uri, type: :string, value: "/api/v1/people"
field :reqtime, type: :float, value: 3.1983877060667103
end
前回と同様に実行してみます。
$ dummer -r 500000 -w 1
$ awk '{print $2}' /var/log/dummy.log | sort | uniq -c
37891 14:06:29
37835 14:06:30
$ dummer -r 500000 -w 30
$ awk '{print $2}' /var/log/dummy.log | sort | uniq -c
239553 22:17:22
240340 22:17:23
1並列で 3.7 万行 / sec、30並列の 24万行 /sec が限界でした。こちらも iowait 発生せず。
固定メッセージ
さらに field を使わず固定 message を指定してみましょう。こちらを使用すると固定文字列しか出力できませんが delimiter (タブ文字) での join などが走らないのでより高速になります。
# dummer.conf
configure 'sample' do
output "dummy.log"
message "time:2013-11-25 00:23:52 +0900\tlevel:ERROR\tmethod:POST\turi:/api/v1/people\treqtime:3.1983877060667103"
end
再度同様に実行してみます。
$ dummer -r 500000
$ tail -F /var/log/fluent-agent.log
441290
431711
$ dummer -r 500000 -w 2
$ tail -F /var/log/fluent-agent.log
296126
278472
1並列の 42万行/sec が限界でした。並列数を増やすとスコアが落ちました。
top で見ると CPU 使用率が 100% の CPUバウンドとなっており、これがこのツールの限界です。最後まで I/O 限界を達成できませんでしたが、リッチな機能があるので仕方がないと思ってください。
$ top -c
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
47395 sonots 20 0 311m 15m 912 R 99.7 0.1 0:08.76 ruby dummer -c dummer.conf -r 500000
dummer_simple
dummer では rate 指定やランダム生成機能などリッチな機能を備えていて便利なのですが、そのためにシステムのI/O限界を引き出せませんでいした。そこでI/O限界までベンチマークテストしたい場合は極力処理を排除した dummer_simple を作成してありますので、そちらを利用してください。
使い方
以下のようなオプションが利用可能です。
Usage:
bin/dummer_simple
Options:
[--sync] # Set `IO#sync=true`
-s, [--second=N] # Duration of running in second
# Default: 1
-p, [--parallel=N] # Number of processes to run in parallel
# Default: 1
-o, [--output=OUTPUT] # Output file
# Default: dummy.log
-i, [--input=INPUT] # Input file (Output messages by reading lines of the file in rotation)
-m, [--message=MESSAGE] # Output message
# Default: time:2013-11-20 23:39:42 +0900 level:ERROR method:POST uri:/api/v1/people reqtime:3.1983877060667103
試しに使ってみる＆出力性能をみてみる
IO#sync = true、つまりバッファリングせずに即座にファイルに書き込む設定にした場合。参照: IO#sync
$ rm -f dummy.log && dummer_simple --sync
$ wc -l dummy.log
771801 dummy.log
$ rm -f dummy.log && dummer_simple --sync -p 2
$ wc -l dummy.log
320870 dummy.log
IO#sync = false の場合
$ rm -f dummy.log && dummer_simple
$ wc -l dummy.log
5413557 dummy.log
$ rm -f dummy.log && dummer_simple -p 2
$ wc -l dummy.log
5252491 dummy.log
$ rm -f dummy.log && dummer_simple -p 3
$ wc -l dummy.log
6824642 dummy.log
$ rm -f dummy.log && dummer_simple -p 4
$ wc -l dummy.log
7154661 dummy.log
$ rm -f dummy.log && dummer_simple -p 5
$ wc -l dummy.log
6725391 dummy.log
Logger らしく IO#sync = true にした状態では 77万行/sec ほどで、IO#sync = false の場合は１並列で 約540万行 / sec 書き込めました。最大は並列4の約715万行 / sec で、それ以上は並列数を増やしても伸びませんでした。
※ 公平さのために言及しておくと dummer は IO#sync = true しています。
top で見ると iowait も発生していたので、システムの最大性能を出せた模様です。
$ top -c
top - 16:25:14 up 15 days, 1:14, 5 users, load average: 0.44, 0.33, 0.66
Tasks: 703 total, 2 running, 701 sleeping, 0 stopped, 0 zombie
Cpu1 : 11.0%us, 48.4%sy, 0.0%ni, 39.4%id, 0.9%wa, 0.0%hi, 0.3%si, 0.0%st
Cpu2 : 12.5%us, 65.6%sy, 0.0%ni, 21.6%id, 0.3%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu8 : 14.6%us, 62.9%sy, 0.0%ni, 12.8%id, 6.7%wa, 0.0%hi, 3.0%si, 0.0%st
Cpu10 : 16.2%us, 68.8%sy, 0.0%ni, 15.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu11 : 1.0%us, 10.1%sy, 0.0%ni, 11.4%id, 77.5%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu13 : 0.0%us, 4.0%sy, 0.0%ni, 83.8%id, 12.2%wa, 0.0%hi, 0.0%si, 0.0%st
また iostat をみると 158MB/s ほど出ていて、事前に dd コマンドで調べておいた検証環境の書き込みベンチの結果 160MB/s に近い値が出ているのでシステムの最大I/O性能を出せたと思ってよさそうです。
$ iostat -dkxt 1
11/22/2013 03:32:52 PM
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 39624.00 0.00 408.00 0.00 157080.00 770.00 142.83 350.68 2.45 100.00
11/22/2013 03:32:54 PM
Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await svctm %util
sda 0.00 39589.00 0.00 412.00 0.00 158480.00 769.32 142.82 346.68 2.43 100.00
dummer_yes
当初 dummer_simple でも iowait が発生していなかったので試しに yes コマンドをラップして作ってみたツールです。チューニングした結果 dummer_simple でも iowait が発生(I/O 限界を達成)できたので、もはや不要かな。。。読み飛ばしてもらってOKです ^^;
使い方
Usage:
bin/dummer_yes
Options:
-s, [--second=N] # Duration of running in second
# Default: 1
-p, [--parallel=N] # Number of processes to run in parallel
# Default: 1
-o, [--output=OUTPUT] # Output file
# Default: dummy.log
-m, [--message=MESSAGE] # Output message
# Default: time:2013-11-20 23:39:42 +0900 level:ERROR method:POST uri:/api/v1/people reqtime:3.1983877060667103
試しに使ってみる＆出力性能をみてみる
$ rm -f dummy.log && dummer_yes -p 1
$ wc -l dummy.log
4815679 dummy.log
$ rm -f dummy.log && dummer_yes -p 2
$ wc -l dummy.log
8570453 dummy.log
$ rm -f dummy.log && dummer_yes -p 3
$ wc -l dummy.log
9981100 dummy.log
$ rm -f dummy.log && bin/dummer_yes -p 4
$ wc -l dummy.log
8857456 dummy.log
並列1で約481万行 / sec 書き込めました。最大は並列3の約1000万行 / sec で、それ以上は並列数を増やしても伸びませんでした。top で見ると iowait も発生しています。
$ top -c
top - 16:25:14 up 15 days, 1:14, 5 users, load average: 0.44, 0.33, 0.66
Tasks: 703 total, 2 running, 701 sleeping, 0 stopped, 0 zombie
Cpu2 : 19.8%us, 18.8%sy, 0.0%ni, 34.7%id, 26.7%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu8 : 10.8%us, 9.8%sy, 0.0%ni, 1.0%id, 77.4%wa, 0.0%hi, 1.0%si, 0.0%st
Cpu9 : 9.9%us, 8.8%sy, 0.0%ni, 61.9%id, 19.4%wa, 0.0%hi, 0.0%si, 0.0%st
Cpu26 : 20.4%us, 19.1%sy, 0.0%ni, 45.6%id, 14.9%wa, 0.0%hi, 0.0%si, 0.0%st
出力性能評価まとめ
表にしてまとめておきます。もちろん評価環境に依存するので参考までに。
| ランダム field | 固定 field | message | simple (IO#sync=true) | simple | yes | |
|---|---|---|---|---|---|---|
| 並列数1 | 2.3 | 3.7 | 42 | 77 | 540 | 481 |
| 最大出力 (並列数) | 20 (30並列) | 24 (30並列) | 42 (1並列) | 77 (1並列) | 715 (4並列) | 1000 (3並列) |
単位: 万行/秒
まとめ
Fluentd をベンチマークテストするためのツール dummer の紹介をしました！
最大出力性能に差があるので、rate を指定したい場合は、dummer を使用し、最大書き込みに fluentd が耐えられるのか検証する際には dummer_simple を利用すると良いでしょう。
これを使って皆さん、どんどん Fluentd のベンチマークテストしていきましょう！
2013/12/13 開催予定の Fluentd Casual Talks #2 では、このツールを使ったFluentd の性能評価の結果もちょっと話すかも？以上、@sonots でした。
明日は @kzk_mover さんです。
追記: 2013/12/01 IO#sync = true すると ruby は fsync(2) すると勘違いしていました。「fsync(2) する場合」の文言を「バッファリングせずに即座にファイルに書き込む設定にした場合。参照: IO#sync」に修正しました。@methane さんありがとうございます。
補足：「ファイル」に書き込んだからと言って「ディスク」に書き込まれるとは限りません。fsync(2) はディスクに sync するためのシステムコールです。IO#sync = true は ruby のバッファを使わずに直接「ファイル」に書き込むためのものです。