Java 应用中高 CPU 利用率问题的定位
文章目录
1. Java 应用中 CPU 峰值故障的排查
Java 应用高 CPU 利用率可能与以下几种原因有关：
- 垃圾收集执行 Full GC 过于频繁，但由于 servlet 容器内应用里的一个内存泄漏问题，或者 servlet 容器自身的内存泄漏问题，导致每次 Full GC 无法释放很多内存出来。
- 由于应用需要更多内存所以垃圾回收器经常执行 Full GC (类似于前面一点所述，但可能没有内存泄漏，单单是分的内存过少)。
译者注：类似于前面一点所述，但跟它还不一样，指的是没有内存泄漏的内存不足的情况，比如分给 JVM 的内存过少，架构或程序存在内存设计不合理等问题
- 程序自身存在的资源竞争，长时间运行的任务，高计算代价等一些问题。
列出这些条目的目的是记载一个解决 Java 应用程序中高 CPU 使用率问题的简单流程，先看是否是 GC 相关，然后逐一排查。
2. 查找 JVM 进程
ps aux | grep java
tomcat 26551 128 30.9 3946348 1215360 ? Sl 13:43 26:21 /usr/java/latest/bin/java ........ org.apache.catalina.startup.Bootstrap start
3. 根据上一步中找到的 Java 主线程 ID 生成线程栈快照
JVM 主线程 = Linux 进程，其他 Java 线程 = 轻量级进程 (Lightweight process LWP)
4. 查找出 CPU 使用率高嫌疑轻量级进程 (LWP)。
top -H
top - 13:59:28 up 29 days, 11:15, 1 user, load average: 5.15, 4.75, 3.38
Tasks: 512 total, 8 running, 504 sleeping, 0 stopped, 0 zombie
Cpu0 : 84.9%us, 9.4%sy, 0.0%ni, 3.7%id, 0.7%wa, 0.0%hi, 1.3%si, 0.0%st
Cpu1 : 84.7%us, 8.0%sy, 0.0%ni, 5.0%id, 0.7%wa, 0.0%hi, 1.7%si, 0.0%st
Mem: 3924512k total, 3784340k used, 140172k free, 148876k buffers
Swap: 2093052k total, 0k used, 2093052k free, 1995456k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
26605 tomcat 20 0 3853m 1.1g 12m R 32.2 29.8 3:10.85 java
26602 tomcat 20 0 3853m 1.1g 12m R 14.1 29.8 1:26.46 java
26771 tomcat 20 0 3853m 1.1g 12m S 2.6 29.8 0:11.74 java
26558 tomcat 20 0 3853m 1.1g 12m S 2.3 29.8 0:06.19 java
26742 tomcat 20 0 3853m 1.1g 12m S 2.3 29.8 0:11.74 java
26792 tomcat 20 0 3853m 1.1g 12m S 2.3 29.8 0:11.82 java
26555 tomcat 20 0 3853m 1.1g 12m S 2.0 29.8 0:06.07 java
26556 tomcat 20 0 3853m 1.1g 12m S 2.0 29.8 0:05.95 java
26743 tomcat 20 0 3853m 1.1g 12m S 2.0 29.8 0:11.63 java
26744 tomcat 20 0 3853m 1.1g 12m S 2.0 29.8 0:11.89 java
26748 tomcat 20 0 3853m 1.1g 12m S 2.0 29.8 0:11.60 java
26770 tomcat 20 0 3853m 1.1g 12m S 2.0 29.8 0:11.76 java
26772 tomcat 20 0 3853m 1.1g 12m S 2.0 29.8 0:11.67 java
26776 tomcat 20 0 3853m 1.1g 12m S 2.0 29.8 0:11.51 java
26794 tomcat 20 0 3853m 1.1g 12m S 2.0 29.8 0:11.70 java
26795 tomcat 20 0 3853m 1.1g 12m S 2.0 29.8 0:11.91 java
26796 tomcat 20 0 3853m 1.1g 12m S 2.0 29.8 0:11.53 java
26800 tomcat 20 0 3853m 1.1g 12m S 2.0 29.8 0:11.70 java
26806 tomcat 20 0 3853m 1.1g 12m S 2.0 29.8 0:11.56 java
可以看到有两个 LWP 分别使用了 CPU 的 32% 和 14%，而其他的则大都保持在 2% 的这样一个水平。
5. 将高 CPU 使用率的 LWP 的 ID 由十进制转换为十六进制。
| 十进制 | 十六进制 |
|---|---|
| 26605 | 67ED |
| 26602 | 67EA |
6. 打开第三步拿到的线程栈快照，找到 nid 为 0x67ed 和 0x67ea 那两个线程。
....
"Dispatcher-Thread-5" daemon prio=10 tid=0x00007faee4862800 nid=0x67ed runnable [0x00007faf0f8ea000]
java.lang.Thread.State: RUNNABLE
at java.util.regex.Pattern$GroupHead.match(Pattern.java:4556)
at java.util.regex.Pattern$Start.match(Pattern.java:3408)
at java.util.regex.Matcher.search(Matcher.java:1199)
at java.util.regex.Matcher.find(Matcher.java:592)
at java.util.regex.Matcher.replaceAll(Matcher.java:902)
at java.lang.String.replaceAll(String.java:2162)
at com.xxxxx.xxxxx.common.log4j.layout.PCIPatternLayout.format(PCIPatternLayout.java:122)
at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:302)
at org.apache.log4j.RollingFileAppender.subAppend(RollingFileAppender.java:263)
at org.apache.log4j.WriterAppender.append(WriterAppender.java:160)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
- locked <0x0000000781277710> (a com.xxxxxx.xxxxxx.common.pci.log4j.DateRollingFileAppender)
at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
at org.apache.log4j.AsyncAppender$Dispatcher.run(AsyncAppender.java:583)
- locked <0x0000000781276590> (a org.apache.log4j.helpers.AppenderAttachableImpl)
at java.lang.Thread.run(Thread.java:745)
...
"Dispatcher-Thread-2" daemon prio=10 tid=0x00007faee47b9000 nid=0x67ea runnable [0x00007faf0fbed000]
java.lang.Thread.State: RUNNABLE
at java.util.regex.Pattern$GroupHead.match(Pattern.java:4556)
at java.util.regex.Pattern$Start.match(Pattern.java:3408)
at java.util.regex.Matcher.search(Matcher.java:1199)
at java.util.regex.Matcher.find(Matcher.java:592)
at java.util.regex.Matcher.replaceAll(Matcher.java:902)
at java.lang.String.replaceAll(String.java:2162)
at com.xxxxxx.xxxxxx.common.log4j.layout.PCIPatternLayout.format(PCIPatternLayout.java:122)
at org.apache.log4j.WriterAppender.subAppend(WriterAppender.java:302)
at org.apache.log4j.RollingFileAppender.subAppend(RollingFileAppender.java:263)
at org.apache.log4j.WriterAppender.append(WriterAppender.java:160)
at org.apache.log4j.AppenderSkeleton.doAppend(AppenderSkeleton.java:251)
- locked <0x000000078126a9b0> (a org.apache.log4j.RollingFileAppender)
at org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders(AppenderAttachableImpl.java:66)
at org.apache.log4j.AsyncAppender$Dispatcher.run(AsyncAppender.java:583)
- locked <0x000000078126a968> (a org.apache.log4j.helpers.AppenderAttachableImpl)
at java.lang.Thread.run(Thread.java:745)
7. 故障排查
根据前边得到的线程栈样本，貌似高的 CPU 占用率跟 log4j 的异步追加有关，在本案例中很有可能涉及 PCIPatternLayout.format() 方法。
8. 结论
两个高 CPU 使用率的 LWP 都指向了同一个原因，解决办法是将 snmp4j 升级到截止到发现问题时的最新版本，并在相关程序中将 log4j appender 配置文件中的自定义布局移除。
关于作者
Orlando L Otero 是联邦快递的一名软件工程师顾问，专注于系统集成，微服务，API 设计、实现以及敏捷交付。
原文链接：https://tech.asimio.net/2016/02/11/Troubleshoot-high-CPU-usage-in-Java-applications.html。
