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。