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

ワイワイ！Fluentd Advent Calendar１日目担当の [@sonots](https://twitter.com/sonots) です。

今回は、最近 Fluentd をベンチマークテストするために作った [dummer](https://github.com/sonots/dummer) というツールの紹介をします！

# なにするもの？

ダミーのログを吐き出しまくるツール群です。Fluentd をベンチマークテストするのに使えます。ruby の入っている環境で

```bash
$ gem install dummer
```

とするとインストールできます。３つツールが入っています。

1. rate (行数 / sec) を指定でき、またメッセージもランダム生成ができる dummer
1. rate を指定できないシンプルな機能しかもたない dummer_simple
1. お試しで yes コマンドをラップして作成した dummer_yes

rate を指定したい場合は、dummer を使用し、最大書き込みに fluentd が耐えられるのか検証する際には dummer_simple を利用すると良いです。１つずつ説明していきます。

# dummer

出力する行数/秒を指定したり、出力フォーマットを定義してランダム生成することができます。conf ファイルを作成し、そこにオプションなどを記述して利用します。

## 試しに使ってみる

試しに使ってみましょう。以下のような dummer.conf ファイルを用意してみます。ruby の DSL として書けるようになっています。

```rb
# 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](http://www.ruby-doc.org/core-2.0.0/Time.html#method-i-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 をランダムに生成する場合で確認してみます。

```rb
# 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限界を出せていないということですね。

```bash
$  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 は指定するがランダム生成はしないようにして性能確認してみます。

```rb
# 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
```

前回と同様に実行してみます。

```bash
$ 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 などが走らないのでより高速になります。

```rb
# 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
```

再度同様に実行してみます。

```bash
$ 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 を作成してありますので、そちらを利用してください。

## 使い方

以下のようなオプションが利用可能です。

```bash
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](http://ruby-doc.org/core-1.8.7/IO.html#method-i-sync-3D)

```bash
$ 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 の場合

```bash
$ 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性能を出せたと思ってよさそうです。

```bash
$ 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](https://github.com/sonots/dummer) の紹介をしました！

最大出力性能に差があるので、rate を指定したい場合は、dummer を使用し、最大書き込みに fluentd が耐えられるのか検証する際には dummer_simple を利用すると良いでしょう。

これを使って皆さん、どんどん Fluentd のベンチマークテストしていきましょう！

2013/12/13 開催予定の [Fluentd Casual Talks #2](http://atnd.org/events/45386) では、このツールを使ったFluentd の性能評価の結果もちょっと話すかも？以上、[@sonots](https://twitter.com/sonots) でした。

明日は [@kzk_mover](https://twitter.com/kzk_mover) さんです。

追記: 2013/12/01 IO#sync = true すると ruby は fsync(2) すると勘違いしていました。「fsync(2) する場合」の文言を「バッファリングせずに即座にファイルに書き込む設定にした場合。参照: [IO#sync](http://ruby-doc.org/core-1.8.7/IO.html#method-i-sync-3D)」に修正しました。@methane さんありがとうございます。
補足：「ファイル」に書き込んだからと言って「ディスク」に書き込まれるとは限りません。fsync(2) はディスクに sync するためのシステムコールです。IO#sync = true は ruby のバッファを使わずに直接「ファイル」に書き込むためのものです。