ワイワイ！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 のバッファを使わずに直接「ファイル」に書き込むためのものです。

Fluentd のベンチマークテストに使える dummer (旧称 dummy_log_generator)

なにするもの？

dummer

試しに使ってみる

設定パラメータ

Filed データタイプ

コマンドラインオプション

出力性能をみてみる

ランダムフィールド生成

固定フィールド生成

固定メッセージ

dummer_simple

使い方

試しに使ってみる＆出力性能をみてみる

dummer_yes

使い方

試しに使ってみる＆出力性能をみてみる

出力性能評価まとめ

まとめ