bench_out_parser.rb

require_relative '../helper'
require 'benchmark'
Fluent::Test.setup

def create_driver(config, tag = 'foo.bar')
  Fluent::Test::OutputTestDriver.new(Fluent::ParserOutput, tag).configure(config)
end

# setup
time = Time.now.to_i
CONFIG = %[
  add_prefix parsed
  key_name message
]
ltsv_message = {'message' => "time:2013-11-20 23:39:42 +0900\tlevel:ERROR\tmethod:POST\turi:/api/v1/people\treqtime:3.1983877060667103"}
ltsv_driver = create_driver(CONFIG + %[format ltsv])
tsv_message = {'message' => "2013-11-20 23:39:42 +0900\tERROR\tPOST\t/api/v1/people\t3.1983877060667103"}
tsv_driver = create_driver(CONFIG + %[format tsv\nkeys time,level,method,uri,reqtime])
regex_message = {'message' => "time:2013-11-20 23:39:42 +0900\tlevel:ERROR\tmethod:POST\turi:/api/v1/people\treqtime:3.1983877060667103"}
regex_driver = create_driver(CONFIG + %[format /^(?<time>[^\t]*)(?<level>[^\t]*)(?<method>[^\t]*)(?<uri>[^\t]*)(?<reqtime>[^\t]*)/])

# bench
n = 100000
Benchmark.bm(7) do |x|
  x.report("ltsv")  { ltsv_driver.run  { n.times { ltsv_driver.emit(ltsv_message, time)  } } }
  x.report("tsv")   { tsv_driver.run  { n.times { tsv_driver.emit(tsv_message, time)  } } }
  x.report("regex") { regex_driver.run  { n.times { regex_driver.emit(regex_message, time)  } } }
end

#              user     system      total        real
#ltsv     13.490000   0.770000  14.260000 ( 14.892446)
#tsv      16.440000   0.770000  17.210000 ( 17.801737)
#regex    22.160000   0.770000  22.930000 ( 23.532429)

なお、比較対象として fluent-plugin-grep をあげるとそちらは

#              user     system      total        real
#          2.700000   0.050000   2.750000 (  3.340524)

程度である

time_parse false にすると爆速になった。

結論: time フィールドを使っていなければ積極的に time_parse false にしていくべし

              user     system      total        real
ltsv      3.480000   0.080000   3.560000 (  4.107753)
tsv       4.540000   0.030000   4.570000 (  5.125833)
regex     5.950000   0.030000   5.980000 (  6.531377)