gc日志分析

31日上午，收到线上告警，连续两次CMS gc。 立即检查gc日志，如下：

// 1  正常新生代GC
2020-07-31T08:52:15.431+0800: 607050.604: [GC (Allocation Failure) 2020-07-31T08:52:15.431+0800: 607050.604: [ParNew: 1260970K->3026K(1415616K), 0.0042920 secs] 1602571K->344662K(1939904K), 0.0045562 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
2020-07-31T08:52:31.250+0800: 607066.422: [GC (Allocation Failure) 2020-07-31T08:52:31.250+0800: 607066.422: [ParNew: 1261394K->3631K(1415616K), 0.0093517 secs] 1603030K->345268K(1939904K), 0.0097018 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 
2020-07-31T08:52:32.780+0800: 607067.953: [GC (Allocation Failure) 2020-07-31T08:52:32.781+0800: 607067.953: [ParNew: 1216655K->139544K(1415616K), 0.0277194 secs] 1558292K->481362K(1939904K), 0.0280757 secs] [Times: user=0.09 sys=0.01, real=0.03 secs] 

// 2 触发full GC的Minor GC
2020-07-31T08:52:38.678+0800: 607073.850: [GC (Allocation Failure) 2020-07-31T08:52:38.678+0800: 607073.850: [ParNew: 1397912K->96724K(1415616K), 0.0326443 secs] 1739730K->509169K(1939904K), 0.0329293 secs] [Times: user=0.11 sys=0.01, real=0.04 secs] 

// 3  开始Full GC
2020-07-31T08:52:38.712+0800: 607073.885: [GC (CMS Initial Mark) [1 CMS-initial-mark: 412445K(524288K)] 523425K(1939904K), 0.0034358 secs] [Times: user=0.00 sys=0.01, real=0.00 secs] 
2020-07-31T08:52:38.716+0800: 607073.888: [CMS-concurrent-mark-start]
2020-07-31T08:52:38.856+0800: 607074.029: [CMS-concurrent-mark: 0.140/0.140 secs] [Times: user=0.15 sys=0.00, real=0.14 secs] 
2020-07-31T08:52:38.856+0800: 607074.029: [CMS-concurrent-preclean-start]
2020-07-31T08:52:38.860+0800: 607074.033: [CMS-concurrent-preclean: 0.004/0.004 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
2020-07-31T08:52:38.860+0800: 607074.033: [CMS-concurrent-abortable-preclean-start]
 CMS: abort preclean due to time 2020-07-31T08:52:43.921+0800: 607079.093: [CMS-concurrent-abortable-preclean: 0.212/5.061 secs] [Times: user=0.61 sys=0.12, real=5.07 secs] 
2020-07-31T08:52:43.923+0800: 607079.095: [GC (CMS Final Remark) [YG occupancy: 386235 K (1415616 K)]2020-07-31T08:52:43.923+0800: 607079.095: [Rescan (parallel) , 0.0130790 secs]2020-07-31T08:52:43.936+0800: 607079.108: [weak refs processing, 0.0629738 secs]2020-07-31T08:52:43.999+0800: 607079.171: [class unloading, 0.0551921 secs]2020-07-31T08:52:44.054+0800: 607079.226: [scrub symbol table, 0.0214387 secs]2020-07-31T08:52:44.075+0800: 607079.248: [scrub string table, 0.0022052 secs][1 CMS-remark: 412445K(524288K)] 798680K(1939904K), 0.1799864 secs] [Times: user=0.22 sys=0.00, real=0.18 secs] 
2020-07-31T08:52:44.103+0800: 607079.275: [CMS-concurrent-sweep-start]
2020-07-31T08:52:44.228+0800: 607079.401: [CMS-concurrent-sweep: 0.125/0.125 secs] [Times: user=0.13 sys=0.00, real=0.12 secs] 
2020-07-31T08:52:44.228+0800: 607079.401: [CMS-concurrent-reset-start]
2020-07-31T08:52:44.229+0800: 607079.402: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

// 4 担保失败，触发第二次full GC
2020-07-31T08:52:58.622+0800: 607093.794: [GC (Allocation Failure) 2020-07-31T08:52:58.622+0800: 607093.794: [ParNew (promotion failed): 1355092K->1260459K(1415616K), 0.0761431 secs]2020-07-31T08:52:58.698+0800: 607093.870: [CMS: 320578K->109668K(524288K), 0.4410863 secs] 1615594K->109668K(1939904K), [Metaspace: 145566K->145566K(1187840K)], 0.5175653 secs] [Times: user=0.60 sys=0.00, real=0.51 secs] 

// 5 回复正常
2020-07-31T08:53:14.881+0800: 607110.053: [GC (Allocation Failure) 2020-07-31T08:53:14.881+0800: 607110.053: [ParNew: 1258368K->1165K(1415616K), 0.0036370 secs] 1368036K->110834K(1939904K), 0.0038635 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
2020-07-31T08:53:30.794+0800: 607125.967: [GC (Allocation Failure) 2020-07-31T08:53:30.794+0800: 607125.967: [ParNew: 1259533K->676K(1415616K), 0.0034265 secs] 1369202K->110344K(1939904K), 0.0036501 secs] [Times: user=0.01 sys=0.01, real=0.00 secs] 

gc日志第一次详细查看，看到很不明白，开始查资料，逐行解析：

一、Minor GC 日志说明

第一行： 2020-07-31T08:52:15.431+0800: 607050.604: [GC (Allocation Failure) 2020-07-31T08:52:15.431+0800: 607050.604: [ParNew: 1260970K->3026K(1415616K), 0.0042920 secs] 1602571K->344662K(1939904K), 0.0045562 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 

1. 607050.604 ： 相对JVM启动的相对时间，单位是秒
2. GC:    区别MinorGC和FullGC的标识，这次代表的是MinorGC
3. (Allocation Failure):  MinorGC的原因，由于年轻代不满足申请的空间，因此触发了MinorGC
4. ParNew:   收集器的名称，它预示了年轻代使用一个并行的 mark-copy stop-the-world 垃圾收集器
5. 1260970K->3026K :  收集前后年轻代的使用情况
6. (1415616K):  整个年轻代的容量
7. 0.0042920 secs :  本次新生代 gc耗用的时间
8. 1602571K->344662K： 收集前后整个堆的使用情况
9. (1939904K)：整个堆的容量
10. 0.0045562 secs： MinorGC花费的时长；ParNew收集器标记和复制年轻代活着的对象所花费的时间（包括和老年代通信的开销、对象晋升到老年代时间、垃圾收集周期结束一些最后的清理对象等的花销）
11. Times: user=0.01 sys=0.00, real=0.00 secs ： 

    user、sys和real与Linux的time命令所输出的时间含义一致，分别代表用户态消耗的CPU时间、内核态消耗的CPU事件和操作从开始到结束所经过的墙钟时间（Wall Clock Time）。

    CPU时间与墙钟时间的区别是，墙钟时间包括各种非运算的等待耗时，例如等待磁盘I/O、等待线程阻塞，而CPU时间不包括这些耗时，但当系统有多CPU或者多核的话，多线程操作会叠加这些CPU时间，所以读者看到user或sys时间超过real时间是完全正常的。

 二、触发full GC

    full GC开始前最后一次Minor GC:   2020-07-31T08:52:38.678+0800: 607073.850: [GC (Allocation Failure) 2020-07-31T08:52:38.678+0800: 607073.850: [ParNew: 1397912K->96724K(1415616K), 0.0326443 secs] 1739730K->509169K(1939904K), 0.0329293 secs] [Times: user=0.11 sys=0.01, real=0.04 secs]

    此时：老年代使用量超过70%，触发full GC（老年代总大小： 524288k，老年代使用/剩余： 412445k/11843k， 新生代剩余： 96724K ）

    为什么老年代超过70%就开始进行full GC呢？ 在于jvm启动时的参数配置：

    -XX:CMSInitiatingOccupancyFraction=70 是指设定CMS在对内存占用率达到70%的时候开始GC(因为CMS会有浮动垃圾,所以一般都较早启动GC);  -XX:+UseCMSInitiatingOccupancyOnly 只是用设定的回收阈值(上面指定的70%),如果不指定,JVM仅在第一次使用设定值,后续则自动调整.

    这两个设置一般配合使用,一般用于『降低CMS GC频率或者增加频率、减少GC时长』的需求

三、FULL GC 日志

    这块日志主要分成 7个阶段。比较繁杂，且已经有人介绍的很详细，不再赘述。

    直接上连接： https://www.cnblogs.com/onmyway20xx/p/6590603.html

四、担保失败，触发第二次GC

    2020-07-31T08:52:58.622+0800: 607093.794: [GC (Allocation Failure) 2020-07-31T08:52:58.622+0800: 607093.794: [ParNew (promotion failed): 1355092K->1260459K(1415616K), 0.0761431 secs]2020-07-31T08:52:58.698+0800: 607093.870: [CMS: 320578K->109668K(524288K), 0.4410863 secs] 1615594K->109668K(1939904K), [Metaspace: 145566K->145566K(1187840K)], 0.5175653 secs] [Times: user=0.60 sys=0.00, real=0.51 secs] 

    此次GC时，新生代有1.2G数据，其中晋升包含大数据对象，此时Survivor空间放不下，CMS的连续空间也放不下。造成担保失败，触发CMS GC。        

 五、触发原因总结    

    在这个连续发生两次full GC的时候，有人员正在上传大图片。这个图片的操作已经造成PS系统附件服务OOM，本系统也处于崩溃的边缘。

    后续方案：

         1、限制过大文件上传。

         2、代码中减少对这种大对象的操作。