为什么logstash进程的CPU使用率100%？

Posted 2021-01-19 dtstack

机器上有个进程cpu使用率很高，近100%了，

Tasks: 120 total, 2 running, 118 sleeping, 0 stopped, 0 zombie
%Cpu(s): 99.0 us, 0.7 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.3 hi, 0.0 si, 0.0 st
KiB Mem: 4048308 total, 3301480 used, 746828 free, 33500 buffers
KiB Swap: 0 total, 0 used, 0 free. 149784 cached Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
18400 admin 20 0 2201508 304712 3948 S 98.1 7.5 17335:45 java
17782 root 20 0 3130780 893164 4476 S 0.7 22.1 120:19.01 java

7 root      20   0       0      0      0 S  0.3  0.0   4:01.17 rcu_sched

1114 root 20 0 154200 9676 2360 S 0.3 0.2 40:41.38 AliYunDun

看下这个进程是干什么的，发现是logstash的一个进程，这个进程的作用是从kafka读取数据，并将数据写入到elasticsearch。


cat /proc/18400/cmdline | sed -e ‘s/x00/ /g‘
/opt/dtstack/java/bin/java 
-XX:+UseParNewGC -XX:+UseConcMarkSweepGC -Djava.awt.headless=true 
-XX:CMSInitiatingOccupancyFraction=75 
-XX:+UseCMSInitiatingOccupancyOnly -XX:+HeapDumpOnOutOfMemoryError 
-Xmx128m -Xss2048k 
-Djffi.boot.library.path=/opt/dtstack/logstash-2.1.1/vendor/jruby/lib/jni 
-XX:+UseParNewGC -XX:+UseConcMarkSweepGC -Djava.awt.headless=true 
-XX:CMSInitiatingOccupancyFraction=75 -XX:+UseCMSInitiatingOccupancyOnly 
-XX:+HeapDumpOnOutOfMemoryError 
-XX:HeapDumpPath=/opt/dtstack/logstash/heapdump.hprof 
-Xbootclasspath/a:/opt/dtstack/logstash-2.1.1/vendor/jruby/lib/jruby.jar 
-classpath : -Djruby.home=/opt/dtstack/logstash-2.1.1/vendor/jruby 
-Djruby.lib=/opt/dtstack/logstash-2.1.1/vendor/jruby/lib 
-Djruby.script=jruby 
-Djruby.shell=/bin/sh org.jruby.Main 
--1.9 /opt/dtstack/logstash/lib/bootstrap/environment.rb logstash/runner.rb agent 
-f /home/admin/logstash/dtlog/conf/logindexer-kafka.conf 
-l /home/admin/logstash/dtlog/log/logindexer-kafka.log

看一下是哪个线程CPU消耗得厉害，可以使用top的-H选项查看线程的情况，使用-p选择指定pid。

发现有个command是kafka的线程cpu使用率一直很高。

top -H -p 18400
top - 12:08:19 up 19 days, 57 min, 4 users, load average: 1.04, 1.19, 1.26
Threads: 31 total, 1 running, 30 sleeping, 0 stopped, 0 zombie
%Cpu(s): 99.0 us, 0.7 sy, 0.0 ni, 0.0 id, 0.0 wa, 0.3 hi, 0.0 si, 0.0 st
KiB Mem: 4048308 total, 3321036 used, 727272 free, 36228 buffers
KiB Swap: 0 total, 0 used, 0 free. 167372 cached Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
18435 admin 20 0 2201508 304920 4120 R 97.9 7.5 17276:37 17837 admin 20 0 2201508 304920 4120 S 0.3 7.5 27:30.14 18400 admin 20 0 2201508 304920 4120 S 0.0 7.5 0:00.00 java
18413 admin 20 0 2201508 304920 4120 S 0.0 7.5 1:58.54 LogStash::Runne
18414 admin 20 0 2201508 304920 4120 S 0.0 7.5 0:00.00 java
18415 admin 20 0 2201508 304920 4120 S 0.0 7.5 0:23.43 java
18416 admin 20 0 2201508 304920 4120 S 0.0 7.5 1:42.88 java
18417 admin 20 0 2201508 304920 4120 S 0.0 7.5 0:00.35 java
18418 admin 20 0 2201508 304920 4120 S 0.0 7.5 0:00.00 java


可以使用jstack看看线程的调用栈，不过里面的内容没看明白。


jstack -F 18400 > tmp1.log
grep -A 50 18435 tmp1.log
Thread 18435: (state = IN_JAVA)

• org.jruby.runtime.callsite.CachingCallSite.call(org.jruby.runtime.ThreadContext, org.jruby.runtime.builtin.IRubyObject, org.jruby.runtime.builtin.IRubyObject) @bci=36, line=134 (Compiled frame; information may be imprecise)
• org.jruby.ast.CallNoArgNode.interpret(org.jruby.Ruby, org.jruby.runtime.ThreadContext, org.jruby.runtime.builtin.IRubyObject, org.jruby.runtime.Block) @bci=18, line=60 (Compiled frame)
• org.jruby.ast.WhileNode.interpret(org.jruby.Ruby, org.jruby.runtime.ThreadContext, org.jruby.runtime.builtin.IRubyObject, org.jruby.runtime.Block) @bci=23, line=127 (Compiled frame)
• org.jruby.ast.NewlineNode.interpret(org.jruby.Ruby, org.jruby.runtime.ThreadContext, org.jruby.runtime.builtin.IRubyObject, org.jruby.runtime.Block) @bci=41, line=105 (Compiled frame)
• org.jruby.ast.BlockNode.interpret(org.jruby.Ruby, org.jruby.runtime.ThreadContext, org.jruby.runtime.builtin.IRubyObject, org.jruby.runtime.Block) @bci=33, line=71 (Compiled

到网上找找看是否有别人遇到这个问题，搜索关键词

logstash kafka cpu high

发现还真有人遇到过这个问题：

http://stackoverflow.com/questions/34486960/logstash-kafka-input-filter-with-high-cpu-usage

The logstash-input-kafka plugin had a bug in its tight loop which unnecessarily checked for an empty queue and skipped to the next iteration instead of blocking.

This has been fixed in this pull request and version 2.0.3 of the plugin has been released with it.

To test this, please update the plugin using:

bin/plugin install --version 2.0.3 logstash-input-kafka

查看我们机器上安装的plugin版本，

$ /opt/dtstack/logstash/bin/plugin list --verbose kafka
logstash-input-kafka (2.0.2)
logstash-output-kafka (2.0.1)


升级一下版本试试

$ /opt/dtstack/logstash/bin/plugin install logstash-input-kafka-2.0.3.gem
Validating logstash-input-kafka-2.0.3.gem
Installing logstash-input-kafka
Installation successful
$ /opt/dtstack/logstash/bin/plugin list --verbose kafka
logstash-input-kafka (2.0.3)
logstash-output-kafka (2.0.1)


CPU使用率恢复正常了。