fluent-plugin-measure_time

Fluentd plugin to measure elapsed time to process messages

Installation

Use RubyGems:

gem install fluent-plugin-measure_time

Parameters

tag

The output tag name. Default is measure_time
hook (required)

Specify the method to measure time.
interval

The time interval to emit measurement results. Default is nil which do not compute statistics and emit the time in each measurement.

Configuration Example 1 - Profile an Output Plugin

As an example, let's profile how long the emit method of fluent-plugin-grep is taking. Configure fluentd.conf as below:

<source>
  type measure_time
  # This makes available the `masure_time` directive for all plugins
</source>

<source>
  type forward
  port 24224
</source>

# measure_time plugin output comes here
<match measure_time>
  type stdout
</match>

# Whatever you want to do
<match greped.**>
  type stdout
</match>

<match **>
  type grep
  add_tag_prefix greped
  <measure_time>
    tag measure_time
    hook emit
  </measure_time>
</source>

The output of fluent-plugin-measure_time will be as below:

measure_time: {"time":0.000849735,"class":"Fluent::GrepOutput","hook":"emit","object_id":83935080}

where time denotes the measured elapsed time, and class, hook, and object_id denotes the hooked class, the hooked method, and the object id of the plugin instance.

interval option

fluent-plugin-measure_time outputs the elapsed time for each calling, but you can use the interval option when you want to get statistics in each interval.

measure_time: {"max":1.011,"avg":0.002","num":10,"class":"Fluent::GrepOutput","hook":"emit","object_id":83935080}

where max and avg are the maximum and average elapsed times, and num is the number of being called in each interval.

Configuration Example (2) - Profile the in_forward plugin

I introduce an interesting example here.

Following illustration draws the sequence of that in_forward plugin receives a data, processes, and passes the data to output plugins.

Sequence Diagram

     +–––––––––––––+    +––––––––––––––+   +––––––––––––––+
     |  in_forwrd  |    |   Output     |   |   Output     |
     +––––––+––––––+    +––––––+–––––––+   +––––––+–––––––+
#on_message | start = Time.now |                  |
            +––––––––––––––––––>                  |
            |      #emit       |                  |
            |                  +––––––––––––––––––>
            |                  |      #emit       |
            |                  |                  |
            |                  |                  |
            |                  <– – – – – – – – – +
            | elapsed = Time.now - start          |
            <– – – – – - – – – +                  |
            |                  |                  |
            +                  +                  +

As the illustration, by hooking on_message method of in_forward plugin, we can measure the blocking time taking to process the received data, which also means that the time taking until in_forward will be ready for receiving a next data.

This profiling is very useful to investigate when you have a suspicion that throughputs of Fluentd fell down extremely.

The configuration will be as follows:

<source>
  type measure_time
  # This makes available the `masure_time` directive for all plugins
</source>

<source>
  type forward
  port 24224
  <measure_time>
    tag measure_time
    hook on_message
  </measure_time>
</source>

<match measure_time>
  type stdout
</match>

# whatever you want
<match **>
  type stdout
</match>

Output becomes as below:

measure_time: {"time":0.000849735,"class":"Fluent::ForwardInput","hook":"on_message","object_id":83935080}

ChangeLog

See CHANGELOG.md for details.

Contributing

Fork it
Create your feature branch (git checkout -b my-new-feature)
Commit your changes (git commit -am 'Add some feature')
Push to the branch (git push origin my-new-feature)
Create new Pull Request