记CPU占用过高的排查

收到CPU占用过高的报警信息，小心脏一跳，赶紧打开VPN看看哪个进程搞鬼。登录CRT，使用top命令定位进程信息：

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND 
41142 root      20   0 20.1g 7.7g  12m S 873.9 12.2 148837:32 java        
 2050 root      20   0 13.8g 1.3g  10m S 30.8  2.1  19488:27 java     
18746 root      20   0 38828  20m 5732 S  2.7  0.0   1634:57 sap1009     
43379 root      20   0 3033m  41m  14m S  2.3  0.1   3407:34 tafnode

使用top -Hp pid定位线程信息：

  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND  
41162 root      20   0 20.1g 7.7g  12m S 82.1 12.2  17439:20 java     
41163 root      20   0 20.1g 7.7g  12m S 82.1 12.2  17457:51 java     
41164 root      20   0 20.1g 7.7g  12m S 82.1 12.2  17649:40 java     
41166 root      20   0 20.1g 7.7g  12m S 82.1 12.2  17565:14 java

使用jstack pid > stack.txt获取线程栈信息，由于其中的线程ID使用16进制，所以先将线程ID转为16进制，使用如下命令：

echo "obase=16;41162" | bc
A0CA

可知线程41162的16进制形式为A0CA，再使用命令grep a0ca stack.txt -A 10取到其中的详细信息：

"Gang worker#0 (Parallel CMS Threads)" prio=10 tid=0x00007f9cb8219800 nid=0xa0ca runnable 

"Gang worker#1 (Parallel CMS Threads)" prio=10 tid=0x00007f9cb821b800 nid=0xa0cb runnable 

"Gang worker#2 (Parallel CMS Threads)" prio=10 tid=0x00007f9cb821d000 nid=0xa0cc runnable 

"Gang worker#3 (Parallel CMS Threads)" prio=10 tid=0x00007f9cb821f000 nid=0xa0cd runnable 

"Gang worker#4 (Parallel CMS Threads)" prio=10 tid=0x00007f9cb8221000 nid=0xa0ce runnable 

"VM Periodic Task Thread" prio=10 tid=0x00007f9cb8686000 nid=0xa0db waiting on condition

Gang worker为CMS垃圾收集器的处理线程，此处对老年代进行回收。定位到垃圾收集器的问题，那么使用命令jstat -gccause 41142 2000查看回收情况：

 S0     S1     E      O      P     YGC     YGCT    FGC    FGCT     GCT    LGCC                GCC 
27.14   0.00  21.54  78.93  59.82   4200   79.281 279120 314876.810 314956.091 CMS Initial Mark     No GC
27.14   0.00  21.54  78.93  59.82   4200   79.281 279120 314876.810 314956.091 CMS Initial Mark     No GC
27.14   0.00  21.54  78.93  59.82   4200   79.281 279121 314877.276 314956.557 CMS Final Remark     No GC
27.14   0.00  21.59  78.93  59.82   4200   79.281 279121 314877.276 314956.557 CMS Final Remark     No GC
27.14   0.00  21.59  78.93  59.82   4200   79.281 279121 314877.276 314956.557 CMS Final Remark     No GC
27.14   0.00  21.59  78.93  59.82   4200   79.281 279122 314877.831 314957.112 CMS Initial Mark     No GC
27.14   0.00  21.59  78.93  59.82   4200   79.281 279122 314877.831 314957.112 CMS Initial Mark     No GC

果然是产生了频繁Full GC，进行了接近28万的Full GC，而Young GC为4200次，且在该命令执行的20s内，Full GC次数就增加了3次。为了更好的查明原因，先使用命令jinfo -flags 41142查看JAVA启动选项参数，结果如下：

-Xmx8096m -Xms8096m -XX:NewSize=4068m -XX:MaxNewSize=4068m -Xss1m 
-XX:+UseConcMarkSweepGC -XX:CMSInitiatingOccupancyFraction=70 -XX:CMSFullGCsBeforeCompaction=2 
-verbose:gc -Xloggc:jvm.log -XX:ErrorFile=jvm_error.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps 
-XX:+PrintGCTimeStamps -XX:+PrintGCApplicationStoppedTime 
-Dcom.sun.management.jmxremote.port=30012 -Dcom.sun.management.jmxremote.authenticate=false

得益于启动选项开启了GC的日志记录，可以查看GC日志获取更多的信息，截取日志如下：

2018-05-11T19:14:54.064+0800: 9676784.222: [GC [1 CMS-initial-mark: 3255477K(4124672K)] 4377866K(7873792K), 0.7914290 secs] [Times: user=0.79 sys=0.01, real=0.79 secs] 
Total time for which application threads were stopped: 0.7926570 seconds
2018-05-11T19:14:54.856+0800: 9676785.014: [CMS-concurrent-mark-start]
Total time for which application threads were stopped: 0.0007540 seconds
2018-05-11T19:15:05.127+0800: 9676795.285: [CMS-concurrent-mark: 10.270/10.271 secs] [Times: user=39.44 sys=2.27, real=10.27 secs] 
2018-05-11T19:15:05.127+0800: 9676795.285: [CMS-concurrent-preclean-start]
2018-05-11T19:15:05.140+0800: 9676795.298: [CMS-concurrent-preclean: 0.013/0.013 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
2018-05-11T19:15:05.140+0800: 9676795.299: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2018-05-11T19:15:10.218+0800: 9676800.376: [CMS-concurrent-abortable-preclean: 1.575/5.078 secs] [Times: user=1.58 sys=0.04, real=5.08 secs] 
2018-05-11T19:15:10.219+0800: 9676800.377: [GC[YG occupancy: 1133867 K (3749120 K)]9676800.377: [Rescan (parallel) , 0.6663010 secs]9676801.044: [weak refs processing, 0.0000100 secs] 
[1 CMS-remark: 3255477K(4124672K)] 4389345K(7873792K), 0.6664460 secs] [Times: user=10.72 sys=0.10, real=0.67 secs] 
Total time for which application threads were stopped: 0.6673220 seconds
2018-05-11T19:15:10.886+0800: 9676801.044: [CMS-concurrent-sweep-start]
2018-05-11T19:15:14.906+0800: 9676805.064: [CMS-concurrent-sweep: 4.020/4.020 secs] [Times: user=4.01 sys=0.04, real=4.02 secs] 
2018-05-11T19:15:14.906+0800: 9676805.064: [CMS-concurrent-reset-start]
2018-05-11T19:15:14.918+0800: 9676805.077: [CMS-concurrent-reset: 0.013/0.013 secs] [Times: user=0.01 sys=0.01, real=0.01 secs]

GC日志不断循环上述的片段，可知CMS GC在不断进行老年代GC。使用命令jmap -histo:live 41142查看一下老年代的存活对象情况，结果如下：

 num     #instances         #bytes  class name
----------------------------------------------
   1:      35404462     1132942784  java.util.concurrent.ConcurrentHashMap$HashEntry
   2:      36067669      865624056  java.lang.Long
   3:      36094746      577515936  java.lang.Integer
   4:       3415960      394297352  [C
   5:        172319      335338360  [I
   6:           888      276059808  [J
   7:          4112      268557272  [Ljava.util.concurrent.ConcurrentHashMap$HashEntry;
   8:       5026988      201079520  java.util.HashMap$KeyIterator

和jvm日志中，老年代占用3255477KB约3.2GB吻合，而Java初始化老年代为4G，约占用了80%的空间，并且设置了选项CMSInitiatingOccupancyFraction的值为70。也就是说，由于老年代占用量为80%，超过了进行GC的阈值70%，所以CMS进行老年代回收，但老年代的对象仍处于生存期，并不是垃圾而不能回收。由此进入死循环，不断尝试回收，但却回收不到空间，由此消耗大量CPU资源。
有必要说明一下该应用的情况：此应用为一个缓存应用，其中使用了ConcurrentHashMap<Long, Integer>存储数据，预估需存储2000万条记录，使用HashMap的简单估算约使用：72 * 20 000 000 ≈ 1.44GB，估算方法可参考文章正确计算Java对象所占内存。由于ConcurrentHashMap有额外的并发存储开销，实际中的内存占用会大于使用HashMap的估算值，在此先忽略。查看应用，Map中已有超过3500万条记录，由此占用了3.2G内存。仔细检查代码，发现没有对过期的数据进行删除，由此导致记录数不断增长，老年代内存占用过高。
找到了原因，应急的解决方法就是：重启应用。好一点的方法是：代码中加入数据过期处理，再重启应用。最终的解决方法是：不要在内存中存储数据量过大的数据，而存储到Redis等外部缓存应用中，这样应用才更稳定。