一次Full GC分析

清疚 2022-05-08 11:22 178阅读 0赞

# 背景 #

最近开始看gc日志，感觉颇有了解。但苦于手上没有例子来练手，结果昨天下午，受到joy-merchant-service的告警，表示有full gc，虽然这个不是我负责的服务，但是好不容易逮到怎么能不管，于是晚上饭后开始查看问题。

![在这里插入图片描述][70]

# 解决步骤 #

### 问题表现 ###

我发现该服务线上共四台机器，每台机器在发布的时候都会发生full gc，但是  
仅限于发布的时候，而且次数不多1-3次。

### 历史记录 ###

想起以前阿菜改过一次joy-merchant的full-gc的问题，然后找到大象的记录：

![在这里插入图片描述][70 1]

### 第一次假想 ###

看到上面之前的问题后，我第一个想法是，会不会还是同样的问题，jvm参数被改了。  
然后一顿操作：

whereis tomcat
    tomcat: /usr/local/tomcat
    cat /usr/local/tomcat/bin/catalina.sh

找到启动参数配置如下：

![在这里插入图片描述][70 2]  
然后其他几台机器的配置都是一样的。然后我知道我们这边机器都是java8的。  
这个时候如果是老司机，就已经能发现问题了。  
但是我还在看参数有什么不对，继续研究。

通过配置发现，线上机器老年代用的CMS垃圾回收器  
然后需要了解一下配置参数的意义：

<table> 
 <thead> 
  <tr> 
   <th>参数</th> 
   <th>意义</th> 
  </tr> 
 </thead> 
 <tbody> 
  <tr> 
   <td>-XX:SurvivorRatio=8</td> 
   <td>两个Survivor和eden的比，8表示eden：survivor1:survivor2=8:1:1</td> 
  </tr> 
  <tr> 
   <td>-XX:MaxTenuringThreshold=9</td> 
   <td>年龄阈值</td> 
  </tr> 
  <tr> 
   <td>-XX:+UseConcMarkSweepGC</td> 
   <td>设置老年代为CMS收集器</td> 
  </tr> 
  <tr> 
   <td>-XX:+UseCMSInitiatingOccupancyOnly</td> 
   <td>使用手动定义初始化定义开始CMS收集；不进行自动平衡</td> 
  </tr> 
  <tr> 
   <td>-XX:+CMSScavengeBeforeRemark</td> 
   <td>开启在CMS重新标记阶段之前的清除尝试</td> 
  </tr> 
  <tr> 
   <td>-XX:+ScavengeBeforeFullGC</td> 
   <td>Full GC前调用YGC</td> 
  </tr> 
  <tr> 
   <td>-XX:+UseCMSCompactAtFullCollection</td> 
   <td>使用并发收集器时，开启对老年代的压缩</td> 
  </tr> 
  <tr> 
   <td>-XX:+CMSParallelRemarkEnabled</td> 
   <td>降低标记停顿</td> 
  </tr> 
  <tr> 
   <td>-XX:CMSFullGCsBeforeCompaction=9</td> 
   <td>设置多少次Full GC后，对老年代进行压缩</td> 
  </tr> 
  <tr> 
   <td>-XX:CMSInitiatingOccupancyFraction=80</td> 
   <td>使用cms作为垃圾回收使用70%后开始CMS收集（老年代）</td> 
  </tr> 
  <tr> 
   <td>-XX:+CMSClassUnloadingEnabled</td> 
   <td>相对于并行收集器，CMS收集器默认不会对永久代进行垃圾回收。如果希望对永久代进行垃圾回收，可用设置标志</td> 
  </tr> 
  <tr> 
   <td>-XX:SoftRefLRUPolicyMSPerMB=0</td> 
   <td>每兆堆空闲空间中SoftReference的存活时间</td> 
  </tr> 
  <tr> 
   <td>-XX:-ReduceInitialCardMarks</td> 
   <td>这个是为了解决 jdk 6u18 放入大对象导致 jvm crash bug 的一个配置参数</td> 
  </tr> 
  <tr> 
   <td>-XX:+CMSPermGenSweepingEnabled</td> 
   <td>允许对持久代进行清理</td> 
  </tr> 
  <tr> 
   <td>-XX:CMSInitiatingPermOccupancyFraction=80</td> 
   <td>设置Perm Gen（永久代）使用到达多少比率时触发CMS GC</td> 
  </tr> 
  <tr> 
   <td>-XX:+ExplicitGCInvokesConcurrent</td> 
   <td>HeapDumpOnOutOfMemoryError</td> 
  </tr> 
  <tr> 
   <td>-XX:+PrintGCDetails</td> 
   <td>开启了详细GC日志模式</td> 
  </tr> 
  <tr> 
   <td>-XX:+PrintGCDateStamps</td> 
   <td>GC发生的时间信息</td> 
  </tr> 
  <tr> 
   <td>-XX:+PrintGCApplicationConcurrentTime</td> 
   <td>打印每次垃圾回收前,程序未中断的执行时间</td> 
  </tr> 
  <tr> 
   <td>-XX:+PrintGCApplicationStoppedTime</td> 
   <td>打印垃圾回收期间程序暂停的时间</td> 
  </tr> 
  <tr> 
   <td>-XX:+PrintHeapAtGC</td> 
   <td>打印GC前后的详细堆栈信息</td> 
  </tr> 
  <tr> 
   <td>-Xloggc:/data/applogs/heap_trace.txt</td> 
   <td>把相关日志信息记录到文件以便分析</td> 
  </tr> 
  <tr> 
   <td>-XX:-HeapDumpOnOutOfMemoryError</td> 
   <td>让JVM在出现内存溢出时候Dump出当前的内存转储快照</td> 
  </tr> 
  <tr> 
   <td>-XX:HeapDumpPath=/data/applogs/HeapDumpOnOutOfMemoryError</td> 
   <td>指定导出堆的存放路径</td> 
  </tr> 
  <tr> 
   <td>待续</td> 
   <td></td> 
  </tr> 
 </tbody> 
</table>

疯狂操作之后，发现更清晰了，然后发现关键配置 \-Xloggc:/data/applogs/heap\_trace.txt ，马上找到这个位置，查看fullGC相关日志。

### fullGC日志 ###

命令：

cat -n heap_trace.txt | grep -15 'CMS'

得到如下日志：

2018-10-10T17:22:02.983+0800: 15.371: Total time for which application threads were stopped: 0.0004046 seconds, Stopping threads took: 0.0001968 seconds
       716	 CMS: abort preclean due to time 2018-10-10T17:22:03.005+0800: 15.394: [CMS-concurrent-abortable-preclean: 3.996/5.201 secs] [Times: user=14.58 sys=0.54, real=5.21 secs] 
       717	2018-10-10T17:22:03.010+0800: 15.398: Application time: 0.0267885 seconds
       718	2018-10-10T17:22:03.010+0800: 15.399: [GC (CMS Final Remark) [YG occupancy: 466879 K (1812800 K)]{Heap before GC invocations=3 (full 1):
       719	 par new generation   total 1812800K, used 466879K [0x0000000680600000, 0x00000006fb500000, 0x00000006fb500000)
       720	  eden space 1611392K,  24% used [0x0000000680600000, 0x0000000698e95660, 0x00000006e2ba0000)
       721	  from space 201408K,  32% used [0x00000006ef050000, 0x00000006f2faa998, 0x00000006fb500000)
       722	  to   space 201408K,   0% used [0x00000006e2ba0000, 0x00000006e2ba0000, 0x00000006ef050000)
       723	 concurrent mark-sweep generation total 3222528K, used 80301K [0x00000006fb500000, 0x00000007c0000000, 0x00000007c0000000)
       724	 Metaspace       used 44821K, capacity 45488K, committed 45788K, reserved 1089536K
       725	  class space    used 5365K, capacity 5541K, committed 5552K, reserved 1048576K
       726	2018-10-10T17:22:03.011+0800: 15.399: [GC (CMS Final Remark) 15.399: [ParNew: 466879K->89071K(1812800K), 0.0922275 secs] 547181K->169373K(5035328K), 0.0923299 secs] [Times: user=0.23 sys=0.01, real=0.09 secs] 
       727	Heap after GC invocations=4 (full 1):
       728	 par new generation   total 1812800K, used 89071K [0x0000000680600000, 0x00000006fb500000, 0x00000006fb500000)
       729	  eden space 1611392K,   0% used [0x0000000680600000, 0x0000000680600000, 0x00000006e2ba0000)
       730	  from space 201408K,  44% used [0x00000006e2ba0000, 0x00000006e829bf10, 0x00000006ef050000)
       731	  to   space 201408K,   0% used [0x00000006ef050000, 0x00000006ef050000, 0x00000006fb500000)
       732	 concurrent mark-sweep generation total 3222528K, used 80301K [0x00000006fb500000, 0x00000007c0000000, 0x00000007c0000000)
       733	 Metaspace       used 44821K, capacity 45488K, committed 45788K, reserved 1089536K
       734	  class space    used 5365K, capacity 5541K, committed 5552K, reserved 1048576K
       735	}
       736	15.491: [Rescan (parallel) , 0.0329930 secs]15.524: [weak refs processing, 0.0008164 secs]15.525: [class unloading, 0.0109658 secs]15.536: [scrub symbol table, 0.0069518 secs]15.543: [scrub string table, 0.0012339 secs][1 CMS-remark: 80301K(3222528K)] 169373K(5035328K), 0.1479142 secs] [Times: user=0.36 sys=0.01, real=0.15 secs] 
       737	2018-10-10T17:22:03.158+0800: 15.547: Total time for which application threads were stopped: 0.1482674 seconds, Stopping threads took: 0.0000994 seconds
       738	2018-10-10T17:22:03.159+0800: 15.547: [CMS-concurrent-sweep-start]
       739	2018-10-10T17:22:03.172+0800: 15.560: Application time: 0.0133639 seconds
       740	2018-10-10T17:22:03.172+0800: 15.561: Total time for which application threads were stopped: 0.0006498 seconds, Stopping threads took: 0.0000686 seconds
       741	2018-10-10T17:22:03.178+0800: 15.566: [CMS-concurrent-sweep: 0.019/0.019 secs] [Times: user=0.06 sys=0.00, real=0.02 secs] 
       742	2018-10-10T17:22:03.178+0800: 15.566: [CMS-concurrent-reset-start]
       743	2018-10-10T17:22:03.188+0800: 15.576: [CMS-concurrent-reset: 0.010/0.010 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
       744	2018-10-10T17:22:04.173+0800: 16.561: Application time: 1.0000975 seconds

其中关键信息：  
**Metaspace used 44821K, capacity 45488K, committed 45788K, reserved 1089536K**

这个说明metaspace使用空间达到44m的时候，就发生了full gc，然后扩容之后，第二次full gc时，情况是这样的：  
**Metaspace used 91845K, capacity 92995K, committed 93504K, reserved 1132544K**

### 找到原因 ###

上面可以发现是因为metaspace空间满了导致full gc。那么问题来了，我们metaspaceSize设置的多大呢？从上面的参数打印来看，并没有配置  
好吧，这就是原因。线上的配置是-XX:PermSize=350m -XX:MaxPermSize=350m ，这都是永久代的配置，但我们线上已升级到java8，并没有永久代。java8取而代之的是metaspace，所以，最终原因是，升级了java8，但是启动参数没有修改。

网上说如果没有配置metaspaceSize，默认大小时20.8M，我在本地测试确实发现是这样，但是这里，为什么是45m？这个问题需要阅读的您帮我解决！！！

还有就是，我们升级了很多机器，为什么就这一个服务启动是会发生full gc？  
这个也很简单，metaspace存放类和方法的元数据以及常量池，joy-merchant项目很老了，东西太多。  
再次更新，事实证明我太大意了，其他服务启动的时候也发生了full gc，只不过没有配置告警而已。20.8m还是太小了

然后就是CMS的日志解析，有兴趣可以阅读文章：[CMS收集过程和日志分析][CMS]

### 解决办法 ###

修改参数：-XX:MetaspaceSize=128m -XX:MaxMetaspaceSize=256m

### 知识补充 ###

关于metaspaceSize这里有几个要点需要明确：

*  无论-XX:MetaspaceSize配置什么值，Metaspace的初始容量一定是21807104（约20.8m）；
 *  Metaspace由于使用不断扩容到-XX:MetaspaceSize参数指定的量，就会发生FGC；且之后每次Metaspace扩容都会发生FGC；
 *  如果Old区配置CMS垃圾回收，那么第2点的FGC也会使用CMS算法进行回收；
 *  Meta区容量范围为\[20.8m, MaxMetaspaceSize)；
 *  如果MaxMetaspaceSize设置太小，可能会导致频繁FGC，甚至OOM；

# 总结 #

多背 多记 多实践 形成沉淀

[70]: /images/20220508/a4ba3304b772404daaca973cf551afde.png
[70 1]: /images/20220508/4f386e54d81e498faf2fde711b20204a.png
[70 2]: /images/20220508/82291d6dcf2347f9aea9df4acf98219a.png
[CMS]: http://www.cnblogs.com/zhangxiaoguang/p/5792468.html