LogStash configuration is compiled for every sample

[ggrossetie]

We have a quite complex configuration file (approximately 1500 lines) and I believe that this line is costly: https://github.com/elastic/logstash/blob/master/lib/logstash/pipeline.rb#L26

If I understand correctly this code, a new pipeline is created for every sample() method, meaning that the configuration is compiled every time.

Meaning that the following test will load and compile 3 times the same configuration:

require "test_utils"

describe "apache common log format" do
  extend LogStash::RSpec

  config %q{
    # Your logstash filter config here
  }

  sample "apache log in debug" do
    insist { subject["level"] } == "DEBUG"
  end
  sample "apache log in info" do
    insist { subject["level"] } == "INFO"
  end
  sample "apache log with stack trace" do
    insist { subject["stacktrace"] } == "oups!"
  end
end

Would it be possible to configure this behavior ? We have 300+ samples and running our tests suite is really slow.
Having said that I think that this behavior should be the default. If I do want to use a different configuration I can call config again with the new configuration, no ?

[ggrossetie]

Each time pipeline.instance_eval is called, LogStash::Pipeline.new(config) is invoked.
I've modified logstash_helpers.rb to add timings:

      let(:results) do
        puts "do results"
        results = []
        start = Time.now
        pipeline.instance_eval { @filters.each(&:register) }
        puts "pipeline.instance_eval in #{Time.now - start} s"

        start = Time.now
        event.each do |e|
          # filter call the block on all filtered events, included new events added by the filter
          pipeline.filter(e) { |filtered_event| results << filtered_event }
        end
        puts "pipeline.filter in #{Time.now - start} s"

        start = Time.now
        # flush makes sure to empty any buffered events in the filter
        pipeline.flush_filters(:final => true) { |flushed_event| results << flushed_event }
        puts "pipeline.flush_filters in #{Time.now - start} s"

        start = Time.now
        results.select { |e| !e.cancelled? }
        puts "results.select in #{Time.now - start} s"
      end

And here is the output:

do results
pipeline.instance_eval in 19.147 s
pipeline.filter in 0.018 s
pipeline.flush_filters in 0.001 s
results.select in 0.0 s
do results
pipeline.instance_eval in 17.688 s
pipeline.filter in 0.003 s
pipeline.flush_filters in 0.0 s
results.select in 0.0 s
do results
pipeline.instance_eval in 17.342 s
pipeline.filter in 0.002 s
pipeline.flush_filters in 0.0 s
results.select in 0.0 s
do results

[ggrossetie]

Actually the value is cached across multiple calls in the same sample but not across samples.
See: https://www.relishapp.com/rspec/rspec-core/v/3-3/docs/helper-methods/let-and-let

[guyboertje]

@Mogztter - would it help if the sample method allowed you to pass in a pipeline object?

  def sample(sample_event, user_pipeline = nil , &block)
    name = sample_event.is_a?(String) ? sample_event : LogStash::Json.dump(sample_event)
    name = name[0..50] + "..." if name.length > 50

    describe "\"#{name}\"" do
      let(:pipeline) { user_pipeline || LogStash::Pipeline.new(config) }
...
....
    end
end

However I would be worried about the pipeline having some in-flight events internally. The pipeline object does not have a reset method.

Obviously you want a clean setup for RSpec.

[ggrossetie]

@guyboertje Yes this is one way of solving the problem but I think "end user" should not be aware of LogStash internal (pipeline).

It would be nice if we could be able to execute multiple samples against the same configuration using Rspec context.
I think this make sense to state in this context (with this configuration) I was to execute sample A and B. Behind the scene a pipeline will be instantiate and configure only once to execute sample A and B.

If I want to execute sample A with another configuration, I can declare another context with another configuration.

[guyboertje]

@Mogztter - in this case the "end user" has the role of test case developer and with this role comes some degree of responsibility for the objects under test. Presently, the sample method hides the fact that 'object under test' is really a (new) pipeline instance in a RSpec let block (preserving the clean state for each it block contract). As soon as that is deviated from, the test case developer must take responsibility for the 'object under test'.

I know what you want to achieve, but I think there is a strong chance of 'not clean slate' tests.

Also, FWIW, this issue is the correct place to generally discuss this (not your PR, as it is only one possible solution to this issue).

[ph]

I am okay with having a way to execute multiples test with a single pipeline instance, I understand the cost of bringing one up on every tests. But the problem with the #sample method is the context, it is used by plugin author, core developers and config developers and they don't have the same requirements.

By requirements, I mean they expect a clean state on every calls of sample which is the current behavior and this is usually what you want when you when are developping the system, you want to make sure that every call is independent of the other, one way to do it is to have a new pipeline under evaluation.

On the other hand, You as the devops/user, you want want fast feedback against the same configuration and the sample method doesn't provide it out of the box.

[ph]

@guyboertje @Mogztter maybe having a subset of specialized helpers targeted at config developers would be better?

[jsvd]

@Mogztter all this you're fighting are rspec mechanisms to ensure isolation in tests. The reason you're fighting it is because logstash is slow when setting up the filters :(

I wonder if we can profile the filter register calls and see which ones are making this delay so big.

[ph]

@Mogztter the problem in changing sample behavior can impact other plugins or core tests.

[guyboertje]

@ph - Note: @Mogztter is also (in the PR) proposing to change the config helper method behaviour.

I was thinking of this:

let(:config) { }
samples do |p|
  # or let(:config) { }
  sample("apache log in debug", p) do
    #expectation
  end
  sample("other", p) do
    # expectation
  end
end

where the samples method provides the 'clean' pipeline. Also, by injecting it into sample here and not providing it elsewhere we retain backwards compatibility.

There is a way to hide the (reused) pipeline provided by samples but it means more work in sample

All of the above is dependent on a way to reset or light-weight clone a pipeline instance when receiving it in sample.

[guyboertje]

@ph - yes perhaps a tailored helpers is a good idea.