Logstash 1.5.6 consuming CPU when no incoming traffic

Elastic Stack Logstash
1

I have a logstash listening on a single port that has accepted traffic from filebeats.
It was working fine for a few hours.

Now I've stopped all the filebeats, there is no incomming traffic on the listened port.

But I can see the process is still consuming 100-200% of cpu (16-core architecture).

this is a thread list from the top command:

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
443328 idam 20 0 6144m 764m 14m S 14.3 1.2 41:27.93 java
443336 idam 20 0 6144m 764m 14m R 12.3 1.2 104:46.11 java
443335 idam 20 0 6144m 764m 14m R 12.0 1.2 104:46.30 java
443337 idam 20 0 6144m 764m 14m R 12.0 1.2 104:46.40 java
443338 idam 20 0 6144m 764m 14m R 12.0 1.2 104:46.36 java
443325 idam 20 0 6144m 764m 14m S 6.3 1.2 39:56.15 java
443326 idam 20 0 6144m 764m 14m S 6.3 1.2 39:57.65 java
443330 idam 20 0 6144m 764m 14m S 6.3 1.2 39:57.82 java
443322 idam 20 0 6144m 764m 14m S 6.0 1.2 39:40.54 java
443323 idam 20 0 6144m 764m 14m S 6.0 1.2 40:57.23 java
443327 idam 20 0 6144m 764m 14m S 6.0 1.2 41:03.17 java
443331 idam 20 0 6144m 764m 14m S 6.0 1.2 39:28.39 java
443332 idam 20 0 6144m 764m 14m S 6.0 1.2 39:34.49 java
443333 idam 20 0 6144m 764m 14m S 6.0 1.2 41:05.91 java
443334 idam 20 0 6144m 764m 14m S 6.0 1.2 41:05.80 java
443339 idam 20 0 6144m 764m 14m S 6.0 1.2 70:11.28 java
443324 idam 20 0 6144m 764m 14m S 5.7 1.2 43:53.77 java
443329 idam 20 0 6144m 764m 14m S 5.7 1.2 42:32.37 java
443340 idam 20 0 6144m 764m 14m S 1.0 1.2 451:47.04 java
443362 idam 20 0 6144m 764m 14m S 0.3 1.2 0:20.09 <beats
443306 idam 20 0 6144m 764m 14m S 0.0 1.2 0:00.01 java
443321 idam 20 0 6144m 764m 14m S 0.0 1.2 0:17.48 LogStash::Runne
443341 idam 20 0 6144m 764m 14m S 0.0 1.2 0:27.41 java
443342 idam 20 0 6144m 764m 14m S 0.0 1.2 0:27.99 java
443343 idam 20 0 6144m 764m 14m S 0.0 1.2 0:01.28 java
443344 idam 20 0 6144m 764m 14m S 0.0 1.2 0:00.00 java
443345 idam 20 0 6144m 764m 14m S 0.0 1.2 0:07.00 java
443346 idam 20 0 6144m 764m 14m S 0.0 1.2 0:07.33 java
443347 idam 20 0 6144m 764m 14m S 0.0 1.2 0:06.73 java
443348 idam 20 0 6144m 764m 14m S 0.0 1.2 0:06.62 java
443349 idam 20 0 6144m 764m 14m S 0.0 1.2 0:07.55 java
443350 idam 20 0 6144m 764m 14m S 0.0 1.2 0:06.95 java
443351 idam 20 0 6144m 764m 14m S 0.0 1.2 0:07.63 java
443352 idam 20 0 6144m 764m 14m S 0.0 1.2 0:07.71 java
443353 idam 20 0 6144m 764m 14m S 0.0 1.2 0:02.88 java
443354 idam 20 0 6144m 764m 14m S 0.0 1.2 0:02.74 java
443355 idam 20 0 6144m 764m 14m S 0.0 1.2 0:03.01 java
443356 idam 20 0 6144m 764m 14m S 0.0 1.2 0:02.87 java
443357 idam 20 0 6144m 764m 14m S 0.0 1.2 0:00.00 java
443358 idam 20 0 6144m 764m 14m S 0.0 1.2 0:50.27 java
443360 idam 20 0 6144m 764m 14m S 0.0 1.2 0:00.00 java
443361 idam 20 0 6144m 764m 14m S 0.0 1.2 0:12.20 LogStash::Runne
443363 idam 20 0 6144m 764m 14m S 0.0 1.2 73:54.21 >output
443364 idam 20 0 6144m 764m 14m S 0.0 1.2 21:42.55 <beats
443620 idam 20 0 6144m 764m 14m S 0.0 1.2 16:50.18 <beats
443735 idam 20 0 6144m 764m 14m S 0.0 1.2 16:09.65 <beats
443737 idam 20 0 6144m 764m 14m S 0.0 1.2 17:41.94 <beats
and there are still ESTABLISHED connections to the port logstash is listening on.

So the question is "what is the Logstash doing now?"

I didn't kill the process yet, so if you want some thread dump or anything - let me know.

2

I've seen these messages in the log file (2 of them, just a minute or so away from each other):

{:timestamp=>"2016-02-04T08:35:30.258000+0530", :message=>"Beats input: unhandled exception", :exception=>#<Zlib::BufError: buffer error>, :backtrace=>["org/jruby/ext/zlib/ZStream.java:134:in finish'", "org/jruby/ext/zlib/JZlibInflate.java:72:ininflate'", "/opt/idam/monitoring/logstash-1.5.6-multiline/vendor/bundle/jruby/1.9/gems/logstash-input-beats-0.9.4/lib/lumberjack/beats/server.rb:292:in compressed_payload'", "/opt/idam/monitoring/logstash-1.5.6-multiline/vendor/bundle/jruby/1.9/gems/logstash-input-beats-0.9.4/lib/lumberjack/beats/server.rb:163:infeed'", "/opt/idam/monitoring/logstash-1.5.6-multiline/vendor/bundle/jruby/1.9/gems/logstash-input-beats-0.9.4/lib/lumberjack/beats/server.rb:296:in compressed_payload'", "/opt/idam/monitoring/logstash-1.5.6-multiline/vendor/bundle/jruby/1.9/gems/logstash-input-beats-0.9.4/lib/lumberjack/beats/server.rb:163:infeed'", "/opt/idam/monitoring/logstash-1.5.6-multiline/vendor/bundle/jruby/1.9/gems/logstash-input-beats-0.9.4/lib/lumberjack/beats/server.rb:338:in read_socket'", "/opt/idam/monitoring/logstash-1.5.6-multiline/vendor/bundle/jruby/1.9/gems/logstash-input-beats-0.9.4/lib/lumberjack/beats/server.rb:315:inrun'", "/opt/idam/monitoring/logstash-1.5.6-multiline/vendor/bundle/jruby/1.9/gems/logstash-input-beats-0.9.4/lib/logstash/inputs/beats.rb:168:in invoke'", "org/jruby/RubyProc.java:281:incall'", "/opt/idam/monitoring/logstash-1.5.6-multiline/vendor/bundle/jruby/1.9/gems/concurrent-ruby-0.9.2-java/lib/concurrent/executor/executor_service.rb:515:in run'", "Concurrent$$JavaExecutorService$$Job_1733551511.gen:13:inrun'"], :level=>:error}

3

Configs would help people guess at the issue

4

Oh yes...

input {
  beats {
    port => 5004
  }
}

output {
  stdout {
#    codec => rubydebug
  }
}

and the stdout is redirected to /dev/null

I just wanted to ensure that the input is able to handle the load.

5

Sounds like the thread is hosed trying to process the message over and over
again. If you can get a heap dump and thread dump that can tell you what it
is stuck on. Otherwise, restart logstash. I figure you might have a little
bit of message loss.

6

I don't see anything suspicious in thread dump...

Here it is:

https://justpaste.it/r5ev

Could you take a look? I probably missed something, as the process still uses around 200% of CPU.

7

I believed this is "normal" behavior, maybe caused by jRuby, everyone complains about high cpu compared to other softwares such as fluentd.

I am using LogStash with RabbitMQ, but see everytime high cpu for a few messages, whereas fluentd consumes a little for almost the same pipeline.