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
1
2

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 由十进制转换为十六进制。

十进制十六进制2660567ED2660267EA

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

人已赞赏
首页

基于Bootstrap的网页“音乐播放器博物馆” --- 处女作!

2019-12-18 23:56:56

首页

Java的运行原理(转载)

2019-12-19 0:01:55

0 条回复 A文章作者 M管理员
    暂无讨论,说说你的看法吧
个人中心
购物车
优惠劵
今日签到
有新私信 私信列表
搜索