fluent-plugin-measure_time

Fluentd plugin to measure elapsed time to process messages

Use RubyGems:

gem install fluent-plugin-measure_time

• 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.

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

For Fluentd v0.10:

<source>
  type measure_time
  # This makes available the `measure_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>
</match>

For Fluentd v0.12:

<label @measure_time>
  <match>
    @type measure_time
    # This makes available the `measure_time` directive for all plugins
  </match>
</label>

<source>
  @type dummy
  tag raw.dummy
  dummy {"message":"foo"}
</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>
</match>

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.

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.

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:

For Fluentd v0.10:

<source>
  type measure_time
  # This makes available the `measure_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>

For Fluentd v0.12:

<label @measure_time>
  <match>
    @type measure_time
    # This makes available the `measure_time` directive for all plugins
  </match>
</match>

<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}

See CHANGELOG.md for details.

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

Copyright (c) 2014 Naotoshi Seo. See LICENSE for details.