Test: add a performance regression test

a follow-up on logstash-pluginsGH-153

spec/filters/grok_performance_spec.rb

@@ -44,13 +44,80 @@
       max_duration = EVENT_COUNT / EXPECTED_MIN_RATE
       pipeline = new_pipeline_from_string(config)
       expect do
-        start = Time.now
-        pipeline.run
-        duration = (Time.now - start)
+        duration = measure { pipeline.run }
         puts "filters/grok parse rate: #{"%02.0f/sec" % (EVENT_COUNT / duration)}, elapsed: #{duration}s"
       end.to perform_under(max_duration).warmup(1).sample(2).times
     end
 
   end
 
+  describe "timeout", :performance => true do
+
+    ACCEPTED_TIMEOUT_DEGRADATION = 7.5 # in % (compared to timeout-less run)
+    # NOTE: usually bellow 5% on average -> we're expecting every run to be < (+ given%)
+
+    it "has less than #{ACCEPTED_TIMEOUT_DEGRADATION}% overhead" do
+      no_timeout_config = <<-CONFIG
+        input {
+          generator {
+            count => 500000
+            message => "Mar 16 00:01:25 evita postfix/smtpd[1713]: connect from aaaaaaaa.aaaaaa.net[111.111.11.1]"
+          }
+        }
+        filter {
+          grok {
+            match => { "message" => [ 
+              "foo0: %{NUMBER:bar}", "foo1: %{NUMBER:bar}", "foo2: %{NUMBER:bar}", "foo3: %{NUMBER:bar}", "foo4: %{NUMBER:bar}",
+              "foo5: %{NUMBER:bar}", "foo6: %{NUMBER:bar}", "foo7: %{NUMBER:bar}", "foo8: %{NUMBER:bar}", "foo9: %{NUMBER:bar}",
+              "%{SYSLOGLINE}" 
+            ] }
+            timeout_scope => "pattern"
+            timeout_millis => 0   # 0 - disabled timeout
+          }
+        }
+        output { null { } }
+      CONFIG
+
+      timeout_config = no_timeout_config.
+          sub('timeout_scope => "pattern"', 'timeout_scope => "event"').
+          sub('timeout_millis => 0', 'timeout_millis => 10000')
+
+      no_timeout_pipeline = new_pipeline_from_string(no_timeout_config)
+      no_timeout_duration = measure { no_timeout_pipeline.run } # warmup
+      puts "filters/grok(timeout => 0) warmed up in #{no_timeout_duration}"
+
+      no_timeout_durations = Array.new(3).map do
+        duration = measure { no_timeout_pipeline.run }
+        puts "filters/grok(timeout => 0) took #{duration}"
+        duration
+      end
+
+      timeout_pipeline = new_pipeline_from_string(timeout_config)
+      timeout_duration = measure { timeout_pipeline.run } # warmup
+      puts "filters/grok(timeout_scope => event) warmed up in #{timeout_duration}"
+
+      expected_duration = avg(no_timeout_durations)
+      expected_duration += (expected_duration / 100) * ACCEPTED_TIMEOUT_DEGRADATION
+      puts "expected_duration #{expected_duration}"
+      expect do
+        duration = measure { timeout_pipeline.run }
+        puts "filters/grok(timeout_scope => event) took #{duration}"
+        duration
+      end.to perform_under(expected_duration).sample(3).times
+    end
+
+  end
+
+  @private
+
+  def measure
+    start = Time.now
+    yield
+    Time.now - start
+  end
+
+  def avg(ary)
+    ary.inject(0) { |m, i| m + i } / ary.size.to_f
+  end
+
 end