快速定位生产故障问题-JVM进程CPU占用率高于100%

2018年03月01日 09:13:41

版权声明：本作品采用知识共享署名-非商业性使用-禁止演绎 4.0 国际许可协议进行许可

目录(?)[+]

前言

古语有云：人在江湖漂，哪有不挨刀。

这几年作为技术leader处理过的线上紧急问题，掐指一算应该有不下10次吧（说多了都是泪啊~~）。所以挡刀救火也是leader的必备技能！本文主要分享遇到“JVM进程CPU占用率超100%”时如何快速定位原因。

1. 生产故障-JVM进程CPU占用率高于100%

某日，运维同学反馈生产环境有故障，某个JVM进程CPU负载一直居高不下。登入服务器用 top -c 命令查看如下：

1. top - 00:37:39 up 48 days, 10:41, 5 users, load average: 3.34, 3.18, 3.10

2. Tasks: 166 total, 1 running, 165 sleeping, 0 stopped, 0 zombie

3. Cpu0 : 0.7%us, 0.3%sy, 0.0%ni, 99.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st

4. Cpu1 :100.0%us, 0.0%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st

5. Cpu2 : 1.3%us, 0.3%sy, 0.0%ni, 98.3%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st

6. Cpu3 : 0.3%us, 0.0%sy, 0.0%ni, 99.7%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st

7. Mem: 16332280k total, 15744336k used, 587944k free, 200632k buffers

8. Swap: 8191992k total, 408724k used, 7783268k free, 7201204k cached

9.  

10. PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND

11. 9702 bb 20 0 2898m 348m 14m S 100.6 2.2 01:47.18 java -server -Xms512M -Xmx512M -Xmn192M -Xss256k -XX:PermSize=64M -XX:MaxPermSize=128M -verbose:

12. ...

从输出结果看，CPU load 达到3以上，服务器是4核机器，负载已经不低了。进程ID为9720的进程CPU占用率超过100%。

2. 定位故障的思路

• 首先找出问题进程内CPU占用率高的线程
• 再通过线程栈信息找出该线程当时在运行的问题代码段

3. 定位故障的步骤

3.1 用top命令查找进程内导致CPU占用率高的线程

先祭出第一招， top命令加上 -H -b 两个选项：-H 可以查看由某个进程启动的所有线程，-b 选项指定以批处理模式输出结果 。具体命令如下：

1. $ top -Hbp 9702

2. top - 00:38:54 up 48 days, 10:43, 5 users, load average: 0.81, 0.36, 0.16

3. Tasks: 38 total, 1 running, 37 sleeping, 0 stopped, 0 zombie

4. Cpu(s): 3.5%us, 1.4%sy, 0.0%ni, 94.5%id, 0.3%wa, 0.0%hi, 0.2%si, 0.0%st

5. Mem: 16332280k total, 15744500k used, 587780k free, 200632k buffers

6. Swap: 8191992k total, 408724k used, 7783268k free, 7201392k cached

7.  

8. PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND

9. 10007 bb 20 0 2898m 348m 14m R 100.5 2.2 1:41.31 java

10. 9702 bb 20 0 2898m 348m 14m S 0.0 2.2 0:00.00 java

11. 9705 bb 20 0 2898m 348m 14m S 0.0 2.2 0:06.44 java

12. 9706 bb 20 0 2898m 348m 14m S 0.0 2.2 0:00.11 java

13. 9707 bb 20 0 2898m 348m 14m S 0.0 2.2 0:00.11 java

14. 9708 bb 20 0 2898m 348m 14m S 0.0 2.2 0:00.11 java

15. 9709 bb 20 0 2898m 348m 14m S 0.0 2.2 0:00.10 java

16. 9710 bb 20 0 2898m 348m 14m S 0.0 2.2 0:00.00 java

17. 9711 bb 20 0 2898m 348m 14m S 0.0 2.2 0:00.07 java

18. 9712 bb 20 0 2898m 348m 14m S 0.0 2.2 0:00.03 java

19. 9713 bb 20 0 2898m 348m 14m S 0.0 2.2 0:00.03 java

20. 9714 bb 20 0 2898m 348m 14m S 0.0 2.2 0:00.00 java

21. 9715 bb 20 0 2898m 348m 14m S 0.0 2.2 0:00.00 java

22. 9716 bb 20 0 2898m 348m 14m S 0.0 2.2 0:05.60 java

输出结果里的PID其实是线程ID，可以看到线程ID为10007的线程CPU占用率为100.5%，它就是罪魁祸首。上面的命令可以再优化下：查出CPU占用率超过某个值的所有线程，例如超过50%，如下：

top -Hbp 9702 | awk '/java/ && $9>50'

•  

3.2 用JVM命令 jstack 精确定位出问题的代码段

第二招，用jstack 命令dump出线程栈信息，可以直接定位到出问题的代码段。这里也分两步。第一步把上面的线程ID 10007 转化为十六进制：

 $ printf "%x\n" 100072717因为jstack输出的线程栈信息中，线程ID是以十六进制展示的。

第二步使用命令 jstack $pid | grep “线程id” 把信息打印出来：

1. $ jstack 9702 | grep '2717' -A 30

2. "http-nio-9092-exec-1" daemon prio=10 tid=0x00007f3a90014800 nid=0x2717 runnable [0x00007f3afc72a000]

3. java.lang.Thread.State: RUNNABLE

4. at com.bb.apigateway.filter.pre.SignatureTokenFilter.run(SignatureTokenFilter.java:44)

5. at com.netflix.zuul.ZuulFilter.runFilter(ZuulFilter.java:112)

6. at com.netflix.zuul.FilterProcessor.processZuulFilter(FilterProcessor.java:197)

7. at com.netflix.zuul.FilterProcessor.runFilters(FilterProcessor.java:161)

8. at com.netflix.zuul.FilterProcessor.preRoute(FilterProcessor.java:136)

9. at com.netflix.zuul.ZuulRunner.preRoute(ZuulRunner.java:105)

10. at com.netflix.zuul.http.ZuulServlet.preRoute(ZuulServlet.java:125)

11. at com.netflix.zuul.http.ZuulServlet.service(ZuulServlet.java:74)

12. at org.springframework.web.servlet.mvc.ServletWrappingController.handleRequestInternal(ServletWrappingController.java:158)

13. at org.springframework.cloud.netflix.zuul.web.ZuulController.handleRequestInternal(ZuulController.java:43)

14. at org.springframework.web.servlet.mvc.AbstractController.handleRequest(AbstractController.java:147)

15. at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:50)

16. at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:961)

17. at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:895)

18. at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:967)

19. at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:869)

20. at javax.servlet.http.HttpServlet.service(HttpServlet.java:648)

21. at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:843)

22. at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)

23. at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:292)

24. at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)

25. at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)

26. at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)

27. at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)

28. at org.springframework.boot.actuate.autoconfigure.EndpointWebMvcAutoConfiguration$ApplicationContextHeaderFilter.doFilterInternal(EndpointWebMvcAutoConfiguration.java:261)

29. at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)

30. at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)

31. at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)

32. at org.springframework.boot.actuate.trace.WebRequestTraceFilter.doFilterInternal(WebRequestTraceFilter.java:115)

下面这行就是出问题的业务代码，根据实际情况修复BUG即可

com.bb.apigateway.filter.pre.SignatureTokenFilter.run(SignatureTokenFilter.java:44)

4. 小结

思路：

• 找出CPU占用率高的进程
• 找出问题进程内CPU占用率高的线程
• 通过线程栈信息找出该线程当时在运行的问题代码段

实施要点：

• top -Hbp ‘pid’ 定位问题线程
• jstack ‘pid’ | grep ‘thread_id’ 找出问题代码