JVM故障排查（　CPU飙升以及频繁FULL GC）

1.查看进程的CPU使用情况

top

top - 14:59:14 up 229 days, 15:04,  2 users,  load average: 0.00, 0.00, 0.00
Tasks: 163 total,   1 running, 162 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.2%us,  0.2%sy,  0.0%ni, 99.7%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%st
Mem:   3922080k total,  3773280k used,   148800k free,   282712k buffers
Swap:  4194300k total,        0k used,  4194300k free,  1049836k cached

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                              
 5063 appweb    20   0 6090m 2.1g  18m S  1.0 55.3 332:52.73 java                                                                  
    1 root      20   0 19344 1528 1200 S  0.0  0.0   0:29.11 init                                                                  
    2 root      20   0     0    0    0 S  0.0  0.0   0:00.00 kthreadd                                                              
    3 root      RT   0     0    0    0 S  0.0  0.0   1:23.65 migration/0                                                           
    4 root      20   0     0    0    0 S  0.0  0.0   0:42.74 ksoftirqd/0                                                           
    5 root      RT   0     0    0    0 S  0.0  0.0   0:00.00 stopper/0                                                             
    6 root      RT   0     0    0    0 S  0.0  0.0   0:34.34 watchdog/0                                                            
    7 root      RT   0     0    0    0 S  0.0  0.0   1:34.51 migration/1                                                           
    8 root      RT   0     0    0    0 S  0.0  0.0   0:00.00 stopper/1                                                             
    9 root      20   0     0    0    0 S  0.0  0.0   1:21.09 ksoftirqd/1                                                           
   10 root      RT   0     0    0    0 S  0.0  0.0   0:31.04 watchdog/1                                                            
   11 root      RT   0     0    0    0 S  0.0  0.0   1:53.36 migration/2                                                           
   12 root      RT   0     0    0    0 S  0.0  0.0   0:00.00 stopper/2                                                             
   13 root      20   0     0    0    0 S  0.0  0.0   0:42.05 ksoftirqd/2                                                           

2.查看消耗比较高的进程是哪个程序

可以看到PID=5063的Java进程CPU使用率特别高

$ jps -l
77362 sun.tools.jps.Jps
5063 com.zes.order.Test

发现是com.zes.order.Test引起的

3.查看堆栈信息

查看消耗cpu过高的线程 tid

ps p 5063 -L -o pcpu,pid,tid,time,tname,cmd

tid 31886

然后查询消耗cpu过高获取线程号 tid

$ printf "%x\n" 31886

13c7

jstack pid 命令查看当前java进程的堆栈状态 搜索tid = 13c7的线程

$ jstack 5063 

"Thread-142" #152 prio=5 os_prio=31 tid=0x00007f8a57da4000 nid=0x16b03 waiting for monitor entry [0x000070000fb1e000]
   java.lang.Thread.State: BLOCKED (on object monitor)
    at java.io.PrintStream.println(PrintStream.java:805)
    - waiting to lock <0x000000074000a990> (a java.io.PrintStream)
    at com.zes.order.Test.lambda$main$0(Test.java:17)
    at com.zes.order.Test$$Lambda$1/1389647288.run(Unknown Source)
    at java.lang.Thread.run(Thread.java:748)

我们可以根据堆栈信息，直接定位到Test的17行，查看代码中具体是什么原因导致计算量如此之高。

4.JVM频繁FullGC

jstat查看进程的运行情况

$ jstat -gc 5063 1000
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   
512.0  512.0  160.0   0.0   24064.0   1932.4   87552.0     2673.8   5504.0 5087.3 640.0  552.9     732    8.725   6703      0.000    8.725
512.0  512.0  160.0   0.0   24064.0  17768.7   87552.0     2673.8   5504.0 5087.3 640.0  552.9     732    8.725   6722      0.000    8.725
512.0  512.0   0.0   128.0  24064.0   5263.1   87552.0     2673.8   5504.0 5087.3 640.0  552.9     733    8.735   6799      0.000    8.735
512.0  512.0   0.0   128.0  24064.0  15237.0   87552.0     2673.8   5504.0 5087.3 640.0  552.9     733    8.735   6822      0.000    8.735

FGC 可以看到FullGC次数过多

dump 内存日志
jmap -dump:format=b,file=/Users/zes/Desktop/heap.hprof  5063 

vsiualVM 分析可得