前言
古语有云: 人在江湖漂, 哪有不挨刀
这几年作为技术 leader 处理过的线上紧急问题, 掐指一算应该有不下 10 次吧 (说多了都是泪啊~~) 所以挡刀救火也是 leader 的必备技能! 本文主要分享遇到 JVM 进程 CPU 占用率超 100% 时如何快速定位原因
1. 生产故障 - JVM 进程 CPU 占用率高于 100%
某日, 运维同学反馈生产环境有故障, 某个 JVM 进程 CPU 负载一直居高不下登入服务器用 top -c 命令查看如下:
- top - 00:37:39 up 48 days, 10:41, 5 users, load average: 3.34, 3.18, 3.10
- Tasks: 166 total, 1 running, 165 sleeping, 0 stopped, 0 zombie
- 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
- 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
- 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
- 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
- Mem: 16332280k total, 15744336k used, 587944k free, 200632k buffers
- Swap: 8191992k total, 408724k used, 7783268k free, 7201204k cached
- PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
- 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:
- ...
从输出结果看, CPU load 达到 3 以上, 服务器是 4 核机器, 负载已经不低了进程 ID 为 9720 的进程 CPU 占用率超过 100%
2. 定位故障的思路
首先找出问题进程内 CPU 占用率高的线程
再通过线程栈信息找出该线程当时在运行的问题代码段
3. 定位故障的步骤
3.1 用 top 命令查找进程内导致 CPU 占用率高的线程
先祭出第一招, top 命令加上 -H -b 两个选项:-H 可以查看由某个进程启动的所有线程,-b 选项指定以批处理模式输出结果 具体命令如下:
- $ top - Hbp 9702 top - 00 : 38 : 54 up 48 days,
- 10 : 43,
- 5 users,
- load average: 0.81,
- 0.36,
- 0.16 Tasks: 38 total,
- 1 running,
- 37 sleeping,
- 0 stopped,
- 0 zombie 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 Mem: 16332280k total,
- 15744500k used,
- 587780k free,
- 200632k buffers Swap: 8191992k total,
- 408724k used,
- 7783268k free,
- 7201392k cached PID USER PR NI VIRT RES SHR S % CPU % MEM TIME + COMMAND 10007 bb 20 0 2898m 348m 14m R 100.5 2.2 1 : 41.31 java 9702 bb 20 0 2898m 348m 14m S 0.0 2.2 0 : 00.00 java 9705 bb 20 0 2898m 348m 14m S 0.0 2.2 0 : 06.44 java 9706 bb 20 0 2898m 348m 14m S 0.0 2.2 0 : 00.11 java 9707 bb 20 0 2898m 348m 14m S 0.0 2.2 0 : 00.11 java 9708 bb 20 0 2898m 348m 14m S 0.0 2.2 0 : 00.11 java 9709 bb 20 0 2898m 348m 14m S 0.0 2.2 0 : 00.10 java 9710 bb 20 0 2898m 348m 14m S 0.0 2.2 0 : 00.00 java 9711 bb 20 0 2898m 348m 14m S 0.0 2.2 0 : 00.07 java 9712 bb 20 0 2898m 348m 14m S 0.0 2.2 0 : 00.03 java 9713 bb 20 0 2898m 348m 14m S 0.0 2.2 0 : 00.03 java 9714 bb 20 0 2898m 348m 14m S 0.0 2.2 0 : 00.00 java 9715 bb 20 0 2898m 348m 14m S 0.0 2.2 0 : 00.00 java 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" 10007
- 2717
因为 jstack 输出的线程栈信息中, 线程 ID 是以十六进制展示的
第二步使用命令 jstack $pid | grep 线程 id 把信息打印出来:
- $ jstack 9702 | grep '2717' -A 30
- "http-nio-9092-exec-1" daemon prio=10 tid=0x00007f3a90014800 nid=0x2717 runnable [0x00007f3afc72a000]
- java.lang.Thread.State: RUNNABLE
- at com.bb.apigateway.filter.pre.SignatureTokenFilter.run(SignatureTokenFilter.java:44)
- at com.netflix.zuul.ZuulFilter.runFilter(ZuulFilter.java:112)
- at com.netflix.zuul.FilterProcessor.processZuulFilter(FilterProcessor.java:197)
- at com.netflix.zuul.FilterProcessor.runFilters(FilterProcessor.java:161)
- at com.netflix.zuul.FilterProcessor.preRoute(FilterProcessor.java:136)
- at com.netflix.zuul.ZuulRunner.preRoute(ZuulRunner.java:105)
- at com.netflix.zuul.http.ZuulServlet.preRoute(ZuulServlet.java:125)
- at com.netflix.zuul.http.ZuulServlet.service(ZuulServlet.java:74)
- at org.springframework.web.servlet.mvc.ServletWrappingController.handleRequestInternal(ServletWrappingController.java:158)
- at org.springframework.cloud.netflix.zuul.web.ZuulController.handleRequestInternal(ZuulController.java:43)
- at org.springframework.web.servlet.mvc.AbstractController.handleRequest(AbstractController.java:147)
- at org.springframework.web.servlet.mvc.SimpleControllerHandlerAdapter.handle(SimpleControllerHandlerAdapter.java:50)
- at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:961)
- at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:895)
- at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:967)
- at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:869)
- at javax.servlet.http.HttpServlet.service(HttpServlet.java:648)
- at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:843)
- at javax.servlet.http.HttpServlet.service(HttpServlet.java:729)
- at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:292)
- at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
- at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
- at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)
- at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
- at org.springframework.boot.actuate.autoconfigure.EndpointWebMvcAutoConfiguration$ApplicationContextHeaderFilter.doFilterInternal(EndpointWebMvcAutoConfiguration.java:261)
- at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
- at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:240)
- at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:207)
- 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 找出问题代码
来源: http://www.tuicool.com/articles/Q32eEb6