Next generation pipeline

[andrewvc]

This replaces #4254 which got just a bit too big. It's squashed and rebased off master.

[andrewvc]

I've done some benchmarking parsing apache logs with the cloud benchmarker and indexing them to ES. The results are pretty interesting. The upshot is, for this benchmark, the ng_pipeline was 28.67% faster than master.

This is a preliminary benchmark of just apache log file parsing (with grok / geoip / useragent) with the cloud benchmarker. I anticipate other benchmarks to act differently. The comments below discuss its performance on this task.

To start with the new pipeline seems quite a bit faster BUT the tuning is all different. There are three parameters to tune the new pipeline:

• -w number of workers
• -b batch size
• -u batch pop latency

The key takeaways were:

• Have more takeaways than cores for either pipeline. -w 8 seemed to be the sweet spot.
• The -u setting doesn't change much if anything. We should leave it in, just in case, but the default of 5ms works fine.
• Tuning -b is very important! For the apache logs a larger batch size yielded significant gains. We may strongly want to consider size based dynamic batches to help optimize this. Currently its hard to know the size of an event, but with the persistent pipeline that should be easier.
• Adjusting master's SizedQueue size did nothing

[andrewvc]

I should mention that watching these benchmarks in htop it seemed that the classic pipeline didn't saturate the cores as effectively and used more system time. I think there are some constant time operations in it that impede thread liveness.

This was partially measured in other benchmarks in #4254 by running the two pipelines within the time command. There's probably an even better way to get at this impact.

[colinsurprenant]

I just completed a round of tests & benchmarks using 2 different configs and sets of inputs. I will put my results in a table but before I wanted to report I problem I encountered using many workers and bigger batch size so that other can see if they can reproduce.

I am seeing the following error output and getting various output delays (output completely stops for seconds)

Concurrent::TimeoutError {:class=>"Concurrent::TimeoutError", :backtrace=>nil, :level=>:warn}

The config & data used is in https://gist.github.com/colinsurprenant/8143a0dfd30830d57b03 and the command line where I started noticing these errors is with

$ while true; do cat syslog.dat; done | bin/logstash -w 8 -b 8000 -f syslog.conf

using syslog.dat and syslog.conf in the gist ^^

[jordansissel]

@andrewvc your most recent patch (the while loop timer) LGTM, butI haven't tested it.

[ph]

@andrewvc what was the issue with the task?

[colinsurprenant]

@andrewvc perfect! I much prefer this simpler flushing implementation, plus it uses Stud.stoppable_sleep which is preferable for handling the shutdown sequence.

I haven't been able to reproduce the Concurrent::TimeoutError exception 👍

Before I post my benchmarks results, I realize that the high workers + bigger batch runs might have been slowed down by the heap memory pressure, so I will re-run them and post results!

[andrewvc]

Thanks @colinsurprenant ! In retrospect, the benchmarks I ran above probably saw declining numbers with greater batch sizes due to memory pressure more than CPU. That said, I think I'll hold off on running further benchmarks till a future date since the main point is that the new pipeline is much more efficient than the old one given similar resources.

[ph]

woa cleaner +1

[colinsurprenant]

Here are my results.

• MBP 13r, 2.8 GHz Intel Core i7, 16GB
• Java 8 1.8.0_45-b14
• logstash config:

input {
  stdin {
    codec => json_lines
  }
}

filter {
  mutate {
    add_field => ["[fields][date]",  "%{+YYYY-MM-dd:HH:mm:ss}"]
    add_field => ["[fields][mixed]",  "foo %{+YYYY-MM-dd} %{foo}"]
    add_field => ["[fields][foo]",  "%{foo}"]
    add_field => ["[fields][bar]",  "%{bar}"]
    remove_field => ["foo"]
    remove_field => ["bar"]
  }
}

output {
  stdout { codec => json_lines }
}

• base command line, adjust -w and -b per bench:

$ yes '{"foo":"testfoo","bar":"testbar"}' | LS_HEAP_SIZE=4g bin/logstash -w X -b Y -f bench.conf | pv -Wlart > /dev/null

• results for a 1 minute run, the average k lines per sec (or kTPS). Note that only a single run has been measured for each scenario, and there is slight variations from run to run with same parameters.

[colinsurprenant]

LGTM

[ph]

did another run LGTM, nice work @andrewvc

[andrewvc]

Thanks for putting in so much time to review and find bugs in this PR @colinsurprenant and @ph !

[elasticsearch-bot]

Andrew Cholakian merged this into the following branches!

Branch	Commits
master	028576b, 3a1b0f2

[colinsurprenant]

one observation: as we can see, these isn't much a difference in the previous performance numbers, for the same workers and default batch the ng-pipeline is slightly faster. I will not post all the results but I performed a few similar tests using the config at https://gist.github.com/colinsurprenant/8143a0dfd30830d57b03 and the performance gain is higher, for example from 5.5k/s in master to 6.6k/s with ng-pipeline which is a lot more significative.

In the previous benchmarks, the input side had more to do because of the JSON parsing by the codec and this input is not parallelized so I think that the input was the actual choke point while in the other tests, the input is straight stdin line input and everything is done in the filters so the hard work is effectively in the filter stage which benefits the ng batching etc.