一、Parallel Scavenge垃圾回收
1.启动参数
java -Xms512M -Xmx512M -XX:+UseParallelGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps GCLogAnalysis
2.回收原理
为了更好的理解GCDetails信息回忆下新生代回收的算法(图出自网友)，此处不会对回收算法进行详细的讲解，也不会介绍ParallelGC的XX:MaxGCPauseMilli、XX:GCTimeRatio等参数。
image.png
3.GCDetails信息
[GC (Allocation Failure) [PSYoungGen: 131584K->21492K(153088K)] 131584K->49286K(502784K), 0.0100835 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [PSYoungGen: 153076K->21503K(153088K)] 180870K->90033K(502784K), 0.0127981 secs] [Times: user=0.03 sys=0.13, real=0.01 secs]
[GC (Allocation Failure) [PSYoungGen: 153087K->21497K(153088K)] 221617K->131023K(502784K), 0.0127866 secs] [Times: user=0.16 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [PSYoungGen: 153081K->21503K(153088K)] 262607K->169575K(502784K), 0.0118875 secs] [Times: user=0.16 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [PSYoungGen: 153087K->21496K(153088K)] 301159K->214212K(502784K), 0.0128921 secs] [Times: user=0.16 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [PSYoungGen: 153080K->21486K(80384K)] 345796K->258216K(430080K), 0.0131486 secs] [Times: user=0.16 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [PSYoungGen: 80366K->33168K(116736K)] 317096K->274856K(466432K), 0.0081034 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [PSYoungGen: 91526K->45353K(116736K)] 333214K->292344K(466432K), 0.0097777 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [PSYoungGen: 103918K->52105K(116736K)] 350909K->307825K(466432K), 0.0117969 secs] [Times: user=0.13 sys=0.03, real=0.01 secs]
[GC (Allocation Failure) [PSYoungGen: 110985K->39773K(116736K)] 366705K->328704K(466432K), 0.0137372 secs] [Times: user=0.11 sys=0.05, real=0.01 secs]
[GC (Allocation Failure) [PSYoungGen: 98610K->21903K(116736K)] 387541K->346984K(466432K), 0.0115041 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[Full GC (Ergonomics) [PSYoungGen: 21903K->0K(116736K)] [ParOldGen: 325080K->244597K(349696K)] 346984K->244597K(466432K), [Metaspace: 2618K->2618K(1056768K)], 0.0483094 secs] [Times: user=0.33 sys=0.00, real=0.05 secs]
[GC (Allocation Failure) [PSYoungGen: 58880K->17139K(116736K)] 303477K->261736K(466432K), 0.0044396 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [PSYoungGen: 75733K->18842K(116736K)] 320330K->278714K(466432K), 0.0076360 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [PSYoungGen: 77722K->23480K(116736K)] 337594K->301527K(466432K), 0.0085277 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[GC (Allocation Failure) [PSYoungGen: 81968K->20316K(116736K)] 360016K->319687K(466432K), 0.0082019 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
[Full GC (Ergonomics) [PSYoungGen: 20316K->0K(116736K)] [ParOldGen: 299370K->266741K(349696K)] 319687K->266741K(466432K), [Metaspace: 2618K->2618K(1056768K)], 0.0522455 secs] [Times: user=0.47 sys=0.00, real=0.05 secs]
4.分析
Parallel Scavenge是JDK8默认的新生代垃圾回收算法，是一种以吞吐量为目标的垃圾回收器，基于标记复制算法，内存分布为堆内存中划分了2块区域，一块为新生代，一块为老年代，默认配置新生代占堆内存1/3，老年代占堆内存2/3，新生代分为Eden，Survivor_To，Survivor_From，默认分配比例为8:1:1，Survivor区负责存储垃圾回收未能回收的对象和晋升到老年代的操作，从上面的GCDetails可以分析一下垃圾回收的大概原理。
以第一行为例，131584K为新生代回收前占用内存大小，21503K为新生代回收后占用内存大小，可以得知这一次GC回收了约110M，垃圾回收器使用Parallel Scavenge，131584K为整个堆内存回收前内存占用大小，42320K为整个堆内存这次GC后内存占用的大小，可以得知这一次GC回收了约89M内存，垃圾回收器使用Parallel Old，花费了大约8.3毫秒，那新生代回收内存与整个堆回收的内存大小差就是新生代晋升到老年代的内存大小，可以得知为21M。
以第二次GC为例，可以看到他触发了Full GC，原因很简单，就是老年代的空间不足，在这次GC中，新生代回收了16269K内存空间，OK代表新生代全部内存都已经回收，老年代回收了316390K-236940K内存空间，大约80M，整个堆内存回收了333077K-271355K内存空间，大约61M，可以得知新生代晋升80-61内存空间，约19M。
在过往的生产经验中只要JVM或者程序没有相关的告警，其实很少去调整启动参数，通过GC日志的学习与分析，我们发现堆内存的大小与系统的吞吐量还是有直接的关系，大家可以尝试使用不同的-Xms、-Xmx1参数来测试系统的吞吐量，我们会发现如果内存过小，会频繁的发生年轻代GC甚至会频发的一直发生Full GC或内存泄漏，其实内存离谱的大也会影响性能，老年代Full GC时STW（stop the word）的时间会比较久，所以一个合适的启动参数是在性能测试中必不可少的一环。
5.垃圾回收器选择参数
在新生代都是Parallel Scavenge回收器的时候，本来想测试一下配合不同的老年代算法来看一下性能，准备使用XX:+UseParallelGC、XX:+UseParallelOldGC，但是发现老年代回收算法一直都是ParOldGen，困惑了一段时间后通过搜索资料发现在JDK 7u4以后的7和JDK8，新生代算法为Parallel Scavenge，老年代默认都为Parallel Old。
6.一点疑问
上面的GC日志中，其中有两个括号，如第一行的（153088K）和（502784K）分别代表新生代分配的内存大小与堆内存分配的大小，但是我们发现这个大小并不是固定的，在七次乃至后面GC的时候括号内的大小发生了改变，这是为什么呢，其实JDK8 Parallel Scavenge默认开启了-XX:+UseAdaptiveSizePolicy参数，这个参数会根据吞吐量与垃圾回收的时间动态的调整各内存区域的大小，虽然有默认新生代的分配比例SurvivorRatio=8，但是也不会固定大小，如果在启动参数显示的写SurvivorRatio=8，则分配的内存不会动态调整，大家可以动手实验一下。
0.139: [GC (Allocation Failure) [PSYoungGen: 139776K->17399K(157184K)] 139776K->50737K(506880K), 0.0106199 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
0.169: [GC (Allocation Failure) [PSYoungGen: 157175K->17403K(157184K)] 190513K->97912K(506880K), 0.0123463 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
0.204: [GC (Allocation Failure) [PSYoungGen: 157179K->17392K(157184K)] 237688K->138599K(506880K), 0.0120867 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
0.235: [GC (Allocation Failure) [PSYoungGen: 157168K->17407K(157184K)] 278375K->186593K(506880K), 0.0136172 secs] [Times: user=0.08 sys=0.08, real=0.01 secs]
0.268: [GC (Allocation Failure) [PSYoungGen: 156865K->17403K(157184K)] 326051K->226716K(506880K), 0.0112440 secs] [Times: user=0.08 sys=0.08, real=0.01 secs]
0.302: [GC (Allocation Failure) [PSYoungGen: 157179K->17407K(157184K)] 366492K->269341K(506880K), 0.0118870 secs] [Times: user=0.09 sys=0.06, real=0.01 secs]
0.335: [GC (Allocation Failure) [PSYoungGen: 157183K->17397K(157184K)] 409117K->315974K(506880K), 0.0124720 secs] [Times: user=0.05 sys=0.11, real=0.01 secs]
0.366: [GC (Allocation Failure) [PSYoungGen: 157173K->17403K(157184K)] 455750K->365040K(506880K), 0.0122782 secs] [Times: user=0.05 sys=0.11, real=0.01 secs]
0.379: [Full GC (Ergonomics) [PSYoungGen: 17403K->0K(157184K)] [ParOldGen: 347637K->252454K(349696K)] 365040K->252454K(506880K), [Metaspace: 2610K->2610K(1056768K)], 0.0502988 secs] [Times: user=0.45 sys=0.00, real=0.05 secs]
0.449: [GC (Allocation Failure) [PSYoungGen: 139654K->17402K(157184K)] 392109K->301091K(506880K), 0.0089392 secs] [Times: user=0.16 sys=0.00, real=0.01 secs]
0.478: [GC (Allocation Failure) [PSYoungGen: 157127K->17393K(157184K)] 440816K->345873K(506880K), 0.0123442 secs] [Times: user=0.14 sys=0.00, real=0.01 secs]
0.490: [Full GC (Ergonomics) [PSYoungGen: 17393K->0K(157184K)] [ParOldGen: 328480K->285302K(349696K)] 345873K->285302K(506880K), [Metaspace: 2610K->2610K(1056768K)], 0.0530783 secs] [Times: user=0.45 sys=0.00, real=0.05 secs]
0.560: [GC (Allocation Failure) [PSYoungGen: 139413K->17388K(157184K)] 424715K->336474K(506880K), 0.0094297 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
0.570: [Full GC (Ergonomics) [PSYoungGen: 17388K->0K(157184K)] [ParOldGen: 319085K->298506K(349696K)] 336474K->298506K(506880K), [Metaspace: 2610K->2610K(1056768K)], 0.0542519 secs] [Times: user=0.63 sys=0.00, real=0.05 secs]
0.644: [Full GC (Ergonomics) [PSYoungGen: 139776K->0K(157184K)] [ParOldGen: 298506K->308783K(349696K)] 438282K->308783K(506880K), [Metaspace: 2610K->2610K(1056768K)], 0.0592678 secs] [Times: user=0.56 sys=0.01, real=0.06 secs]
0.721: [Full GC (Ergonomics) [PSYoungGen: 139776K->0K(157184K)] [ParOldGen: 308783K->317675K(349696K)] 448559K->317675K(506880K), [Metaspace: 2610K->2610K(1056768K)], 0.0555292 secs] [Times: user=0.45 sys=0.00, real=0.06 secs]
0.796: [Full GC (Ergonomics) [PSYoungGen: 139776K->0K(157184K)] [ParOldGen: 317675K->329497K(349696K)] 457451K->329497K(506880K), [Metaspace: 2610K->2610K(1056768K)], 0.0605840 secs] [Times: user=0.47 sys=0.00, real=0.06 secs]
0.878: [Full GC (Ergonomics) [PSYoungGen: 139776K->0K(157184K)] [ParOldGen: 329497K->338035K(349696K)] 469273K->338035K(506880K), [Metaspace: 2610K->2610K(1056768K)], 0.0630429 secs] [Times: user=0.58 sys=0.00, real=0.06 secs]
0.961: [Full GC (Ergonomics) [PSYoungGen: 139776K->0K(157184K)] [ParOldGen: 338035K->340230K(349696K)] 477811K->340230K(506880K), [Metaspace: 2610K->2610K(1056768K)], 0.0602097 secs] [Times: user=0.61 sys=0.00, real=0.06 secs]
1.043: [Full GC (Ergonomics) [PSYoungGen: 139776K->0K(157184K)] [ParOldGen: 340230K->339767K(349696K)] 480006K->339767K(506880K), [Metaspace: 2610K->2610K(1056768K)], 0.0639372 secs] [Times: user=0.50 sys=0.00, real=0.06 secs]
二、其他新生代垃圾回收
在JD8以前新生代垃圾回收除了Parallel Scavenge还有Serial和ParNew大家可以通过以下的指令进行测试，都基于标记复制算法，GC日志在新生代部分都是相同的分析方法。
java -Xms512M -Xmx512M -XX:+UseParNewGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps GCLogAnalysis
java -Xms512M -Xmx512M -XX:+UseSerialGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps GCLogAnalysis
三、老年代垃圾回收
1.启动参数
java -Xms512M -Xmx512M -XX:+UseParNewGC -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps GCLogAnalysis
2.回收原理
CMS作为一款老年代垃圾回收期，以减少垃圾回收的停顿时间为目标，采用标记清除算法，只能与新生代垃圾回收ParNew和Serial搭配使用，JDK9后只支持与ParNew配合使用，同样本部分不做详细的原理的说明，主要是分析GCDetails日志来加深理解，这部分有两个比较重要的概念，一个是三色标记法与读写屏障，一个是卡表结构，没有了解的可以参考这篇文章，感觉写的比较好理解。
3.GCDetails日志
0.137: [GC (Allocation Failure) 0.137: [ParNew: 139776K->17470K(157248K), 0.0091054 secs] 139776K->40713K(506816K), 0.0092111 secs] [Times: user=0.09 sys=0.06, real=0.01 secs]
0.170: [GC (Allocation Failure) 0.170: [ParNew: 157246K->17471K(157248K), 0.0142116 secs] 180489K->87941K(506816K), 0.0142434 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
0.205: [GC (Allocation Failure) 0.206: [ParNew: 157247K->17470K(157248K), 0.0259308 secs] 227717K->131524K(506816K), 0.0259642 secs] [Times: user=0.16 sys=0.00, real=0.03 secs]
0.253: [GC (Allocation Failure) 0.253: [ParNew: 157246K->17470K(157248K), 0.0260825 secs] 271300K->176029K(506816K), 0.0261210 secs] [Times: user=0.05 sys=0.05, real=0.03 secs]
0.301: [GC (Allocation Failure) 0.301: [ParNew: 156913K->17467K(157248K), 0.0264536 secs] 315471K->221267K(506816K), 0.0265076 secs] [Times: user=0.30 sys=0.02, real=0.03 secs]
-----------
0.328: [GC (CMS Initial Mark) [1 CMS-initial-mark: 203800K(349568K)] 224505K(506816K), 0.0004953 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.328: [CMS-concurrent-mark-start]
0.330: [CMS-concurrent-mark: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.330: [CMS-concurrent-preclean-start]
0.331: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.331: [CMS-concurrent-abortable-preclean-start]
0.351: [GC (Allocation Failure) 0.351: [ParNew: 157243K->17471K(157248K), 0.0247706 secs] 361043K->265332K(506816K), 0.0248061 secs] [Times: user=0.31 sys=0.00, real=0.02 secs]
0.396: [GC (Allocation Failure) 0.396: [ParNew: 157247K->17469K(157248K), 0.0273243 secs] 405108K->310389K(506816K), 0.0274060 secs] [Times: user=0.28 sys=0.03, real=0.03 secs]
0.443: [GC (Allocation Failure) 0.443: [ParNew: 157245K->17471K(157248K), 0.0245417 secs] 450165K->351522K(506816K), 0.0246113 secs] [Times: user=0.30 sys=0.02, real=0.02 secs]
0.467: [CMS-concurrent-abortable-preclean: 0.003/0.136 secs] [Times: user=0.94 sys=0.05, real=0.14 secs]
0.468: [GC (CMS Final Remark) [YG occupancy: 17759 K (157248 K)]0.468: [Rescan (parallel) , 0.0003444 secs]0.468: [weak refs processing, 0.0000089 secs]0.468: [class unloading, 0.0001881 secs]0.468: [scrub symbol table, 0.0003177 secs]0.469: [scrub string table, 0.0001022 secs][1 CMS-remark: 334051K(349568K)] 351810K(506816K), 0.0010110 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.469: [CMS-concurrent-sweep-start]
0.469: [CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
0.469: [CMS-concurrent-reset-start]
0.470: [CMS-concurrent-reset: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
-----------
0.490: [GC (Allocation Failure) 0.490: [ParNew: 157247K->17470K(157248K), 0.0121868 secs] 451196K->351647K(506816K), 0.0122208 secs] [Times: user=0.13 sys=0.00, real=0.01 secs]
4.分析
GC (Allocation Failure)是使用ParNew作为新生代的垃圾回收算法，此部分的内存情况与之前分析Parallel相似，所以这部分主要分析CMS老年代的垃圾回收原理。CMS垃圾回收日志其实与垃圾回收的阶段强相关，主要也是通过看日志来反向加强垃圾回收的流程与原理。
1）初始标记-CMS Initial Mark
CMS为了减少停顿时间大家可以记两段标记阶段都STW，剩下的阶段都并行，日志中时间0.328行可以得知一些信息，初始标记阶段老年代使用内存大小为203782K，整个老年代分配大小为349568K，整个堆内存使用内存为221541K，整个堆内存分配的大小为506816K，标记的时间也很短，从这里也能大概算出新生代分配的内存大小约为506816K-349568K=157M左右，与第一行的新生代内存分配大小一致。
2）并发标记-CMS-concurrent-mark，并发标记主要是根据初始标记来进行对象的可达性，日志中时间0.330行得知并行标记花费了0.01s；预清理-CMS-concurrent-preclean，预清理主要解决在并发标记的过程中业务线程对对象引用关系的修改（包括跨代引用和引用改变），主要是扫描标记为“脏块”的卡表，花费了0.01s；
3）可终止预清理-CMS-concurrent-abortable-preclean，该步骤不是一定执行，如果现在新生代内存小于CMSScheduleRemarkEdenSizeThreshold则不执行，如果大于该值继续标记（一直重复）的时候会有退出条件如循环次数、时间阈值、Eden区内存使用率等，在循环退出之前会进行一次YGC减轻后面最终标记的压力（因为老年代存在指向年轻代的指针），通过日志我们可以看出在0.331的可终止预清理阶段进行了三次YGC，从内存的情况上看 有大量对象从新生代晋升到老年代。
小疑问：在该部分我们观察时间指标是0.003/0.136 secs，0.003s是CPU执行的时间，0.136s是可终止预清理的总耗时，他们之间存在一个差值，这部分我其实也没有一个明确的答案，我第一感觉可能是在等待一次新生代GC。
3）最终标记-CMS Final Remark
从日志中时间0.468可以分析最终标记的结果，17759K新生代使用内存的大小，Rescan (parallel)为最后的标记SWT的时间，weak refs processing为清理弱引用的时间，class unloading为卸载未使用类的时间，scrub symbol table为清理符号表，我理解就是清理符号引用，scrub string table为清理字符表，我理解就是清理字面量，最终CMS的最终标记后老年代使用内存为334051K，堆内存使用为351810K。
4）并发清理-CMS-concurrent-sweep，很好理解就是并发清理；并发重置-CMS-concurrent-reset，重新调整CMS的内存结构，以便下次垃圾回收。
5.调优
在CMS中不是并发的垃圾回收一定成功，可能会发生失败，这样就会降级为Serial Old垃圾回收算法，为了避免这个可以考虑CMSInitiatingOccupancyFraction参数，默认92%
网友评论