文章目录

  • 1. Java 应用中 CPU 峰值故障的排查
  • 2. 查找 JVM 进程
  • 3. 根据上一步中找到的 Java 主线程 ID 生成线程栈快照
  • 4. 查找出 CPU 使用率高嫌疑轻量级进程 (LWP)。
  • 5. 将高 CPU 使用率的 LWP 的 ID 由十进制转换为十六进制。
  • 6. 打开第三步拿到的线程栈快照，找到 nid 为 0x67ed 和 0x67ea 那两个线程。
  • 7. 故障排查
  • 8. 结论
  • 关于作者


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 配置文件中的自定义布局移除。

关于作者

java Thumbnails java thumbnails造成cpu占用率高_apache


Orlando L Otero 是联邦快递的一名软件工程师顾问，专注于系统集成，微服务，API 设计、实现以及敏捷交付。