Interpreting output of logstash metrics filter

I am trying to understand the output of the logstash metrics filter . I have provided my config below

input {
beats {
port => 5044
}
}

filter {
metrics {
meter => "documents"
add_tag => "metric"
flush_interval => 300
}
}

output {
if "metric" in [tags] {
stdout {
codec => line { format => "1m rate: %{[documents][rate_1m]} 5m rate: %{[documents][rate_5m]} ( %{[documents][count]} ) "}
}
}

kafka {
topic_id => "topbeat-stage"
acks => "all"
}
}

I am generating a meter event every minute. The output from this config looks like this

1m rate: 0.18044890219106202E3 5m rate: 0.2600351072999375E3 ( 4307 )
1m rate: 173.89725967987482 5m rate: 192.70737574400775 ( 6188 )
1m rate: 0.11145593844218484E3 5m rate: 0.22895949668831238E3 ( 7174 )
1m rate: 109.4792179541377 5m rate: 171.86302887539142 ( 9054 )

If I take the last row ( 1m rate: 109.4792179541377 5m rate: 171.86302887539142 ( 9054 )), what does it signify.

  • Does it mean, logstash filter plugin is processing 109 events in the last minute and 171*5 events in the last 5 min
  • Is 9054 the total number of events it has processed so far ?
  • The difference between the doc count for this row(9054) and the doc count for the previous row(7174) is around 1880 . That does not match either the 1 min rate or the 5 min rate. Am i misinterpreting something ?
  • The problem is that if i try to match these numbers to the number of events added in elastic per minute , they do not add up at all.

any help here please ?

Your interpretation is right, and your assessment that the numbers don't line up is also correct. That's not good :(.

Could you also log the @timestamp of these events? My thinking is that for some reason they're not flushing at the right intervals perhaps. Could you open a ticket on https://github.com/logstash-plugins/logstash-filter-metrics/issues so we can take a further look?

This is how the output looks after adding @timestamp.

1m rate| 2016-01-30T03:01:27.093Z | 156.28981476909323 5m rate: 200.3834395629629 ( 4941 )
1m rate| 2016-01-30T03:02:27.087Z | 119.09684969884763 5m rate: 183.42570974398714 ( 9432 )
1m rate| 2016-01-30T03:03:27.086Z | 99.88978458297444 5m rate: 167.96488037187547 ( 13536 )

PS:- I had changed the flush_interval to 60 (instead of 300) .

Opened issue 29