LS 6.2.3: JVM heap size filling up with default jvm.options (invokedynamic and jit.threshold is set)

[marioplumbarius]

• Version:
  6.2.3
• Operating System:
  RHEL
  jruby 9.1.13.0 (2.3.3) 2017-09-06 8e1c115 OpenJDK 64-Bit Server VM 25.162-b12 on 1.8.0_162-b12 +jit [linux-x86_64]
• Config File (if you have sensitive info, please remove it):

input {
  udp {
    port => 55514
    type => syslog
    queue_size => 20000
    receive_buffer_bytes => 134217728
    workers => 2
    codec => plain {
      charset => "ISO-8859-1"
    }
  }
}

filter {}
output {}

• When I remove the following settings, the issue disappears.

# Turn on JRuby invokedynamic
-Djruby.compile.invokedynamic=true
# Force Compilation
-Djruby.jit.threshold=0

• Sample Data:

"{\"type\":\"syslog\",\"@timestamp\":\"2018-04-09T15:46:03.071Z\",\"host\":\"127.0.0.1\",\"message\":\"<38>2018-04-09T15:46:03 localhost prg00000[1234]: seq: 0000057360, thread: 0000, runid: 1523288758, stamp: 2018-04-09T15:46:03 PADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADD\",\"@version\":\"1\"}"

• Steps to Reproduce:

1. Start Logstash
2. Send 10k sample data per second
3. Logstash is going to crash and restart

This same piece of come used to handle up to 40k events per second.

UPDATE: I've just confirmed the issue raises even when only the udp input is set.

[andrewvc]

@marioluan I take it this started after an upgrade? Which version were you using previously?

[marioplumbarius]

@andrewvc Yes, it started after an upgrade from LS 5.6.3.

[andrewvc]

Hmmmm, I had trouble reproducing this locally with 6.2.3. See the below yourkit perf charts. The heap looks quite healthy.

I'm sending data with: while true; echo sampledata | nc -c -u localhost 55514; end (using fish shell).

How are you determining that the heap is full?

[marioplumbarius]

@andrewvc

1. Regarding the heap size, the following error message is shown at the logs:

[2018-04-09T15:41:42,331][ERROR][org.logstash.Logstash    ] java.lang.OutOfMemoryError: Java heap space

2. How many messages per second could you send using while true?
I use to generate syslog messages by using loggen.

The way I could reproduce the issue was by running loggen with the following settings:

loggen --dgram --size=300 --interval=300 --rate=10000 localhost 55514

[andrewvc]

Would you mind sharing a heap dump? https://dzone.com/articles/memory-analysis-how-to-obtain-java-heat-dump

I'll try and repro on a linux box, loggen isn't available on OSX AFAICT

[marioplumbarius]

@andrewvc sent you an email.

Let me know when you have the linux box results in place.

[marioplumbarius]

@andrewvc I included a grok filter to that config and got different error messages:
Filter:

grok {
    "tag_on_failure" => []
    "match" => { "message" => "^<%{NONNEGINT}>%{SYSLOGTIMESTAMP}\[%{POSINT}\]: %{POSINT:heartbeat_ts_ms:int}$" }
  }

Errors:

[2018-04-12T14:53:18,420][ERROR][logstash.filters.grok    ] Error while attempting to check/cancel excessively long grok patterns {:message=>"Java heap space", :class=>"Java::JavaLang::OutOfMemoryError", :backtrace=>[]}

[2018-04-12T14:55:24,603][ERROR][org.logstash.Logstash    ] java.lang.IllegalArgumentException: Self-suppression not permitted

PS: This grok pattern runs OK in 5.6.3.

[marioplumbarius]

Another thing I noticed: the issue is intermittent, that is, after restarts it can happen (or not).

[andrewvc]

@marioluan what configurations options are you passing into LS? I'm especially interested in the batch size and the number of workers. If you aren't setting the number of workers, how many cores are you using?

[andrewvc]

Looking at the heap dump I see I lot of RubyString objects, ~93,400 of them. They appear to be 65535 bytes apiece.

The weird thing here is that the Ruby strings are not really that long, they're zero padded to reach that size. The actual message is only 300 bytes. So, that's quite a bit of overhead.

I was wondering if it is the case that your batch_size*num_workers > 93400, and that maybe you were sending too many large messages, but it seems like these Ruby String objects are just many times larger than they need to be.

[andrewvc]

Also, which queue are you using? Memory or persistent?

[marioplumbarius]

@andrewvc thanks for taking a look at this.

This is the settings from logstash.yml:

pipeline.workers: 8
pipeline.batch.size: 500
metric.collect: true

I'm also setting heap space to 1GB in jvm.options:

-Xms1g
-Xmx1g

And this is the packet I'm sendint to the UDP listener:

{
  "@timestamp": "2018-04-09T15:46:03.071Z",
  "@version": "1"​,
  "host": "127.0.0.1",
  "message": "<38>2018-04-09T15:46:03 localhost prg00000[1234]: 
  seq: 0000057360, thread: 0000, runid: 1523288758, stamp: 
  2018-04-09T15:46:03 PADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPAD
  DPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPA
  DDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADDPADD",
  "type": "syslog"
}

And I'm using default config for queues.

[praseodym]

The UDP plugin is likely the cause of the 65535 byte strings you are seeing:

https://github.com/logstash-plugins/logstash-input-udp/blob/cf26a0561e186544b079522e58ed5aa1c8705949/lib/logstash/inputs/udp.rb#L26