GC Activity

[driverpt]

It would be nice if Logstash would create a Pool of reusable Event objects instead of constantly creating new ones.

The purpose of this, is to reduce the GC Overhead when running a Pipeline. I recommend that if this goes forward, the Pool size should be equal to the Max In Flight objects in the Pipeline.

It would cost a bit of memory, but it will boost the performance.

Log4J2 has already done something similar. See here.

Currently from my benchmarks with VisualVM, i find Logstash very GC-Active since it disposes a lot of objects.

[jsvd]

@driverpt first of all, thanks for bringing this issue up and starting the PR. What follows below is my raw mind dump about this:

To add a bit more context to this issue, here is a bit of background on logstash memory consumption:

---

Logstash is an streaming event processing pipeline, which means the unit of work is the event, which is created from byte streams through the inputs, gets filtered, and then pushed out through outputs. Once these stages are completed the event is discarded. Each event is composed of a LogStash::Event instance and data in the form of multiple instances of classes like strings, numbers, arrays and hash maps.

If Logstash is processing 10k eps it will allocate + deallocate events at the same rate, 10k allocations+10k deallocations per second (note that deallocations will be batched by the gc).

---

With this in mind it begs the question if such allocation+GC activity has an impact in performance, and if so at which rate does logstash saturate the cpu enough that GC is stealing away from it.

Also, taking from the fact that GC overhead accounts for more than X% of cpu time and that X is not tolerable, we need to understand what instances do we need to avoid allocating to lower X% to an acceptable Y%. For example, do we accomplish this by not allocating LogStash::Event instances as in #5455 ? Thinking now, I can think of other (hidden) costs, drawbacks and tradeoffs that need measuring, like:

• all data that is put into the events is still allocated and collected from the heap
• cleaning the contents of an event for reusability has a cost
• does the return of an output's receive(event) ensure the event won't be used anymore? What if an output buffers?
• what is the overhead of managing the object pool?
• filters like split and clone will consistently multiply the inflight event count by N fold, should we parse the config file and adjust this pool size?

@driverpt ^ these are my current questions about this, I haven't ran any benchmarks or done any tests to know more about this problem as such an investigation is as important is time consuming :) Is there more information you can share, like reproducible benchmark scripts/results, heapdumps, preliminary results with your #5455 ?

[colinsurprenant]

@driverpt before moving forward with this idea I'd like to see a performance analysis which demonstrate that GC activity has a significant impact on logstash performance.

5455 might be a good idea but I'd like to avoid proposing solutions to an unsubstantiated problem at this point. Could you share any of your observations which mesure the impact of the GC activity?

[driverpt]

@jsvd @colinsurprenant . The conclusions that led to this behaviour was the memory consumption and it's relation to the GC activity. We monitored the memory consumption and GC activity and noticed that it peaks when Memory reaches 3/4 of Heap, as you can see in the screenshot. From my experience this is what is called a Hard GC, which means it's "Stop the world!" to free memory, which in high data throughput environments it can cause the loss of events due to TCP Input not being able to receive.

Today we're going to test the performance with the applied patches in the Pull Request to see if this improves.

As a suggestion, if you want to transform Logstash into a Generic Pipeline processor, it must have as low CPU overhead as possible (at the cost of some memory of course). It can have a configurable setting to turn on the GC-Free Mode for low-memory systems.

UPDATE Forgot to mention we're generating around 6k Events per second in batches of 10 Events per TCP Input using a custom script.

[jsvd]

From that CPU/GC activity charts we can conclude some things:

a) Xms is not set to Xmx, which means the jvm will allocate by default the Xms size and, if memory hits a certain percentage, it gradually grows until it hits Xmx (also, any resize of heap triggers a full gc)

b) CPU isn't saturated: CPU usage varies around 50% with some spikes. I'd be interested to see the balance between CPU usage and GC activity during maximum throughput. Most IO and locking resolution will create idle time in the CPU, which seems to be giving plenty of cycles to the GC without stealing away from logstash's throughput

c) there's a periodic behaviour (every 20 minutes?) that triggers a lot of memory allocation, do you know what's happening in those moments?

Can you try the same tests with Xmx==Xms==1gb or 2gb? I'm curious to see a more prolonged gc behaviour, for 2 or 3 hours.

[kryptpt]

Hi all, @driverpt co-worker speaking.

@colinsurprenant I understand your point, and personally I respect that. I believe that Therefore, I have to say the peaks of GC activity scares me a bit. Currently our logstash instance produces ~3000 events/sec, and when GC jumps in, logstash slows down to ~1000 events/sec (sometimes ~600). For our use case, this behaviour is a critical issue.

@driverpt and I will provide conclusions later, taking in account @jsvd recommendations.

Note: we are just trying to help :)

[colinsurprenant]

@driverpt @kryptpt thanks for the information. hopefully my comment was not misunderstood as being dismissive of your concerns.

So, looking at the graphs, what I see is relatively healthy GC activity. The reported GC activity is 2.4% which is not problematic IMO and should not result in significant performance impact.

As @jsvd reported there is a bit of a weird pattern every 20 minutes right before a major GC is triggered. Typically there is a constant upward trend that ends up in a GC and so on; a typical healthy jigsaw pattern. This pattern here is very constant with a sudden memory consumption which triggers a GC. The good news is that there does not seem to be any leak involved.

Now, it is very hard to say how much this 20 minutes interval major GC actually impacts performance, my take is that it is very minimal on the overall performance.

Again, before attacking the problem from an object allocation optimization angle, I would first look at optimizing/fine tuning the JVM GC parameters but it first requires to correctly analyzing the GC activity to see what need to be optimized.

I suggest you start with looking at this article https://engineering.linkedin.com/garbage-collection/garbage-collection-optimization-high-throughput-and-low-latency-java-applications which list a few good pointers.

[colinsurprenant]

also @kryptpt could you elaborate on

when GC jumps in, logstash slows down to ~1000 events/sec (sometimes ~600)

Is that what we see every ~20 minutes? In other words, do you see a slowdown from ~3000 to ~1000 every 20 minutes in that major GC period?

[colinsurprenant]

And thinking some more about that, I would definitely try to understand this sudden memory consumption spike we see every ~15-20 mins. What is causing this spike might be the actual source of the slowdown instead of the GC itself that gets triggered as a result? maybe there is some periodic data patterns or some plugins are reaching some kind of thresholds which result in some heavier memory consumption? I understand you are using some custom plugins, but nonetheless could you share your config? What other plugins are you using?

[kryptpt]

@colinsurprenant I'm really thankful for your help. We will look at JVM GC parameters as you recommended.

Answering your question, we are seeing this happening every 20 minutes in GC periods. The data pattern is approximately 3000 events/sec (with a oscillation of 300 events). The events are flat json objects with 9 keys, with a size of ~180 characters.
We built a dedup plugin that discards an event if received before in a given time window (1 second currently). It's a big HashMap initialized to support 4096 events, re-created second by second.

[colinsurprenant]

@kryptpt what input/filter/output/codec plugins are you running other than your custom filter? Could you share your config?

For your dedupping, are you dedupping on a particular key only? what are you doing to identify a duplicate? comparing the original json message field?

Have you tried running logstash without the custom dedupping filter to see if there is a difference in the GC activity?

[kryptpt]

@colinsurprenant I'm not authorized to share that here (NDA), my sincere apologies. Therefore I can describe it in an abstract way.

input: 
  tcp
filter:
  blacklist (custom)
  dedup (custom)
  classification (custom)
  if
    mutate
  else
    mutate 
output:
   udp 

Our dedupping plugin hashes a event (xxhash) then stores it onto a HashMap. We made it such way that we can configure what are the keys we want dedupping on. We only compare hashes (long values), not the event itself. The plugin discards and re-create a new HashMap time by time which is also configured.

Dedup plugin makes GC activity higher than usual, but we can stabilized it until our acceptable state extending the time window. The "stop the world" issue remains, even without our dedupping plugin activated.

Then comes the idea to propose a solution which Logstash becomes "GC free". Of course, it's a astronomic step with a huge impact which we expected to be questioned, but we feel a little responsible to give our contribute to the project because we recognized the passion and effort of the team that maintains the project, and also importance of project itself.

Note: Thanks for your attention guys, I really appreciate that.

[kryptpt]

Anyway, @jsvd @colinsurprenant you are right and we will perform some load tests with new GC parameters as you recommended.

[colinsurprenant]

@kryptpt

Dedup plugin makes GC activity higher than usual

Have you considered using alternate strategies like a bloom filter instead of hashes? (see https://github.com/colinsurprenant/bloombroom) - this is something I meant to do to refresh that gem and make a LS plugin with it.

Also, you have 3 custom plugins, I would definitely try and isolate each to see if any of there are responsible for this memory consumption spike we see every 15-20m. Again, without more information, this is the only thing which seems a concern here and I have not really seen such a memory consumption pattern with logstash. Unless there is a memory leak, the pattern is the typical upward jigsaw pattern where memory consumption gradually go up until it triggers a major GC, goes down and so on.

My hypothesis here (obviously I might be wrong, I don't have much information to work with) is that the slowdown you witness might be related to this memory consumption spike and maybe not the GC itself?

Then comes the idea to propose a solution which Logstash becomes "GC free"

It is not a bad idea per-se, it's just that we are proposing a solution for a problem that we haven't fully understood yet. Before going that route, there is a lot that can be done first in measuring if/where there is GC performance impact and after tuning the memory + GC parameter to better fit your use-case. The default setting are not bad but can definitely be tweaked to specific logstash configurations and use-cases.