JVM CPU 使用率高 问题两则

最近有两个系统先后被恶意扫描,出现 CPU 使用率高的现象。很好,把问题暴露出来解决掉。

CPU 使用率很高,首先是要找出 CPU 在执行什么样的代码,然后在分析这些代码有什么问题。

一、问题定位

1、 用命令 “ps aux | grep APP” 找出应用的进程 id:

801       84703  5.6 28.8 4627436 1132100 pts/2 Sl   11:08  11:19 /usr/jdk1.6.0_38/bin/java APP

2、 找出耗CPU的线程,在Linux系统下用命令:“ top –H –p pid ”, pid 就是前面找出来的应用进程 ID 。这个命令会显示出当前占用CPU高的线程。

Tasks: 426 total,   0 running, 426 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.5%us,  0.6%sy,  0.0%ni, 72.3%id, 26.6%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   3924912k total,  3308088k used,   616824k free,      768k buffers
Swap:  8388600k total,  3236720k used,  5151880k free,    12304k cached

   PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND
84784 appdeplo  20   0 4518m 1.1g 3816 S  0.4 29.0   0:00.85 java
84903 appdeplo  20   0 4518m 1.1g 3816 S  0.4 29.0   0:34.66 java
84983 appdeplo  20   0 4518m 1.1g 3816 S  0.4 29.0   0:00.99 java
85091 appdeplo  20   0 4518m 1.1g 3816 S  0.4 29.0   0:02.69 java
85164 appdeplo  20   0 4518m 1.1g 3816 S  0.4 29.0   0:04.92 java
84703 appdeplo  20   0 4518m 1.1g 3816 S  0.0 29.0   0:00.00 java
84704 appdeplo  20   0 4518m 1.1g 3816 S  0.0 29.0   0:00.42 java
84705 appdeplo  20   0 4518m 1.1g 3816 S  0.0 29.0   0:02.52 java
84706 appdeplo  20   0 4518m 1.1g 3816 S  0.0 29.0   0:02.64 java
84707 appdeplo  20   0 4518m 1.1g 3816 S  0.0 29.0   0:02.46 java
84708 appdeplo  20   0 4518m 1.1g 3816 S  0.0 29.0   0:02.39 java
84709 appdeplo  20   0 4518m 1.1g 3816 S  0.0 29.0   0:33.99 java

这里的 PID 比如 84784 是十进制的,需要转换为十六进制,用windows的计算器就可以转换了,转换为十六进制是:14B30

3、 dump 出进程的所有线程栈,用命令 “./jstack -F -m -l 84703 > 84703.stack”84703 是 pid。
dump出的其中一个线程栈大概是这样的:

"container-332" prio=10 tid=0x00007f4a044fa800 nid=0x13c7a runnable [0x00007f46e4ec8000]
   java.lang.Thread.State: RUNNABLE
         at java.net.SocketInputStream.socketRead0(Native Method)
         at java.net.SocketInputStream.read(SocketInputStream.java:129)
         at java.io.BufferedInputStream.fill(BufferedInputStream.java:218)
         at java.io.BufferedInputStream.read(BufferedInputStream.java:237)
         - locked <0x0000000709252728> (a java.io.BufferedInputStream)
         at java.io.DataInputStream.readInt(DataInputStream.java:370)
         at com.ibm.mq.MQInternalCommunications.timedReadInt(MQInternalCommunications.java:2748)
         at com.ibm.mq.MQInternalCommunications.receiveBytesFaster(MQInternalCommunications.java:2846)
         - locked <0x00000007092524e0> (a com.ibm.mq.MQv6InternalCommunications)
         at com.ibm.mq.MQInternalCommunications.receive(MQInternalCommunications.java:1179)
         - locked <0x00000007092524e0> (a com.ibm.mq.MQv6InternalCommunications)
         at com.ibm.mq.MQSESSIONClient.lowLevelComms(MQSESSIONClient.java:2841)
         - locked <0x0000000709252e10> (a java.lang.Integer)
         at com.ibm.mq.MQSESSIONClient.MQGET(MQSESSIONClient.java:1852)
         at com.ibm.mq.MQQueue.getMsg2Int(MQQueue.java:1217)
         - locked <0x0000000760c4c738> (a com.ibm.mq.MQSPIQueue)
         at com.ibm.mq.MQQueue.getMsg2(MQQueue.java:1074)
         - locked <0x0000000760c4c738> (a com.ibm.mq.MQSPIQueue)
         at com.ibm.mq.jms.MQMessageConsumer.getMessage(MQMessageConsumer.java:3451)
         at com.ibm.mq.jms.MQMessageConsumer.receiveInternal(MQMessageConsumer.java:2866)
         at com.ibm.mq.jms.MQMessageConsumer.receive(MQMessageConsumer.java:2669)
         at com.ibm.mq.connector.outbound.MessageConsumerWrapper.receive(MessageConsumerWrapper.java:180)
         at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveMessage(AbstractPollingMessageListenerContainer.java:429)
         at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.doReceiveAndExecute(AbstractPollingMessageListenerContainer.java:310)
         at org.springframework.jms.listener.AbstractPollingMessageListenerContainer.receiveAndExecute(AbstractPollingMessageListenerContainer.java:263)
         at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.invokeListener(DefaultMessageListenerContainer.java:1058)
         at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.executeOngoingLoop(DefaultMessageListenerContainer.java:1050)
         at org.springframework.jms.listener.DefaultMessageListenerContainer$AsyncMessageListenerInvoker.run(DefaultMessageListenerContainer.java:947)
         at java.lang.Thread.run(Thread.java:662)

第一行的 nid 就是前面转换出来的十六进制数字,所有线程都有这样的对应线程栈。线程dump文件是文本文件,直接用文本编辑器查看就可以了。从上面的线程栈,我们就可以看到占用cpu高的线程在做什么。

二、问题分析

这两个问题虽然原因不同,但都可以通过上面的方法找到问题代码。

复杂正则导致 CPU 使用率高

从当时 dump 出来的线程栈来看,CPU 一直在执行正则匹配。

以前一直以为正则匹配是很高效的,其实不是。Java 的正则匹配采用的贪婪模式,也就是对每个模式,采用尽可能匹配最多个字符,当匹配不成功时,再回退,这样可能导致匹配的复杂度跟字符串的长度成阶乘的关系,可以看看这篇文章的分析

随便写了个上百个字符的字符串去测试我们的正则,发现几个钟都没匹配完,汗!

HashMap 在并发访问下导致 CPU 使用率高

HashMap 是非线程安全的,在并发访问的情况下就可能出现死循环,这个死循环的分析网上很多了。Spring 的缓存模块(spring-modules-cache-0.7.jar)用它作为缓存,在平时并发访问度不高,没有问题,被恶意扫描时,就触发了死循环,可以看这个bug 报告 https://jira.spring.io/browse/MOD-371

发表评论

电子邮件地址不会被公开。 必填项已用*标注

此站点使用Akismet来减少垃圾评论。了解我们如何处理您的评论数据