上周系统出现了FullGC频发的问题，应该是内存中又出现了大对象导致的，到底是分页查询的pageSize=10000导致的呢还是存在别的什么原因？
GC日志
19:26开始FullGC一直持续到19:40
2018-04-18T19:21:50.142+0800: 433042.760: [GC2018-04-18T19:21:50.142+0800: 433042.760: [ParNew: 631407K->2100K(707840K), 0.0056650 secs] 959391K->330123K(2018560K), 0.0059200 secs] [Times: user=0.09 sys=0.00, real=0.00 secs]
2018-04-18T19:24:03.688+0800: 433176.306: [GC2018-04-18T19:24:03.688+0800: 433176.306: [ParNew: 631348K->78592K(707840K), 0.3269520 secs] 959371K->544673K(2018560K), 0.3272060 secs] [Times: user=1.74 sys=0.06, real=0.33 secs]
2018-04-18T19:24:05.109+0800: 433177.728: [GC2018-04-18T19:24:05.109+0800: 433177.728: [ParNew: 707840K->78592K(707840K), 0.3398880 secs] 1173921K->730279K(2018560K), 0.3401420 secs] [Times: user=3.75 sys=0.00, real=0.34 secs]
2018-04-18T19:24:06.655+0800: 433179.273: [GC2018-04-18T19:24:06.655+0800: 433179.273: [ParNew: 707840K->78592K(707840K), 0.2906480 secs] 1359527K->894638K(2018560K), 0.2909050 secs] [Times: user=3.83 sys=0.00, real=0.29 secs]
2018-04-18T19:24:06.946+0800: 433179.565: [GC [1 CMS-initial-mark: 816046K(1310720K)] 903563K(2018560K), 0.0997080 secs] [Times: user=0.10 sys=0.00, real=0.10 secs]
2018-04-18T19:24:07.046+0800: 433179.665: [CMS-concurrent-mark-start]
2018-04-18T19:24:07.300+0800: 433179.918: [CMS-concurrent-mark: 0.254/0.254 secs] [Times: user=1.89 sys=0.00, real=0.26 secs]
2018-04-18T19:24:07.300+0800: 433179.919: [CMS-concurrent-preclean-start]
2018-04-18T19:24:07.314+0800: 433179.932: [CMS-concurrent-preclean: 0.013/0.013 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
2018-04-18T19:24:07.314+0800: 433179.932: [CMS-concurrent-abortable-preclean-start]
2018-04-18T19:24:09.876+0800: 433182.494: [CMS-concurrent-abortable-preclean: 2.006/2.562 secs] [Times: user=7.38 sys=0.23, real=2.56 secs]
2018-04-18T19:24:09.877+0800: 433182.495: [GC[YG occupancy: 692704 K (707840 K)]2018-04-18T19:24:09.877+0800: 433182.495: [Rescan (parallel) , 0.4336470 secs]2018-04-18T19:24:10.310+0800: 433182.929: [weak refs processing, 0.0042640 secs]2018-04-18T19:24:10.315+0800: 43
3182.933: [class unloading, 0.0233340 secs]2018-04-18T19:24:10.338+0800: 433182.957: [scrub symbol table, 0.0194050 secs]2018-04-18T19:24:10.358+0800: 433182.976: [scrub string table, 0.0028380 secs] [1 CMS-remark: 977603K(1310720K)] 1670308K(2018560K), 0.4921040 secs]
[Times: user=11.89 sys=0.00, real=0.49 secs]
2018-04-18T19:24:10.369+0800: 433182.988: [CMS-concurrent-sweep-start]
2018-04-18T19:24:11.194+0800: 433183.813: [CMS-concurrent-sweep: 0.472/0.825 secs] [Times: user=5.27 sys=0.00, real=0.83 secs]
2018-04-18T19:24:11.194+0800: 433183.813: [CMS-concurrent-reset-start]
2018-04-18T19:24:11.203+0800: 433183.822: [CMS-concurrent-reset: 0.009/0.009 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
这是其中一部分的日志，可以看到19:24:06之前几乎都是YoungGC，FullGC的发生次数应该不会太高，但是从19:24:06开始到19:40持续了上百次的FullGC，但是老年代的空间始终没有下来。
YoungGC日志
含义
我们取日志的第一行来认识一下各个字段的含义。
2018-04-18T19:21:50.142+0800: 433042.760: [GC2018-04-18T19:21:50.142+0800: 433042.760: [ParNew: 631407K->2100K(707840K), 0.0056650 secs] 959391K->330123K(2018560K), 0.0059200 secs] [Times: user=0.09 sys=0.00, real=0.00 secs]
2018-04-18T19:21:50.142+0800: 433042.760（时间戳）: [GC（Young GC）2018-04-18T19:21:50.142+0800: 433042.760（时间戳）: [ParNew（使用ParNew作为年轻代的垃圾回收期）: 631407K（年轻代垃圾回收前的大小）->2100K（年轻代垃圾回收以后的大小）(707840K)（年轻代的总大小）, 0.0056650 secs（回收时间）] 959391K（堆区垃圾回收前的大小）->330123K（堆区垃圾回收后的大小）(2018560K)（堆区总大小）, 0.0059200 secs（回收时间）] [Times: user=0.09（Young GC用户耗时） sys=0.00（Young GC系统耗时）, real=0.00 secs（Young GC实际耗时）]
计算分析
以日志的最后两条YoungGC记录为例，最后一条记录显示年轻代回收了707840-78592=629248K,整个堆回收了1359527-894638=464889K,说明此次回收有629248-464889=164359K从年轻代转移到了老年代。
再看最后一次YoungGC前的情况，看倒数第二条记录，老年代的内存使用有730279-78592=651687K,回收后有894638-78592=816046K。
回收后老年代使用空间-回收前老年代使用空间=年轻代转向老年代空间（816046-651687=164359K）。
CMS
第一段日志后面那一段是CMS日志。
简介
CMS(Concurrent Mark Sweep)收集器是一种以获取最短回收停顿时间为目标的收集器，适用于对响应速度有追求的系统，如BS网站，有助于提高用户体验度。使用的GC算法是标记清除，用来清理老年代空间。
总共分为⑤个步骤：
①初始标记(CMS-initial-mark)
②并发标记(CMS-concurrent-mark)
③重新标记(CMS-remark)
④并发清除(CMS-concurrent-sweep)
⑤并发重置状态等待下次CMS的触发(CMS-concurrent-reset)
其中，第一步初始标记和第三步重新标记会"Stop The World",也就是挂起应用程序。初始标记仅仅是标记GCRoots能直接关联的对象，速度快。所谓的并发标记、并发清除、并发重置中的并发是指回收线程也快和应用程序一起工作。重新标记就是重新标记并发标记阶段遗漏的对象（在并发标记阶段结束后对象状态的更新导致），这一步比初始标记时间长，但比并发标记时间短。
CMS
缺点
①对CPU资源敏感。在并发阶段，占用了CPU资源导致应用程序变慢，总吞吐量降低。CMS默认启动的回收线程是(CPU数量+3)/4,cpu的占用率随着核数增多而减小。
②无法收集浮动垃圾，可能出现“Concurrent Mode Failure”失败导致下一次FullGC的发生。因为CMS与应用程序并发执行，在清理的同时也有新的垃圾产生，而此次标记结束，只好下次GC，这部分垃圾称为浮动垃圾。
③CMS使用标记清除算法，该算法的缺点的是会产生大量的内存碎片，当程序需要分配一个大对象而无法满足空间要求时，就必须提前触发下一次FullGC。
涉及的VM参数
①-XX:+UseConcMarkSweepGC （使用CMS收集器）
②-XX:CMSInitiatingOccupancyFraction=N
CMS与应用程序并发执行，所以不能等老年代满了再清理，还是要预留一部分空间给应用线程使用。那么就需要设置一个阈值，当满足百分之多少了就进行FullGC，默认是68%,通过该参数可以设置阈值。
③-XX:+UseCMSCompactAtFullCollection,上面写了CMS会产生很多内存碎片，这个参数的作用就是当CMS收集器就是开启内存碎片合并，默认开始。合并的过程无法并发，停顿时间就会变长，会影响一定的性能。
④-XX:CMSFullGCsBeforeCompaction,用于设置执行多少次不压缩的FullGC，然后跟着来一次压缩的。
⑤-XX:ParallelCMSThreads=N,CMS默认启动的回收线程是(CPU数量+3)/4，如果不想默认就可以用它来设置。
⑥-XX:ParallelGCThreads= N,年轻代的并行收集线程数默认是(ncpus <= 8) ? ncpus : 3 + ((ncpus * 5) / 8),如果不想默认就可以用它来设置。
CMS日志解释
2018-04-18T19:24:06.946+0800: 433179.565: [GC [1 CMS-initial-mark: 816046K(1310720K)] 903563K(2018560K), 0.0997080 secs]
[Times: user=0.10 sys=0.00, real=0.10 secs]
初始标记阶段，老年代空间使用量816046K（老年代空间总量1310720K），整个堆使用量903563K（整个堆总量2018560K），耗时0.0997080秒。
2018-04-18T19:24:07.046+0800: 433179.665: [CMS-concurrent-mark-start]
开始并发标记
2018-04-18T19:24:07.300+0800: 433179.918: [CMS-concurrent-mark: 0.254/0.254 secs] [Times: user=1.89 sys=0.00, real=0.26 secs]
并发标记阶段结束，占用 0.254秒CPU时间, 0.254秒墙钟时间(也包含线程让出CPU给其他线程执行的时间)，用户耗时1.89秒，系统耗时0秒，实际耗时0.26秒。
2018-04-18T19:24:07.300+0800: 433179.919: [CMS-concurrent-preclean-start]
开始预清理阶段，预清理也是一个并发执行的阶段。在本阶段，会查找前一阶段执行过程中,从新生代晋升或新分配或被更新的对象。
通过并发地重新扫描这些对象，预清理阶段可以减少下一个stop-the-world 重新标记阶段的工作量。
2018-04-18T19:24:07.314+0800: 433179.932: [CMS-concurrent-preclean: 0.013/0.013 secs] [Times: user=0.03 sys=0.00, real=0.01 secs]
预清理阶段耗时，0.013秒CPU时间，0.013秒墙钟时间。用户耗时0.03秒，系统耗时0秒，实际耗时0.01秒。
2018-04-18T19:24:07.314+0800: 433179.932: [CMS-concurrent-abortable-preclean-start]
开始可中断的预处理，该阶段发生的前提是，新生代Eden区的内存使用量大于参数CMSScheduleRemarkEdenSizeThreshold 默认是2M，如果新生代的对象太少，
就没有必要执行该阶段，直接执行重新标记阶段。
2018-04-18T19:24:09.876+0800: 433182.494: [CMS-concurrent-abortable-preclean: 2.006/2.562 secs] [Times: user=7.38 sys=0.23, real=2.56 secs]
可中断的预处理耗时，2.006秒CPU时间，2.562秒墙钟时间。用户耗时7.38秒，系统耗时0.23秒，实际耗时2.56秒。
2018-04-18T19:24:09.877+0800: 433182.495: [GC[YG occupancy: 692704 K (707840 K)]
年轻代已使用692704K,年轻代中空间707840K。
2018-04-18T19:24:09.877+0800: 433182.495: [Rescan (parallel) ,0.4336470 secs]
重新标记,从根及被其引用对象开始，，parallel 表示多GC线程并行，重新扫描 CMS 堆中残留的更新过的对象耗时0.4336470秒。
2018-04-18T19:24:10.310+0800: 433182.929: [weak refs processing, 0.0042640 secs]
第一个子阶段，处理弱引用对象费时0.0042640秒，本阶段费时0.1897792 秒，。
2018-04-18T19:24:10.315+0800: 433182.933: [class unloading, 0.0233340 secs]
第二个子阶段(that is unloading the unused classes, with the duration and timestamp of the phase);
2018-04-18T19:24:10.338+0800: 433182.957: [scrub symbol table, 0.0194050 secs]
2018-04-18T19:24:10.358+0800: 433182.976: [scrub string table, 0.0028380 secs]
最后一个子阶段（that is cleaning up symbol and string tables which hold class-level metadata and internalized string respectively）
[1 CMS-remark: 977603K(1310720K)] 1670308K(2018560K), 0.4921040 secs] [Times: user=11.89 sys=0.00, real=0.49 secs]
重新标记后，老年代使用977603K(老年代总量1310720K),堆使用量1670308K(堆总量2018560K)，耗时0.4921040秒。用户耗时11.89秒，系统耗时0秒，实际耗时0.49秒。
2018-04-18T19:24:10.369+0800: 433182.988: [CMS-concurrent-sweep-start]
开始并发清除
2018-04-18T19:24:11.194+0800: 433183.813: [CMS-concurrent-sweep: 0.472/0.825 secs] [Times: user=5.27 sys=0.00, real=0.83 secs]
并发清除耗时 0.472秒CPU时间，0.825秒墙钟时间。用户耗时5.27秒，系统耗时0秒，实际耗时0.83秒。
2018-04-18T19:24:11.194+0800: 433183.813: [CMS-concurrent-reset-start]
开始并发重置，本阶段重新初始化CMS内部数据结构，以备下一轮 GC 使用。
2018-04-18T19:24:11.203+0800: 433183.822: [CMS-concurrent-reset: 0.009/0.009 secs] [Times: user=0.02 sys=0.00, real=0.01 secs]
并发重置耗时 0.009秒CPU时间，0.009秒墙钟时间。用户耗时0.02秒，系统耗时0秒，实际耗时0.01秒。
总结
通过本篇基本就可以看懂YoungGC和CMS的日志了，介绍了CMS收集器的步骤、缺点、VM参数。其实GC这一块涉及到的内容很多，比如判断对象死活、四种GC算法、八种回收器等，也是第一次实战。
可是，扯了半天犊子还是没说是什么导致的FullGC频发。在我司框架师的帮助下定位到了一个下载Excel的接口，是因为操作者要下载一个百万条记录的excel，但是写excel使用的是HSSFWorkbook，当记录数过大时，就会有内存溢出的问题。最后换成了SXSSFWorkbook，在自动刷新的模式下，可以指定窗口中访问Row的数量，从而在内存中保持一定数量的Row。当达到这一数量时，在窗口中产生新的Row数据，并将低索引的数据从窗口中移动到磁盘中。
网友评论