JVM进程CPU占用率高于100%

半兽人 发表于: 2018-02-24   最后更新时间: 2018-02-28  
  •   13 订阅,295 游览

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’ 找出问题代码






发表于: 3月前   最后更新时间: 3月前   游览量:295
上一条: 自己写一个java.lang.reflect.Proxy代理
下一条: LinkedBlockingQueue线程安全例子

评论…


  • 评论…
    • in this conversation
      提问