大纲
1.TLAB的GC日志解读
2.YGC的GC日志解读
3.模拟YGC(单次GC及多次GC的不同场景)
4.打开实验选项查看YGC的详情日志信息
5.Mixed GC日志信息之初始标记过程
6.Mixed GC日志信息之混合回收过程
7.Mixed GC日志信息之Region的详细信息和标记过程的详细信息
8.FGC的日志信息及日志详情
1.TLAB的GC日志解读
(1)一套基本的参数设置
(2)针对这个参数设置写一套简单的Demo代码
(3)TLAB相关的运行日志
(1)一套基本的参数设置
首先参数上要有一套基本的设置：
-XX:InitialHeapSize=128M -XX:MaxHeapSize=128M -XX:+UseG1GC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTLAB -XX:+UnlockExperimentalVMOptions -XX:G1LogLevel=finest -XX:MaxGCPauseMillis=20 -Xloggc:gc.log堆内存的大小设置为128M是因为：G1本身的Region都要最小1M，总共就没有几个Region。如果设置成10MB这种值，不好做实验。
-XX:+UnlockExperimentalVMOptions这个参数是一个实验选项，打开以后才可以使用-XX:G1LogLevel这个参数，-XX:G1LogLevel=finest表示设置日志的输出级别为最详细级别。
(2)针对这个参数设置写一套简单的Demo代码
public class TLABDemo { private static final ArrayList<String> strs = new ArrayList<String>(); public static void main(String[] args) throws Exception { for (int n = 0 ;; n++) { //外层循环100次，每次内层循环创建10个字符串 for (int i = 0; i<100; i++) { //内层循环10次 for (int j = 0; j < 10; j++) { strs.add(new String("NO." + j + "Str" )); } } //无限循环，每次循环间隔0.1s System.out.println("第" + n + "次循环"); Thread.sleep(100); } } }这段代码的意思是：无限循环去创建字符串，放到一个list去。每次循环会执行1000次创建字符串，并把字符串加入到list的操作。通过这段代码，看看TLAB相关的GC日志信息。
(3)TLAB相关的运行日志
//这一部分是我们设置的一些参数信息 CommandLine flags: -XX:G1LogLevel=finest -XX:InitialHeapSize=134217728 -XX:MaxGCPauseMillis=20 -XX:MaxHeapSize=134217728 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTLAB -XX:+UnlockExperimentalVMOptions -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation 2.236: [GC pause (G1 Evacuation Pause) (young) TLAB: gc thread: 0x00000000181fd800 [id: 8648] desired_size: 122KB slow allocs: 0 refill waste: 1960B alloc: 0.99996 6144KB refills: 1 waste 1.4% gc: 1704B slow: 0B fast: 0B TLAB: gc thread: 0x00000000181fa000 [id: 3280] desired_size: 122KB slow allocs: 2 refill waste: 1960B alloc: 0.99996 6144KB refills: 3 waste 25.0% gc: 91168B slow: 3104B fast: 0B TLAB: gc thread: 0x00000000181bb000 [id: 10280] desired_size: 122KB slow allocs: 2 refill waste: 1960B alloc: 0.99996 6144KB refills: 7 waste 2.0% gc: 13992B slow: 3624B fast: 0B TLAB: gc thread: 0x0000000003683800 [id: 12164] desired_size: 122KB slow allocs: 6 refill waste: 1960B alloc: 0.99996 6144KB refills: 41 waste 0.1% gc: 0B slow: 7584B fast: 0B TLAB totals: thrds: 4 refills: 52 max: 41 slow allocs: 10 max 6 waste: 1.9% gc: 106864B max: 91168B slow: 14312B max: 7584B fast: 0B max: 0B, 0.0025449 secs] //这一部分是我们设置的一些参数信息 CommandLine flags: -XX:G1LogLevel=finest -XX:InitialHeapSize=134217728 -XX:MaxGCPauseMillis=20 -XX:MaxHeapSize=134217728 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTLAB -XX:+UnlockExperimentalVMOptions -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation //下面的GC pause，就是我们的停顿时间，后面跟的young指的是新生代 2.236: [GC pause (G1 Evacuation Pause) (young) //TLAB后跟的这一大段，其中有几个关键点需要我们注意 TLAB: gc thread: 0x00000000181fd800 [id: 8648] desired_size: 122KB slow allocs: 0 refill waste: 1960B alloc: 0.99996 6144KB refills: 1 waste 1.4% gc: 1704B slow: 0B fast: 0Bgc thread：表示是哪个线程的TLAB。
desired_size：122KB指的是期望分配的TLAB的大小。这个值，其实就是我们前面讲解TLAB计算公式的时候，计算出来的值。TLABSize = Eden * 2 * 1% / 线程个数。
slow allocs：0，指的是慢速分配的次数。0说明每次都使用了TLAB快速分配，没有直接使用堆内存去分配。注意慢速TLAB分配也算是快速分配。
refill waste：1960B，代表可浪费的内存，也是重新申请一个TLAB的阈值。
alloc: 0.99996，表示当前这个线程在一个分区中分配对象占用的比例，Region使用的比例。
refills: 1，代表出现多少次废弃TLAB，重新申请一个TLAB的次数。refills次数为1表示只做了一次TLAB申请。每次废弃TLAB时，都会填充一个dummy对象。注意：refills的次数就是填充TLAB的次数，可理解为申请新的TLAB的次数。
waste 1.4% gc: 1704B slow: 0B fast: 0B，waste代表的是浪费的空间，这个浪费的空间分为三个层面：
一.gc表示：GC时还没有使用的TLAB的空间，现在正处于GC的状态中，TLAB还剩下多少空间没使用。
二.slow表示：申请新的TLAB时，旧的TLAB浪费的空间。这里就是0B，因为只产生了1次。
三.fast表示：在出现需要调整TLAB的大小时，即refill_waste不合理时，旧的TLAB浪费的空间，也就是dummy对象造成的浪费。
2.236: [GC pause (G1 Evacuation Pause) (young)TLAB: gc thread: 0x00000000181fd800 [id: 8648] desired_size: 122KB slow allocs: 0 refill waste: 1960B alloc: 0.99996 6144KB refills: 1 waste 1.4% gc: 1704B slow: 0B fast: 0B 观察这个TLAB状态，refill次数还是非常有用的。refill次数可以帮助我们调整TLAB相关参数的设置，有助于优化性能。
比如，经过压测通过GC日志发现：当TLAB的大小设置成 1/4 RegionSize时会出现更少的TLAB动态调整情况，并且这个值能够保证大多数对象能够直接走TLAB分配。那么就可手动设置TLAB的大小，不使用G1自动推断的值，避免动态调整。因为自动调整是需要代价的，每次自动调整都会有一定的性能损耗。
2.YGC的GC日志解读
(1)参数设置
(2)沿用简单的Demo代码
(3)代码及YGC时机分析
(4)YGC相关的运行日志
(1)参数设置
对于YGC来说，我们只是要模拟YGC的整个过程。并且要打印出YGC整个过程的一些GC细节，所以才设置这么一套参数：
-Xmx256M -XX:+UseG1GC -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:MaxGCPauseMillis=20 -Xloggc:gc.log(2)沿用简单的Demo代码
public class TLABDemo { private static final ArrayList<String> strs = new ArrayList<String>(); public static void main(String[] args) throws Exception { for (int n = 0 ;; n++) { //外层循环100次，每次内层循环创建10个字符串 for (int i = 0; i<100; i++) { //内层循环10次 for (int j = 0; j < 10; j++) { strs.add(new String("NO." + j + "Str" )); } } //无限循环，每次循环间隔0.1s System.out.println("第" + n + "次循环"); Thread.sleep(100); } } }(3)代码及YGC时机分析
首先，运行这个代码时，没有设置新生代占用多少空间就会发生YGC，所以具体什么时候会发生YGC暂时不确定。
不过可以简单的思考YGC的发生时机，尤其是第一次。第一次发生YGC时，应该是256M * 5%的新生代被使用的时候。大概是这个值，当然，实际可能会比这个值略小一点。因为新生代第一次GC时Survivor区是没有存活对象的，并且堆内存会有一部分被其他的一些描述信息占用，所以256M堆内存不会全部都用来分配对象。程序运行一段时间后：大量字符串对象会填满Eden区，此时就会触发一次YGC。
(4)YGC相关的运行日志
可以看到，G1的GC日志看起来非常复杂，中间有非常复杂的处理步骤。比如，roots扫描，RS扫描等操作。每一步的操作都会有各自的耗时时长。接下来一步一步分析这个日志。
//这一部分是我们设置的一些参数信息 CommandLine flags: -XX:InitialHeapSize=266064256 -XX:MaxGCPauseMillis=20 -XX:MaxHeapSize=268435456 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation //从这里开始，出现了第一次GC，大概是在程序启动6.193s之后，停顿时间是0.0048641秒，也就是4.8ms左右； 6.193: [GC pause (G1 Evacuation Pause) (young), 0.0048641 secs] //这里很明显看到GC线程并行工作的时间是2.9ms，并且使用了8个GCWorkers线程； //因为此时电脑是8核的，不同的电脑，会有不同的结果，因为没有设置GC的GCParallelThreads线程数量的值； [Parallel Time: 2.9 ms, GC Workers: 8] //这些是线程启动，GC Roots扫描，RSet扫描，对象拷贝等操作的一些耗时情况； [GC Worker Start (ms): Min: 6192.9, Avg: 6193.1, Max: 6193.6, Diff: 0.7] [Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 1.7] [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1] [Object Copy (ms): Min: 1.9, Avg: 2.2, Max: 2.3, Diff: 0.4, Sum: 17.8] [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1] [Termination Attempts: Min: 16, Avg: 20.3, Max: 24, Diff: 8, Sum: 162] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.0, Sum: 0.3] [GC Worker Total (ms): Min: 1.9, Avg: 2.5, Max: 2.6, Diff: 0.7, Sum: 19.9] [GC Worker End (ms): Min: 6195.5, Avg: 6195.5, Max: 6195.6, Diff: 0.0] [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.9 ms] [Other: 1.0 ms] [Choose CSet: 0.0 ms] [Ref Proc: 0.5 ms] [Ref Enq: 0.0 ms] //卡表更新 [Redirty Cards: 0.5 ms] //大对象相关的操作时间 [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.0 ms] //在第一次GC之后，Eden区从使用12M，到使用0M，从总大小12M，到总大小10M，发生了动态变化； //Survivor区从0变为了2048K，也就是本次GC之后有2048K的对象存活下来； //堆内存从12M的使用量，降为了4424K的使用量，说明本次回收的效果还是不错的，基本上回收了百分之九十以上的垃圾； [Eden: 12.0M(12.0M)->0.0B(10.0M) Survivors: 0.0B->2048.0K Heap: 12.0M(254.0M)->4424.0K(254.0M)] [Times: user=0.00 sys=0.00, real=0.01 secs] //第二次GC发生的时机，对于第二次GC，着重关注一下Eden Survivor 的大小，看看它是否有变化； 17.261: [GC pause (G1 Evacuation Pause) (young), 0.0087213 secs] [Parallel Time: 7.7 ms, GC Workers: 8] [GC Worker Start (ms): Min: 17261.5, Avg: 17261.5, Max: 17261.6, Diff: 0.2] [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.3, Diff: 0.3, Sum: 1.0] [Update RS (ms): Min: 0.0, Avg: 1.0, Max: 2.9, Diff: 2.9, Sum: 7.8] [Processed Buffers: Min: 0, Avg: 1.3, Max: 3, Diff: 3, Sum: 10] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1] [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1] [Object Copy (ms): Min: 4.6, Avg: 6.5, Max: 7.5, Diff: 2.9, Sum: 51.8] [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3] [Termination Attempts: Min: 1, Avg: 2.6, Max: 5, Diff: 4, Sum: 21] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [GC Worker Total (ms): Min: 7.5, Avg: 7.6, Max: 7.7, Diff: 0.1, Sum: 61.1] [GC Worker End (ms): Min: 17269.1, Avg: 17269.1, Max: 17269.1, Diff: 0.0] [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.3 ms] [Other: 0.7 ms] [Choose CSet: 0.0 ms] [Ref Proc: 0.5 ms] [Ref Enq: 0.0 ms] [Redirty Cards: 0.1 ms] [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.0 ms] //从这里并没有发现新生代的变化，说明此时还没有进行新生代的调整； //但是有一个现象，新生代使用从10MB降为了2048K，而堆内存，从14.9降为了12.9； //也就是说，本次只回收了2M左右的对象，那么肯定是有一部分对象进入了老年代分区的； [Eden: 10.0M(10.0M)->0.0B(10.0M) Survivors: 2048.0K->2048.0K Heap: 14.9M(254.0M)->12.9M(254.0M)] [Times: user=0.09 sys=0.02, real=0.01 secs] 38.020: [GC pause (G1 Evacuation Pause) (young), 0.0101857 secs] [Parallel Time: 8.9 ms, GC Workers: 8] [GC Worker Start (ms): Min: 38019.9, Avg: 38020.0, Max: 38020.1, Diff: 0.1] [Ext Root Scanning (ms): Min: 0.1, Avg: 0.3, Max: 1.3, Diff: 1.2, Sum: 2.2] [Update RS (ms): Min: 0.0, Avg: 1.4, Max: 1.7, Diff: 1.7, Sum: 10.8] [Processed Buffers: Min: 0, Avg: 1.9, Max: 3, Diff: 3, Sum: 15] [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.5, Diff: 0.5, Sum: 0.7] [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Object Copy (ms): Min: 6.9, Avg: 7.0, Max: 7.1, Diff: 0.2, Sum: 56.4] [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Termination Attempts: Min: 1, Avg: 28.9, Max: 43, Diff: 42, Sum: 231] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1] [GC Worker Total (ms): Min: 8.7, Avg: 8.8, Max: 8.8, Diff: 0.1, Sum: 70.3] [GC Worker End (ms): Min: 38028.7, Avg: 38028.7, Max: 38028.7, Diff: 0.0] [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.3 ms] [Other: 1.0 ms] [Choose CSet: 0.0 ms] [Ref Proc: 0.1 ms] [Ref Enq: 0.0 ms] [Redirty Cards: 0.7 ms] [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.0 ms] [Eden: 10.0M(10.0M)->0.0B(10.0M) Survivors: 2048.0K->2048.0K Heap: 25.2M(254.0M)->27.9M(254.0M)] [Times: user=0.00 sys=0.00, real=0.01 secs] 58.728: [GC pause (G1 Evacuation Pause) (young), 0.0103349 secs] [Parallel Time: 8.3 ms, GC Workers: 8] [GC Worker Start (ms): Min: 58727.8, Avg: 58727.9, Max: 58728.0, Diff: 0.2] [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.8] [Update RS (ms): Min: 0.7, Avg: 1.0, Max: 1.5, Diff: 0.8, Sum: 8.3] [Processed Buffers: Min: 1, Avg: 1.5, Max: 2, Diff: 1, Sum: 12] [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.7] [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Object Copy (ms): Min: 6.3, Avg: 6.7, Max: 6.9, Diff: 0.6, Sum: 53.7] [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Termination Attempts: Min: 1, Avg: 11.6, Max: 19, Diff: 18, Sum: 93] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1] [GC Worker Total (ms): Min: 7.8, Avg: 8.0, Max: 8.0, Diff: 0.2, Sum: 63.6] [GC Worker End (ms): Min: 58735.8, Avg: 58735.8, Max: 58735.8, Diff: 0.0] [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.7 ms] [Other: 1.2 ms] [Choose CSet: 0.0 ms] [Ref Proc: 0.5 ms] [Ref Enq: 0.0 ms] [Redirty Cards: 0.7 ms] [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.0 ms] [Eden: 10.0M(10.0M)->0.0B(10.0M) Survivors: 2048.0K->2048.0K Heap: 40.0M(254.0M)->42.0M(254.0M)] [Times: user=0.00 sys=0.00, real=0.01 secs]从多次GC的结果来看，新生代GC的情况相对比较稳定，每次的时长都在1ms左右(除了第一次时间比较长)，并且由于我们的代码是没有对象置为null的操作的，所以基本上所有的对象都能存活下来晋升到老年代。
3.模拟YGC(单次GC及多次GC的不同场景)
(1)参数设置
(2)模拟代码
(3)代码运行相关的GC日志
(4)接下来把代码改造一下
(5)观察GC日志
(1)参数设置
还是这么一套参数结构，主要是为了和前面做一些对比，看看模拟出来的GC场景是否符合前面对日志的解读。
-Xmx256M -XX:+UseG1GC -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:MaxGCPauseMillis=20 -Xloggc:gc.log(2)模拟代码
public class YGCDemo1 { //5% * 256 = 12M左右是第一次发生YGC的时机 //因为堆内存256M / 2048小于1，根据G1的处理，会把一个Region定为1M public static void main(String[] args) throws Exception { //设定一个对象为256K的原因，如果太大，会直接走大对象分配无法模拟YGC byte[] data = new byte[1024 * 256]; for (int i = 0; i< 36; i++) { data = new byte[1024 * 256]; } data = new byte[1024 * 256]; } }下面来解析一下代码：
一.首先第一段创建了一个data字节数组，大小是1024 * 256 = 256K
因为对象如果超过了Region大小一半，是一定会被当作大对象单独存储的，所以需要把这个对象的大小设置得合理一点。
而对于设置的这一套参数，堆内存是256M。通过计算不难发现，Region的大小是1M。因为256 / 2048很显然小于1M，然后会自动调整，调整成1M大小。代码中创建的对象设置成256K，就能正常分配到新生代Region中。
二.然后使用了一个循环，在循环中不断去创建新的数组
并且循环的次数设置在了36，为什么设置成36呢？原因是：G1启动时会初始化新生代的大小。新生代的大小占总空间的5%，也就是256M * 5% 约等于12M。也就是说，当应用程序用掉12个Region左右时，就会触发第一次YGC。
三.在触发了YGC之后
此时data这个变量还在，所以还是会有一个256K的字节数组存活，加上一些堆内存中存在的一些未知对象也可能会存活。那么在第一次回收后，应该会有不到1M的对象存活下来进入Survivor区域。
(3)代码运行相关的GC日志
//这些是我们设置的启动参数，其中需要注意的是，最大停顿时间，和堆内存的大小； CommandLine flags: -XX:InitialHeapSize=266064256 -XX:MaxGCPauseMillis=20 -XX:MaxHeapSize=268435456 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation //接下来看这里的内容，GC线程还是8个，本次GC造成的停顿时间是0.00178，很明显是在20ms内的； 0.155: [GC pause (G1 Evacuation Pause) (young), 0.0017840 secs] [Parallel Time: 1.1 ms, GC Workers: 8] //这一段日志，可以看出来，在GC前，Eden区使用了12MB的内存，也就是12个Region； //在本次GC之后，Survivor从GC开始前的0使用量，到了2048K，也就是Survivor使用了2个Region //注意，这里不是说S区就有这么多的对象，而是S区总共使用了2个Region； //堆内存的使用，从12M最后变为了1120K，大概1M左右 [Eden: 12.0M(12.0M)->0.0B(10.0M) Survivors: 0.0B->2048.0K Heap: 12.0M(254.0M)->1120.0K(254.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] //堆内存的最终使用状态是这样的，总共256MB，使用了3MB左右，region size是1MB，5个region给了新生代，两个region给了survivor Heap garbage-first heap total 260096K, used 3168K [0x00000000f0000000, 0x00000000f01007f0, 0x0000000100000000) region size 1024K, 5 young (5120K), 2 survivors (2048K) Metaspace used 3451K, capacity 4496K, committed 4864K, reserved 1056768K class space used 376K, capacity 388K, committed 512K, reserved 1048576K (4)接下来把代码改造一下
public class YGCDemo1 { private static final ArrayList<String> strs = new ArrayList<String>(); //5% * 256 = 12M左右 //因为256M / 2048小于1 ，根据G1的处理，会把一个Region定为1M； public static void main(String[] args) throws Exception { //设定一个对象为256K，如果太大，会直接走大对象分配无法模拟YGC byte[] data = new byte[1024 * 256]; for (int i = 0; i< 36; i++) { data = new byte[1024 * 256]; } //创建n个对象，加入到一个list中，不回收这些数组； ArrayList list = new ArrayList(); for (int i = 0; i<= 36; i++) { byte[] data2 = new byte[1024 * 256]; //一部分字节数组加入到list中 if (i % 3 == 0) { list.add(data2); } } } }这段代码可以触发2次YGC，因为代码中会保留一些存活对象，所以第二次GC时，Region的使用情况会发生一些变化。
//创建n个对象，加入到一个list中，不回收这些数组； ArrayList list = new ArrayList(); for (int i = 0; i<= 36; i++) { byte[] data2 = new byte[1024 * 256]; //一部分字节数组加入到list中 if (i % 3 == 0) { list.add(data2); } }上面就是代码的变化位置，我们加了一个循环，并且每3个数组会有一个数组加入到list中不会被回收。
(5)观察GC日志
CommandLine flags: -XX:InitialHeapSize=266064256 -XX:MaxGCPauseMillis=20 -XX:MaxHeapSize=268435456 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation 0.150: [GC pause (G1 Evacuation Pause) (young), 0.0018467 secs] [Parallel Time: 1.1 ms, GC Workers: 8] [GC Worker Start (ms): Min: 149.9, Avg: 150.1, Max: 150.9, Diff: 0.9] [Ext Root Scanning (ms): Min: 0.0, Avg: 0.2, Max: 0.4, Diff: 0.4, Sum: 1.7] [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Object Copy (ms): Min: 0.0, Avg: 0.5, Max: 0.6, Diff: 0.6, Sum: 3.9] [Termination (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.5] [Termination Attempts: Min: 1, Avg: 7.4, Max: 12, Diff: 11, Sum: 59] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3] [GC Worker Total (ms): Min: 0.0, Avg: 0.8, Max: 1.0, Diff: 0.9, Sum: 6.4] [GC Worker End (ms): Min: 150.9, Avg: 150.9, Max: 150.9, Diff: 0.0] [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.2 ms] [Other: 0.5 ms] [Choose CSet: 0.0 ms] [Ref Proc: 0.2 ms] [Ref Enq: 0.0 ms] [Redirty Cards: 0.2 ms] [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.0 ms] [Eden: 12.0M(12.0M)->0.0B(10.0M) Survivors: 0.0B->2048.0K Heap: 12.0M(254.0M)->1120.0K(254.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] 0.153: [GC pause (G1 Evacuation Pause) (young), 0.0014333 secs] [Parallel Time: 1.0 ms, GC Workers: 8] [GC Worker Start (ms): Min: 152.9, Avg: 152.9, Max: 153.2, Diff: 0.3] [Ext Root Scanning (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.1] [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Processed Buffers: Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0] [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Object Copy (ms): Min: 0.5, Avg: 0.6, Max: 0.7, Diff: 0.1, Sum: 5.1] [Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1] [Termination Attempts: Min: 1, Avg: 1.9, Max: 4, Diff: 3, Sum: 15] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [GC Worker Total (ms): Min: 0.6, Avg: 0.8, Max: 0.9, Diff: 0.3, Sum: 6.4] [GC Worker End (ms): Min: 153.7, Avg: 153.7, Max: 153.7, Diff: 0.0] [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.1 ms] [Other: 0.3 ms] [Choose CSet: 0.0 ms] [Ref Proc: 0.2 ms] [Ref Enq: 0.0 ms] [Redirty Cards: 0.1 ms] [Humongous Register: 0.0 ms] [Humongous Reclaim: 0.0 ms] [Free CSet: 0.0 ms] [Eden: 10.0M(10.0M)->0.0B(10.0M) Survivors: 2048.0K->2048.0K Heap: 11.1M(254.0M)->3666.5K(254.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] Heap garbage-first heap total 260096K, used 7762K [0x00000000f0000000, 0x00000000f01007f0, 0x0000000100000000) region size 1024K, 7 young (7168K), 2 survivors (2048K) Metaspace used 3451K, capacity 4496K, committed 4864K, reserved 1056768K class space used 376K, capacity 388K, committed 512K, reserved 1048576K 很明显是发生了两次GC的，并且两次GC之后Eden区的Region数量并没有发生变化。
4.打开实验选项查看YGC的详情日志信息
(1)参数设置
(2)模拟代码
(3)代码运行相关的GC日志
(4)问题
(1)参数设置
具体参数如下：
-Xmx256M -XX:+UseG1GC -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:+UnlockExperimentalVMOptions -XX:G1LogLevel=finest -XX:MaxGCPauseMillis=20 -Xloggc:gc.log在参数上没有什么特别的变化，主要是添加了两个参数。一个是开启实验选项，用于设置日志的输出级别，日志的输出级别设置为-XX:G1LogLevel=finest
(2)模拟代码
public class YGCDemo1FinestLog { //5% * 256 = 12M左右 //因为256M / 2048小于1 ，根据G1的处理，会把一个Region定为1M public static void main(String[] args) throws Exception{ //设定一个对象为256K，如果太大，会直接走大对象分配无法模拟YGC byte[] data = new byte[1024 * 256]; for (int i = 0; i< 36; i++) { data = new byte[1024 * 256]; } //创建n个对象，加入到一个list中，不回收这些数组 ArrayList list = new ArrayList(); for (int i = 0; i<= 36; i++) { byte[] data2 = new byte[1024 * 256]; //一部分字节数组加入到list中 if (i % 3 == 0) { list.add(data2); byte[] bigData1 = new byte[1024 * 512]; byte[] bigData2 = new byte[1024 * 1024]; } //随机某次，我们把list直接清空掉，最终可能会留下一些存活对象 //这块儿主要是模拟程序正常运行过程中对象可能会被回收 if (i % Math.random() * 10 == 0) { list.clear(); } } } }接下来解析一下代码：
一.首先第一段创建了一个data字节数组，大小是1024 * 256 = 256K
因为对象如果超过了Region大小，是一定会被当作大对象单独存储的，所以要把这个对象的大小设置的合理一点。而对于我们设置的这一套参数，堆内存是256M。通过计算不难发现，Region的大小是1M。因为256M/ 2048很显然小于1M，然后会自动调整，调整成1M大小。那么将对象设置成256K大小，就能正常分配到新生代Region中。
二.然后使用了一个循环，在循环中不断去创建新的数组
并且循环的次数设置在了36，为什么设置成36呢？原因是，在G1启动时会初始化新生代的大小。新生代的大小占总空间的5%，也就是256M * 5% 约等于12M。也就是说，当程序用掉了12个Region时，就会触发第一次YGC。
三.在触发了YGC之后
此时data这个变量还在，所以还是会有一个256K的字节数组存活。加上一些堆内存中存在的一些未知对象也可能会存活，那么在第一次回收后，应该会有不到1M的对象存活下来进入Survivor区域。
四.保留一些存活对象到list中
//创建n个对象，加入到一个list中，不回收这些数组 ArrayList list = new ArrayList(); for (int i = 0; i<= 36; i++) { byte[] data2 = new byte[1024 * 256]; //一部分字节数组加入到list中 if (i % 3 == 0) { list.add(data2); byte[] bigData1 = new byte[1024 * 512]; byte[] bigData2 = new byte[1024 * 1024]; } ... }代码运行中，这个地方会模拟出每3次执行就放一点存活对象到数组中。
五.紧接着，随机清理一下list，模拟每次运行垃圾和存活对象不定的情况
(3)代码运行相关的GC日志
//这些内容是我们设置的启动参数，其中需要注意的是，最大停顿时间，和堆内存的大小； CommandLine flags: -XX:G1LogLevel=finest -XX:InitialHeapSize=266064256 -XX:MaxGCPauseMillis=20 -XX:MaxHeapSize=268435456 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UnlockExperimentalVMOptions -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation //接下来看这里的内容，GC线程还是8个，本次GC造成的停顿时间是0.00178，很明显是在20ms内的； 0.189: [GC pause (G1 Evacuation Pause) (young), 0.0020256 secs] [Parallel Time: 1.4 ms, GC Workers: 8] //注意，下面这一行信息是说我们这8个线程开始的时间，min表示最早开始的线程时间，avg表示平均开始时间，max表示最晚开始时间，diff表示最早和最晚的时间差，这个diff越大就说明线程启动时间越不均衡，一般这个地方的时间不会差别很大； [GC Worker Start (ms): 188.7 188.7 188.7 188.7 188.8 188.8 188.8 188.8 Min: 188.7, Avg: 188.7, Max: 188.8, Diff: 0.1] //8个线程对根(GC Roots)扫描处理的时间，可以注意到，根的类型非常多。除了经常说的Java静态变量、方法局部变量外还有很多其他的一些根 [Ext Root Scanning (ms): 0.3 1.2 0.2 0.0 0.2 0.2 0.2 0.2 Min: 0.0, Avg: 0.3, Max: 1.2, Diff: 1.2, Sum: 2.5] [Thread Roots (ms): 0.0 1.2 0.1 0.0 0.0 0.0 0.1 0.0 Min: 0.0, Avg: 0.2, Max: 1.2, Diff: 1.2, Sum: 1.5] [StringTable Roots (ms): 0.0 0.0 0.1 0.0 0.1 0.1 0.1 0.2 Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.6] [Universe Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [JNI Handles Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [ObjectSynchronizer Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [FlatProfiler Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Management Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [SystemDictionary Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [CLDG Roots (ms): 0.3 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.3, Diff: 0.3, Sum: 0.3] [JVMTI Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [CodeCache Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [CM RefProcessor Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Wait For Strong CLD (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Weak CLD Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [SATB Filtering (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] //更新RSet的操作，前面提过要先更新RSet后，再进行RSet的扫描，其实在这个日志里就能看的出来； //对象引用关系更新之后，要通过Refine线程 + 系统程序的线程 + DCQ更新RSet //下面显示的是GC线程时间都为0.0，说明这块更新没问题 //因为引用更新导致RSet更新的这些操作，都已经由Refine线程提前处理完了； [Update RS (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Processed Buffers: 0 0 0 0 0 0 0 0 Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0] //扫描RSet，处理存活对象； [Scan RS (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Code Root Scanning (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] //这一步很关键，对象拷贝，就是把存活对象拷贝到一个新的分区，可以看出来，拷贝消耗的时间非常长； //注意：对象拷贝消耗的时间占了GC绝大部分的时间 [Object Copy (ms): 0.5 0.0 0.6 0.0 0.7 0.6 0.6 0.6 Min: 0.0, Avg: 0.5, Max: 0.7, Diff: 0.7, Sum: 3.8] //GC线程关闭的一些信息 [Termination (ms): 0.4 0.0 0.4 0.4 0.4 0.4 0.4 0.4 Min: 0.0, Avg: 0.4, Max: 0.4, Diff: 0.4, Sum: 2.8] [Termination Attempts: 3 1 12 1 16 9 11 9 Min: 1, Avg: 7.8, Max: 16, Diff: 15, Sum: 62] //GC线程的一些其他工作的处理时间，通常是JVM析构释放资源 [GC Worker Other (ms): 0.0 0.1 0.1 0.9 0.1 0.1 0.0 0.0 Min: 0.0, Avg: 0.2, Max: 0.9, Diff: 0.9, Sum: 1.3] //并行GC过程花费的总体时间； [GC Worker Total (ms): 1.3 1.3 1.3 1.3 1.3 1.3 1.3 1.3 Min: 1.3, Avg: 1.3, Max: 1.3, Diff: 0.1, Sum: 10.4] [GC Worker End (ms): 190.0 190.0 190.0 190.1 190.0 190.1 190.0 190.1 Min: 190.0, Avg: 190.0, Max: 190.1, Diff: 0.0] [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] //清理卡表 [Clear CT: 0.2 ms] [Other: 0.5 ms] //选择Cset时间，对YGC来说，一般都是0，因为不需要选 [Choose CSet: 0.0 ms] [Ref Proc: 0.2 ms] [Ref Enq: 0.0 ms] //重构RSet花费的时间 [Redirty Cards: 0.2 ms] [Parallel Redirty: 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Redirtied Cards: 0 0 0 0 0 0 0 0 Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0] //大对象的处理时间 [Humongous Register: 0.0 ms] [Humongous Total: 0] [Humongous Candidate: 0] //如果大对象要回收，回收花费的时间以及回收了多少个大对象 [Humongous Reclaim: 0.0 ms] [Humongous Reclaimed: 0] //释放CSet中的分区花费的时间 [Free CSet: 0.0 ms] [Young Free CSet: 0.0 ms] [Non-Young Free CSet: 0.0 ms] //本次回收之后，Eden区和Survivor区的状态 [Eden: 12.0M(12.0M)->0.0B(10.0M) Survivors: 0.0B->2048.0K Heap: 12.0M(254.0M)->1120.0K(254.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] 0.199: [GC pause (G1 Evacuation Pause) (young), 0.0015365 secs] [Parallel Time: 1.0 ms, GC Workers: 8] [GC Worker Start (ms): 199.4 199.4 199.4 199.4 199.9 199.9 199.9 200.3 Min: 199.4, Avg: 199.7, Max: 200.3, Diff: 0.9] [Ext Root Scanning (ms): 0.2 0.2 0.2 0.2 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.7] [Thread Roots (ms): 0.0 0.1 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1] [StringTable Roots (ms): 0.0 0.1 0.2 0.1 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.4] [Universe Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [JNI Handles Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [ObjectSynchronizer Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [FlatProfiler Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Management Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [SystemDictionary Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [CLDG Roots (ms): 0.2 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.2, Sum: 0.2] [JVMTI Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [CodeCache Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [CM RefProcessor Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Wait For Strong CLD (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Weak CLD Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [SATB Filtering (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Update RS (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Processed Buffers: 0 0 0 0 0 0 0 0 Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0] [Scan RS (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Code Root Scanning (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Object Copy (ms): 0.6 0.7 0.7 0.7 0.4 0.4 0.3 0.0 Min: 0.0, Avg: 0.5, Max: 0.7, Diff: 0.7, Sum: 3.7] [Termination (ms): 0.1 0.0 0.1 0.1 0.1 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.4] [Termination Attempts: 1 1 5 1 4 1 1 1 Min: 1, Avg: 1.9, Max: 5, Diff: 4, Sum: 15] [GC Worker Other (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [GC Worker Total (ms): 0.9 0.9 0.9 0.9 0.4 0.4 0.4 0.0 Min: 0.0, Avg: 0.6, Max: 0.9, Diff: 0.9, Sum: 4.9] [GC Worker End (ms): 200.3 200.3 200.3 200.3 200.3 200.3 200.3 200.3 Min: 200.3, Avg: 200.3, Max: 200.3, Diff: 0.0] [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.2 ms] [Other: 0.4 ms] [Choose CSet: 0.0 ms] [Ref Proc: 0.1 ms] [Ref Enq: 0.0 ms] [Redirty Cards: 0.2 ms] [Parallel Redirty: 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Redirtied Cards: 67 0 0 0 0 0 0 0 Min: 0, Avg: 8.4, Max: 67, Diff: 67, Sum: 67] [Humongous Register: 0.0 ms] [Humongous Total: 16] [Humongous Candidate: 16] [Humongous Reclaim: 0.0 ms] [Humongous Reclaimed: 16] [Free CSet: 0.0 ms] [Young Free CSet: 0.0 ms] [Non-Young Free CSet: 0.0 ms] [Eden: 10.0M(10.0M)->0.0B(10.0M) Survivors: 2048.0K->2048.0K Heap: 23.1M(254.0M)->3357.5K(254.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] //以下这个就是在我们程序运行结束之后，堆内存的使用状态 Heap garbage-first heap total 260096K, used 15133K [0x00000000f0000000, 0x00000000f01007f0, 0x0000000100000000) region size 1024K, 7 young (7168K), 2 survivors (2048K) Metaspace used 3465K, capacity 4496K, committed 4864K, reserved 1056768K class space used 377K, capacity 388K, committed 512K, reserved 1048576K(4)问题
模拟YGC一直运行的日志输出情况，把代码改造一下，加一个while循环，参数不变：
-Xmx256M -XX:+UseG1GC -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:+UnlockExperimentalVMOptions -XX:G1LogLevel=finest -XX:MaxGCPauseMillis=20 -Xloggc:gc.log如下这样的代码，如果一直运行下去，新生代会发生怎样的变化？结合TLAB的变化、预测模型、YGC后的新生代动态调整、以及新生代动态调整的比例，来思考下YGC在程序持续运行一段时间后，会发生怎样的变化？
//5% * 256 = 12M左右 //因为256M / 2048小于1，根据G1的处理，会把一个Region定为1M public static void main(String[] args) throws Exception { while(true) { //设定一个对象为256K，如果太大，会直接走大对象分配无法模拟YGC byte[] data = new byte[1024 * 256]; for (int i = 0; i< 36; i++) { data = new byte[1024 * 256]; } //创建n个对象，加入到一个list中，不回收这些数组 ArrayList list = new ArrayList(); for (int i = 0; i<= 36; i++) { byte[] data2 = new byte[1024 * 256]; //一部分字节数组加入到list中 if (i % 3 == 0) { list.add(data2); byte[] bigData1 = new byte[1024 * 512]; byte[] bigData2 = new byte[1024 * 1024]; } //随机某次把list直接清空掉，最终可能会留下一些存活对象 //这块主要是模拟程序正常运行过程中对象可能会被回收 if (i % Math.random()*10 == 0) { list.clear(); } } } }
5.Mixed GC日志信息之初始标记过程
(1)参数设置
(2)模拟代码
(3)代码运行相关的GC日志
(1)参数设置
具体参数如下：
-Xmx256M -XX:+UseG1GC -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:+UnlockExperimentalVMOptions -XX:G1LogLevel=finest -XX:MaxGCPauseMillis=20 -Xloggc:gc.log 在参数上没有什么特别的变化，主要是添加了两个参数。一个是开启实验选项，用于设置日志的输出级别，日志的输出级别设置为-XX:G1LogLevel=finest
(2)模拟代码
private static final ArrayList list = new ArrayList(); //5% * 256 = 12M左右 //因为256M / 2048小于1，根据G1的处理，会把一个Region定为1M public static void main(String[] args) throws Exception { while(true) { //设定一个对象为256K，如果太大，会直接走大对象分配无法模拟YGC byte[] data = new byte[1024 * 256]; for (int i = 0; i< 36; i++) { data = new byte[1024 * 256]; } //创建n个对象，加入到一个list中，不回收这些数组 for (int i = 0; i<= 36; i++) { byte[] data2 = new byte[1024 * 256]; //一部分字节数组加入到list中 if (i % 2 == 0) { list.add(data2); byte[] bigData1 = new byte[1024 * 512]; } } Thread.sleep(1000); } }下面来解析一下代码：
一.首先第一段创建了一个data字节数组，大小是1024 * 256 = 256KB
因为对象如果超过了Region大小一半，是一定会被当作大对象单独存储的，所以要把这个对象的大小设置的合理一点。而对于设置的参数，堆内存是256M。通过计算不难发现，Region的大小是1M。因为256M / 2048很显然小于1M，然后会自动调整，调整成1M大小。那么将对象设置成256K大小，就能正常分配到新生代Region中。
二.然后使用了一个循环，在循环中会不断创建新的数组
并且循环的次数设置在了36，为什么设置成36呢？原因是，在G1启动时会初始化新生代的大小。新生代的大小占总空间的5%，也就是256M * 5%约等于12M。也就是用掉12个Region时，就会触发第一次YGC。
三.在触发了YGC之后
由于data这个变量还在，所以还是会有一个256K的字节数组存活。加上一些堆内存中存在的一些未知对象也可能会存活，那么在第一次回收后，应该会有不到1M的对象存活下来进入Survivor区域。
四.比较大的改变在这里：
//一部分字节数组加入到list中 if (i % 2 == 0) { list.add(data2); byte[] bigData1 = new byte[1024 * 512]; }代码运行中，这个地方模拟出，每2次执行就把存活对象放入到数组中。这样做是为了更快触发Mixed GC，因为Mixed GC的触发条件是老年代使用了45%，并且垃圾清理的过程并不一定是跟在Initial Mark之后的。
也就是说，即使触发了初始标记过程，也不一定会启动Mixed GC。所以要让堆内存里的存活对象始终在增长，保证它一定会触发Mixed GC。
(3)代码运行相关的GC日志
从如下这个日志可以看出：首先会触发了一次YGC，并且时间并不长。然后经过很多次YGC后才会触发Mixed GC的初始标记，并且触发Mixed GC的初始标记后，紧接着的也不一定就是Mixed GC。因为这期间应用程序还会运行，就有可能继续触发YGC。
0.177: [GC pause (G1 Evacuation Pause) (young), 0.0017408 secs] // 启动了8个线程去执行，并且并行的执行时间1.2ms [Parallel Time: 1.2 ms, GC Workers: 8] [GC Worker Start (ms): 177.2 177.2 177.2 177.2 177.2 177.6 178.3 178.3 Min: 177.2, Avg: 177.5, Max: 178.3, Diff: 1.1] ... [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.1 ms] [Other: 0.4 ms] ... //从这里可以看出，这次GC是一次非常常规的YGC，GC之前，S区没有，GC之后，下一次S区是1个，也就是1M的空间； //堆内存在回收前是6144K垃圾，回收后是1048K垃圾 [Eden: 6144.0K(6144.0K)->0.0B(5120.0K) Survivors: 0.0B->1024.0K Heap: 6144.0K(128.0M)->1048.0K(128.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] //第二次回收，我们着重看一下对象的增涨速度 0.180: [GC pause (G1 Evacuation Pause) (young), 0.0016041 secs] [Parallel Time: 1.1 ms, GC Workers: 8] [GC Worker Start (ms): 180.3 180.3 180.3 180.3 180.3 180.3 180.6 181.2 Min: 180.3, Avg: 180.4, Max: 181.2, Diff: 1.0] ... [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.1 ms] [Other: 0.4 ms] ... //从下面这里可以看到： //对象增涨的速度其实并不快，并且Eden区的个数，调大了一个 [Eden: 5120.0K(5120.0K)->0.0B(6144.0K) Survivors: 1024.0K->1024.0K Heap: 6168.0K(128.0M)->1427.9K(128.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] //接下来省略很多次普通的YGC，YGC的过程没必要放出来了，因为太多了； ... ... ... ... //到了这次YGC，依然是很正常的YGC，还是常规的YGC结果； 7.289: [GC pause (G1 Evacuation Pause) (young), 0.0029624 secs] [Parallel Time: 1.8 ms, GC Workers: 8] [GC Worker Start (ms): 7288.9 7288.9 7288.9 7289.0 7289.0 7289.0 7289.0 7289.0 Min: 7288.9, Avg: 7288.9, Max: 7289.0, Diff: 0.1] ... [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.5 ms] [Other: 0.6 ms] ... //注意这里，此时堆内存的使用已经非常多了； //Eden区在回收以后是0B，S区扩展到了6M左右，堆内存总使用量47.5M，此时这个使用量其实已经比较高了； [Eden: 38.0M(38.0M)->0.0B(57.0M) Survivors: 5120.0K->6144.0K Heap: 89.3M(128.0M)->47.5M(128.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] //重点看这里，发现已经开启了初始标记(可见此时也还是一次YGC)； 8.309: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0014780 secs] [Parallel Time: 1.0 ms, GC Workers: 8] [GC Worker Start (ms): 8308.9 8308.9 8308.9 8308.9 8308.9 8308.9 8309.0 8309.1 Min: 8308.9, Avg: 8309.0, Max: 8309.1, Diff: 0.2] ... [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.1 ms] [Other: 0.3 ms] ... //从这次回收之后的数据可以看到，确实是遵循45%这个规则； //YGC垃圾回收后，即将分配的对象 + 老年代的所有对象占用的空间达到了45%时，就会触发Mixed GC，也就是开启并发标记； [Eden: 24.0M(57.0M)->0.0B(49.0M) Survivors: 6144.0K->6144.0K Heap: 78.8M(128.0M)->53.0M(128.0M)] [Times: user=0.09 sys=0.00, real=0.00 secs] //并发根扫描的开始和结束 8.311: [GC concurrent-root-region-scan-start] 8.311: [GC concurrent-root-region-scan-end, 0.0000467 secs] //并发标记的开始和结束 8.311: [GC concurrent-mark-start] 8.313: [GC concurrent-mark-end, 0.0018556 secs] //重新标记阶段 8.313: [GC remark 8.313: [Finalize Marking, 0.0001905 secs] 8.313: [GC ref-proc, 0.0003040 secs] 8.313: [Unloading 8.313: [System Dictionary Unloading, 0.0000130 secs] 8.313: [Parallel Unloading, 0.0005763 secs] 8.314: [Deallocate Metadata, 0.0000144 secs], 0.0006416 secs], 0.0014267 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] //预清理阶段 8.314: [GC cleanup 75M->75M(128M), 0.0016325 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] //又进行了一次YGC，因为Mixed GC初始标记后的并发标记阶段会和系统程序一起并发运行，所以这里是系统程序触发的YGC 9.331: [GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0008772 secs] [Parallel Time: 0.4 ms, GC Workers: 8] [GC Worker Start (ms): 9331.0 9331.0 9331.0 9331.0 9331.0 9331.0 9331.0 9331.0 Min: 9331.0, Avg: 9331.0, Max: 9331.0, Diff: 0.1] ... [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.1 ms] [Other: 0.4 ms] ... [Eden: 37.0M(49.0M)->0.0B(6144.0K) Survivors: 6144.0K->0.0B Heap: 108.5M(128.0M)->78.8M(128.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] //接下来才是打印触发的Mixed GC 10.347: [GC pause (G1 Evacuation Pause) (mixed), 0.0017163 secs] [Parallel Time: 1.2 ms, GC Workers: 8] [GC Worker Start (ms): 10347.3 10347.3 10347.3 10347.3 10347.3 10347.3 10347.5 10347.6 Min: 10347.3, Avg: 10347.4, Max: 10347.6, Diff: 0.3] ... [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.1 ms] [Other: 0.4 ms] ... [Eden: 6144.0K(6144.0K)->0.0B(5120.0K) Survivors: 0.0B->1024.0K Heap: 85.3M(128.0M)->78.8M(128.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] 10.350: [GC pause (G1 Evacuation Pause) (mixed), 0.0015104 secs] [Parallel Time: 0.8 ms, GC Workers: 8] [GC Worker Start (ms): 10350.1 10350.2 10350.2 10350.2 10350.2 10350.2 10350.2 10350.3 Min: 10350.1, Avg: 10350.2, Max: 10350.3, Diff: 0.2] ... [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.1 ms] [Other: 0.5 ms] ... [Eden: 5120.0K(5120.0K)->0.0B(27.0M) Survivors: 1024.0K->1024.0K Heap: 83.8M(128.0M)->79.5M(128.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] //又出现了一次Mixed GC的初始标记 10.353: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0009719 secs] [Parallel Time: 0.4 ms, GC Workers: 8] [GC Worker Start (ms): 10352.6 10352.6 10352.7 10352.7 10352.7 10352.7 10352.7 10352.7 Min: 10352.6, Avg: 10352.7, Max: 10352.7, Diff: 0.1] ... [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.2 ms] [Other: 0.4 ms] ... [Eden: 3072.0K(27.0M)->0.0B(28.0M) Survivors: 1024.0K->1024.0K Heap: 82.0M(128.0M)->79.8M(128.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] 10.354: [GC concurrent-root-region-scan-start] 10.354: [GC concurrent-root-region-scan-end, 0.0000481 secs] 10.354: [GC concurrent-mark-start] 10.356: [GC concurrent-mark-end, 0.0019111 secs] 10.356: [GC remark 10.356: [Finalize Marking, 0.0002410 secs] 10.357: [GC ref-proc, 0.0002787 secs] 10.357: [Unloading 10.357: [System Dictionary Unloading, 0.0000089 secs] 10.357: [Parallel Unloading, 0.0005675 secs] 10.357: [Deallocate Metadata, 0.0000145 secs], 0.0006318 secs], 0.0014424 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 10.358: [GC cleanup 101M->101M(128M), 0.0006501 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
6.Mixed GC日志信息之混合回收过程
继续前面的Mixed GC日志分析：
... //到了这次YGC，依然是很正常的YGC； 7.289: [GC pause (G1 Evacuation Pause) (young), 0.0029624 secs] [Parallel Time: 1.8 ms, GC Workers: 8] ... //注意，此时堆内存的使用已经非常多了； //Eden区在回收以后，是0B，S区扩展到了6M左右，堆内存总使用量47.5M，此时这个使用量其实已经比较高了； [Eden: 38.0M(38.0M)->0.0B(57.0M) Survivors: 5120.0K->6144.0K Heap: 89.3M(128.0M)->47.5M(128.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] //接下来这里，发现已经开启了初始标记； 8.309: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0014780 secs] [Parallel Time: 1.0 ms, GC Workers: 8] ... //这次回收之后的数据如下一行所示； //从数据中可以看到，确实是遵循45%这个规则来的； //垃圾回收后，即将分配的对象 + 老年代的所有对象占用的空间达到了45%的时候，就会触发Mixed GC，也就是开启并发标记； [Eden: 24.0M(57.0M)->0.0B(49.0M) Survivors: 6144.0K->6144.0K Heap: 78.8M(128.0M)->53.0M(128.0M)] [Times: user=0.09 sys=0.00, real=0.00 secs] //从这里也可以看出来，初始标记状态，其实就是一次YGC，但是需要注意的是，初始标记之后，并不一定会执行Mixed GC //初始标记之后会进入并发标记； //下面这几行实际上做的是从YHR中的Survivor分区开始进行并发标记的GC Roots扫描； //可以理解成，找到Survivor区的所有存活对象，并作为根对象，这一部分还没有对GC Roots直接引用的老年代对象做扫描 8.311: [GC concurrent-root-region-scan-start] //扫描结束，用时0.0000467秒，这个扫描过程需要注意的是：它是和应用程序同时进行的，并且有多个线程参与 8.311: [GC concurrent-root-region-scan-end, 0.0000467 secs] //并发标记的全量扫描过程，就是以Survivor + GC Roots(方法栈里面的局部变量，静态变量等)，标记整个堆里面的所有存活对象 8.311: [GC concurrent-mark-start] //并发标记结束，花费了0.0018565秒 8.313: [GC concurrent-mark-end, 0.0018556 secs] //最终标记阶段，标记程序创建出来的新对象，软引用、弱引用等的处理； 8.313: [GC remark 8.313: [Finalize Marking, 0.0001905 secs] 8.313: [GC ref-proc, 0.0003040 secs] 8.313: [Unloading 8.313: [System Dictionary Unloading, 0.0000130 secs] 8.313: [Parallel Unloading, 0.0005763 secs] 8.314: [Deallocate Metadata, 0.0000144 secs], 0.0006416 secs], 0.0014267 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] //预清理处理，这个地方清除的是全部都是垃圾的那些Region分区，从这里的日志可以看出来，没有清理掉任何一个Region 8.314: [GC cleanup 75M->75M(128M), 0.0016325 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] //紧接着，又进入了YGC(此时S区不足需要清空S区)； //而且是标明了to-space exhausted，这说明to区在本次GC之后不够用了，要做一些对象升入老年代的操作，调整S区大小 9.331: [GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0008772 secs] [Parallel Time: 0.4 ms, GC Workers: 8] [GC Worker Start (ms): 9331.0 9331.0 9331.0 9331.0 9331.0 9331.0 9331.0 9331.0 Min: 9331.0, Avg: 9331.0, Max: 9331.0, Diff: 0.1] ... [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.1 ms] [Other: 0.4 ms] ... //这里可以看出来，在本次回收之后，S区已经变成了0了 [Eden: 37.0M(49.0M)->0.0B(6144.0K) Survivors: 6144.0K->0.0B Heap: 108.5M(128.0M)->78.8M(128.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] //然后开始进入混合回收阶段，混合回收的内容和YGC的内容其实差不多 10.347: [GC pause (G1 Evacuation Pause) (mixed), 0.0017163 secs] //并行时间1.2ms，8个线程参与 [Parallel Time: 1.2 ms, GC Workers: 8] [GC Worker Start (ms): 10347.3 10347.3 10347.3 10347.3 10347.3 10347.3 10347.5 10347.6 Min: 10347.3, Avg: 10347.4, Max: 10347.6, Diff: 0.3] [Ext Root Scanning (ms): 0.2 0.2 0.2 0.2 0.2 0.1 0.0 0.0 Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.0] [Thread Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [StringTable Roots (ms): 0.1 0.2 0.1 0.1 0.2 0.1 0.0 0.0 Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.8] [Universe Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [JNI Handles Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [ObjectSynchronizer Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [FlatProfiler Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Management Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [SystemDictionary Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [CLDG Roots (ms): 0.1 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.1] [JVMTI Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [CodeCache Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.1 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2] [CM RefProcessor Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Wait For Strong CLD (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Weak CLD Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [SATB Filtering (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Update RS (ms): 0.0 0.0 0.0 0.0 0.0 0.1 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2] [Processed Buffers: 2 1 1 0 0 1 0 0 Min: 0, Avg: 0.6, Max: 2, Diff: 2, Sum: 5] [Scan RS (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Code Root Scanning (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Object Copy (ms): 0.8 0.9 0.9 0.8 0.8 0.8 0.8 0.7 Min: 0.7, Avg: 0.8, Max: 0.9, Diff: 0.2, Sum: 6.4] [Termination (ms): 0.1 0.1 0.0 0.1 0.1 0.1 0.1 0.1 Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.7] [Termination Attempts: 1 1 1 1 1 1 1 1 Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 8] [GC Worker Other (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [GC Worker Total (ms): 1.1 1.1 1.1 1.1 1.1 1.1 0.9 0.8 Min: 0.8, Avg: 1.0, Max: 1.1, Diff: 0.3, Sum: 8.4] [GC Worker End (ms): 10348.4 10348.4 10348.4 10348.4 10348.4 10348.4 10348.4 10348.4 Min: 10348.4, Avg: 10348.4, Max: 10348.4, Diff: 0.0] [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.1 ms] [Other: 0.4 ms] [Choose CSet: 0.0 ms] [Ref Proc: 0.2 ms] [Ref Enq: 0.0 ms] [Redirty Cards: 0.1 ms] [Parallel Redirty: 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Redirtied Cards: 4 0 0 0 0 0 0 0 Min: 0, Avg: 0.5, Max: 4, Diff: 4, Sum: 4] [Humongous Register: 0.0 ms] [Humongous Total: 1] [Humongous Candidate: 1] [Humongous Reclaim: 0.0 ms] [Humongous Reclaimed: 1] [Free CSet: 0.0 ms] [Young Free CSet: 0.0 ms] [Non-Young Free CSet: 0.0 ms] [Eden: 6144.0K(6144.0K)->0.0B(5120.0K) Survivors: 0.0B->1024.0K Heap: 85.3M(128.0M)->78.8M(128.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] //由上述可见，Mixed GC的回收阶段的过程和YGC几乎一模一样，什么原因呢？ //其实就是复用了代码，然后主要的区别在于选择的Cset不同 //下面又是一次Mixed GC，因为会分批次，默认最多分8次 10.350: [GC pause (G1 Evacuation Pause) (mixed), 0.0015104 secs] [Parallel Time: 0.8 ms, GC Workers: 8] [GC Worker Start (ms): 10350.1 10350.2 10350.2 10350.2 10350.2 10350.2 10350.2 10350.3 Min: 10350.1, Avg: 10350.2, Max: 10350.3, Diff: 0.2] ... [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.1 ms] [Other: 0.5 ms] ... [Eden: 5120.0K(5120.0K)->0.0B(27.0M) Survivors: 1024.0K->1024.0K Heap: 83.8M(128.0M)->79.5M(128.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] //又一次触发了初始标记 //其实看到这里触发初始标记，也可以大概猜到，后续的Mixed GC也会非常频繁，并且初始标记也会经常发生，因为老年代的存活对象太多了； 10.353: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0009719 secs] [Parallel Time: 0.4 ms, GC Workers: 8] [GC Worker Start (ms): 10352.6 10352.6 10352.7 10352.7 10352.7 10352.7 10352.7 10352.7 Min: 10352.6, Avg: 10352.7, Max: 10352.7, Diff: 0.1] ... [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.2 ms] [Other: 0.4 ms] ... [Eden: 3072.0K(27.0M)->0.0B(28.0M) Survivors: 1024.0K->1024.0K Heap: 82.0M(128.0M)->79.8M(128.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] 10.354: [GC concurrent-root-region-scan-start] 10.354: [GC concurrent-root-region-scan-end, 0.0000481 secs] 10.354: [GC concurrent-mark-start] 10.356: [GC concurrent-mark-end, 0.0019111 secs] 10.356: [GC remark 10.356: [Finalize Marking, 0.0002410 secs] 10.357: [GC ref-proc, 0.0002787 secs] 10.357: [Unloading 10.357: [System Dictionary Unloading, 0.0000089 secs] 10.357: [Parallel Unloading, 0.0005675 secs] 10.357: [Deallocate Metadata, 0.0000145 secs], 0.0006318 secs], 0.0014424 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 10.358: [GC cleanup 101M->101M(128M), 0.0006501 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]Mixed GC的过程相对复杂。在触发了初始标记以后，并不一定紧跟的就是Mixed GC的回收阶段。有可能会继续进行YGC的过程，然后才进入Mixd GC的回收阶段。
由此可见，对于Mixed GC来说：从初始标记到并发标记到回收阶段整个流程，不一定是连续的整个流程。因为在并发标记阶段程序会运行，接下来有可能再触发一次YGC。并且在可回收的垃圾不足5%时，也不会触发Mixed GC的回收阶段。同时如果进行了多次GC后，小于了这个5%，也可能不继续进行混合回收。当然这个5%不太好模拟，如果是线上的程序其实更好模拟一些。
7.Mixed GC日志信息之Region的详细信息和标记过程的详细信息
(1)参数设置
(2)模拟代码
(3)代码运行相关的GC日志
(4)这些数据有什么作用
(1)参数设置
具体参数如下：
-Xmx128M -XX:+UseG1GC -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:+UnlockExperimentalVMOptions -XX:G1LogLevel=finest -XX:+UnlockDiagnosticVMOptions -XX:+G1PrintRegionLivenessInfo -XX:+G1SummarizeConcMark -XX:MaxGCPauseMillis=20 -Xloggc:gc.log和前面设置的JVM参数有区别的是如下这几个：
打开数据分析选项：-XX:+UnlockDiagnosticVMOptions 打印所有的region的使用详情信息：-XX:+G1PrintRegionLivenessInfo 打开并发标记的详细信息：-XX:+G1SummarizeConcMark(2)模拟代码
public static void main(String[] args) throws Exception { while(true) { //设定一个对象为256K，如果太大，会直接走大对象分配无法模拟YGC byte[] data = new byte[1024 * 256]; for (int i = 0; i< 36; i++) { data = new byte[1024 * 256]; } //创建n个对象，加入到一个list中，不回收这些数组 for (int i = 0; i<= 36; i++) { byte[] data2 = new byte[1024 * 256]; //一部分字节数组加入到list中 if (i % 2 == 0) { list.add(data2); byte[] bigData1 = new byte[1024 * 512]; } } Thread.sleep(100); } }(3)代码运行相关的GC日志
CommandLine flags: -XX:G1LogLevel=finest -XX:+G1PrintRegionLivenessInfo -XX:+G1SummarizeConcMark -XX:InitialHeapSize=134217728 -XX:MaxGCPauseMillis=20 -XX:MaxHeapSize=134217728 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UnlockDiagnosticVMOptions -XX:+UnlockExperimentalVMOptions -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation 0.130: [GC pause (G1 Humongous Allocation) (young) (initial-mark), 0.0020150 secs] [Parallel Time: 1.0 ms, GC Workers: 8] [GC Worker Start (ms): 129.7 129.8 129.8 129.8 129.8 129.8 129.8 129.8 Min: 129.7, Avg: 129.8, Max: 129.8, Diff: 0.1] ... [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] [Clear CT: 0.4 ms] [Other: 0.7 ms] ... [Eden: 3072.0K(6144.0K)->0.0B(5120.0K) Survivors: 0.0B->1024.0K Heap: 31.1M(128.0M)->1848.1K(128.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] 0.132: [GC concurrent-root-region-scan-start] 0.133: [GC concurrent-root-region-scan-end, 0.0008120 secs] 0.133: [GC concurrent-mark-start] 0.133: [GC concurrent-mark-end, 0.0001406 secs] 0.133: [GC remark 0.133: [Finalize Marking, 0.0004982 secs] 0.134: [GC ref-proc, 0.0002247 secs] 0.134: [Unloading 0.134: [System Dictionary Unloading, 0.0000091 secs] 0.134: [Parallel Unloading, 0.0005040 secs] 0.134: [Deallocate Metadata, 0.0000141 secs], 0.0005701 secs], 0.0016329 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 0.135: [GC cleanup ### PHASE Post-Marking @ 0.135 ### HEAP reserved: 0x00000000f8000000-0x0000000100000000 region-size: 1048576 ### type(分区类型) address-range(地址范围) used(使用量) prev-live next-live gc-eff(GC效率) remset(Rset大小) code-roots ### (bytes) (bytes) (bytes) (bytes/ms) (bytes) (bytes) ### HUMS 0x00000000f8000000-0x00000000f8100000 1048576 1048576 1048576 0.0 2904 16 ### HUMC 0x00000000f8100000-0x00000000f8200000 16 16 16 0.0 2904 16 ... ### HUMS 0x00000000fae00000-0x00000000faf00000 1048576 1048576 1048576 0.0 2904 16 ### HUMC 0x00000000faf00000-0x00000000fb000000 16 16 16 0.0 2904 16 ### FREE 0x00000000fb000000-0x00000000fb100000 0 0 0 0.0 2904 16 ### FREE 0x00000000fb100000-0x00000000fb200000 0 0 0 0.0 2904 16 ### FREE 0x00000000fb200000-0x00000000fb300000 0 0 0 0.0 2904 16 ### FREE 0x00000000fb300000-0x00000000fb400000 0 0 0 0.0 2904 16 ### FREE 0x00000000fb400000-0x00000000fb500000 0 0 0 0.0 2904 16 ### FREE 0x00000000fb500000-0x00000000fb600000 0 0 0 0.0 2904 16 ### FREE 0x00000000fb600000-0x00000000fb700000 0 0 0 0.0 2904 16 ### FREE 0x00000000fb700000-0x00000000fb800000 0 0 0 0.0 2904 16 ### HUMS 0x00000000fb800000-0x00000000fb900000 1048576 1048576 1048576 0.0 2904 16 ### HUMC 0x00000000fb900000-0x00000000fba00000 16 16 16 0.0 2904 16 ### FREE 0x00000000fba00000-0x00000000fbb00000 0 0 0 0.0 2904 16 ... ### FREE 0x00000000ffa00000-0x00000000ffb00000 0 0 0 0.0 2904 16 ### FREE 0x00000000ffb00000-0x00000000ffc00000 0 0 0 0.0 2904 16 ### SURV 0x00000000ffc00000-0x00000000ffd00000 843840 843840 843840 0.0 3056 168 ### FREE 0x00000000ffd00000-0x00000000ffe00000 0 0 0 0.0 2904 16 ### FREE 0x00000000ffe00000-0x00000000fff00000 0 0 0 0.0 2904 16 ### EDEN 0x00000000fff00000-0x0000000100000000 104904 104904 104904 0.0 2904 16 ### ### SUMMARY capacity: 128.00 MB used: 25.91 MB / 20.24 % prev-live: 25.91 MB / 20.24 % next-live: 25.91 MB / 20.24 % remset: 0.36 MB code-roots: 0.00 MB ### PHASE Post-Sorting @ 0.136 ### HEAP reserved: 0x00000000f8000000-0x0000000100000000 region-size: 1048576 ### ### type address-range used prev-live next-live gc-eff remset code-roots ### (bytes) (bytes) (bytes) (bytes/ms) (bytes) (bytes) ### ### SUMMARY capacity: 0.00 MB used: 0.00 MB / 0.00 % prev-live: 0.00 MB / 0.00 % next-live: 0.00 MB / 0.00 % remset: 0.01 MB code-roots: 0.00 MB 25M->25M(128M), 0.0010444 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] //堆内存退出前的使用状态 Heap garbage-first heap total 131072K, used 65513K [0x00000000f8000000, 0x00000000f8100400, 0x0000000100000000) region size 1024K, 1 young (1024K), 0 survivors (0K) Metaspace used 3969K, capacity 4568K, committed 4864K, reserved 1056768K class space used 437K, capacity 460K, committed 512K, reserved 1048576K //并发标记的状态，其中包括标记类型，比如初始标记状态、init marks、并发标记remarks、最终标记final marks、weak refs，弱引用处理 Concurrent marking: 0 init marks: total time = 0.00 s (avg = 0.00 ms). 2 remarks: total time = 0.00 s (avg = 1.36 ms). [std. dev = 0.00 ms, max = 1.36 ms] 2 final marks: total time = 0.00 s (avg = 0.21 ms). [std. dev = 0.02 ms, max = 0.23 ms] 2 weak refs: total time = 0.00 s (avg = 1.14 ms). [std. dev = 0.02 ms, max = 1.16 ms] 2 cleanups: total time = 0.00 s (avg = 0.78 ms). [std. dev = 0.33 ms, max = 1.11 ms] //对对象进行计数统计花费的时间 Final counting total time = 0.00 s (avg = 0.24 ms). //RSet的处理时长 RS scrub total time = 0.00 s (avg = 0.22 ms). //所有STW的阶段加起来一共停顿了多久 Total stop_world time = 0.00 s. //所有GC线程在整个并发标记过程中的总花费时间(多个线程并发，每个线程的耗时求和) Total concurrent time = 0.03 s ( 0.03 s marking).(4)这些数据有什么作用
平常的话， 如下这几个参数是不需要打开的：
-XX:+UnlockExperimentalVMOptions -XX:G1LogLevel=finest -XX:+UnlockDiagnosticVMOptions -XX:+G1SummarizeConcMark基本上借助普通的GC日志就能发现问题。如果想详细了解每个阶段的耗时、每个Region的回收效率，那么就可打开这些选项。比如统计并发标记各阶段耗时，统计每个Region的数据是如何分布的。以此为基础来调整停顿时间、RegionSize等参数来做优化。
//YGC各阶段耗时 //GC线程还是8个，本次GC造成的停顿时间是0.00178，很明显是在20ms内的； 0.189: [GC pause (G1 Evacuation Pause) (young), 0.0020256 secs] [Parallel Time: 1.4 ms, GC Workers: 8] //注意，下面这一行信息是说我们这8个线程开始的时间，min表示最早开始的线程时间，avg表示平均开始时间，max表示最晚开始时间，diff表示最早和最晚的时间差，这个diff越大就说明线程启动时间越不均衡，一般这个地方的时间不会差别很大； [GC Worker Start (ms): 188.7 188.7 188.7 188.7 188.8 188.8 188.8 188.8 Min: 188.7, Avg: 188.7, Max: 188.8, Diff: 0.1] //8个线程对根(GC Roots)扫描处理的时间，可以注意到，根的类型非常多，除了经常说的Java静态变量、方法局部变量外还有很多其他的一些根 [Ext Root Scanning (ms): 0.3 1.2 0.2 0.0 0.2 0.2 0.2 0.2 Min: 0.0, Avg: 0.3, Max: 1.2, Diff: 1.2, Sum: 2.5] [Thread Roots (ms): 0.0 1.2 0.1 0.0 0.0 0.0 0.1 0.0 Min: 0.0, Avg: 0.2, Max: 1.2, Diff: 1.2, Sum: 1.5] [StringTable Roots (ms): 0.0 0.0 0.1 0.0 0.1 0.1 0.1 0.2 Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 0.6] [Universe Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [JNI Handles Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [ObjectSynchronizer Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [FlatProfiler Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Management Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [SystemDictionary Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [CLDG Roots (ms): 0.3 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.3, Diff: 0.3, Sum: 0.3] [JVMTI Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [CodeCache Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [CM RefProcessor Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Wait For Strong CLD (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Weak CLD Roots (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [SATB Filtering (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] //更新RSet的操作，前面提过要先更新RSet后，再进行RSet的扫描，其实在这个日志里就能看的出来； //对象引用关系更新之后，要通过Refine线程 + 系统程序的线程 + DCQ更新RSet //下面显示的是GC线程时间都为0.0，说明这块更新没问题 //因为引用更新导致RSet更新的这些操作，都已经由Refine线程提前处理完了； [Update RS (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Processed Buffers: 0 0 0 0 0 0 0 0 Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0] //扫描RSet，处理存活对象； [Scan RS (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Code Root Scanning (ms): 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] //这一步很关键，对象拷贝，就是把存活对象拷贝到一个新的分区，可以看出来，拷贝消耗的时间非常长； //注意：对象拷贝消耗的时间占了GC绝大部分的时间 [Object Copy (ms): 0.5 0.0 0.6 0.0 0.7 0.6 0.6 0.6 Min: 0.0, Avg: 0.5, Max: 0.7, Diff: 0.7, Sum: 3.8] //GC线程关闭的一些信息 [Termination (ms): 0.4 0.0 0.4 0.4 0.4 0.4 0.4 0.4 Min: 0.0, Avg: 0.4, Max: 0.4, Diff: 0.4, Sum: 2.8] [Termination Attempts: 3 1 12 1 16 9 11 9 Min: 1, Avg: 7.8, Max: 16, Diff: 15, Sum: 62] //GC线程的一些其他工作的处理时间，通常是JVM析构释放资源 [GC Worker Other (ms): 0.0 0.1 0.1 0.9 0.1 0.1 0.0 0.0 Min: 0.0, Avg: 0.2, Max: 0.9, Diff: 0.9, Sum: 1.3] //并行GC过程花费的总体时间； [GC Worker Total (ms): 1.3 1.3 1.3 1.3 1.3 1.3 1.3 1.3 Min: 1.3, Avg: 1.3, Max: 1.3, Diff: 0.1, Sum: 10.4] [GC Worker End (ms): 190.0 190.0 190.0 190.1 190.0 190.1 190.0 190.1 Min: 190.0, Avg: 190.0, Max: 190.1, Diff: 0.0] [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms] //清理卡表 [Clear CT: 0.2 ms] [Other: 0.5 ms] //选择Cset时间，对YGC来说，一般都是0，因为不需要选 [Choose CSet: 0.0 ms] [Ref Proc: 0.2 ms] [Ref Enq: 0.0 ms] //重构RSet花费的时间 [Redirty Cards: 0.2 ms] [Parallel Redirty: 0.0 0.0 0.0 0.0 0.0 0.0 0.0 0.0 Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0] [Redirtied Cards: 0 0 0 0 0 0 0 0 Min: 0, Avg: 0.0, Max: 0, Diff: 0, Sum: 0] //大对象的处理时间 [Humongous Register: 0.0 ms] [Humongous Total: 0] [Humongous Candidate: 0] //如果大对象要回收，回收花费的时间以及回收了多少个大对象 [Humongous Reclaim: 0.0 ms] [Humongous Reclaimed: 0] //释放CSet中的分区花费的时间 [Free CSet: 0.0 ms] [Young Free CSet: 0.0 ms] [Non-Young Free CSet: 0.0 ms] //Mixed GC各阶段耗时 //初始标记之后会进入并发标记； //下面这几行实际上做的是从YHR中的Survivor分区开始进行并发标记的GC Roots扫描； //可以理解成，找到Survivor区的所有存活对象，并作为根对象，这一部分还没有对GC Roots直接引用的老年代对象做扫描 8.311: [GC concurrent-root-region-scan-start] //扫描结束，用时0.0000467秒，这个扫描过程需要注意的是：它是和应用程序同时进行的，并且有多个线程参与 8.311: [GC concurrent-root-region-scan-end, 0.0000467 secs] //并发标记的全量扫描过程，就是以Survivor + GC Roots(方法栈里面的局部变量，静态变量等)，标记整个堆里面的所有存活对象 8.311: [GC concurrent-mark-start] //并发标记结束，花费了0.0018565秒 8.313: [GC concurrent-mark-end, 0.0018556 secs] //最终标记阶段，标记程序创建出来的新对象，软引用、弱引用等的处理； 8.313: [GC remark 8.313: [Finalize Marking, 0.0001905 secs] 8.313: [GC ref-proc, 0.0003040 secs] 8.313: [Unloading 8.313: [System Dictionary Unloading, 0.0000130 secs] 8.313: [Parallel Unloading, 0.0005763 secs] 8.314: [Deallocate Metadata, 0.0000144 secs], 0.0006416 secs], 0.0014267 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] //预清理处理，这个地方清除的是全部都是垃圾的那些Region分区，从这里的日志可以看出来，没有清理掉任何一个Region 8.314: [GC cleanup 75M->75M(128M), 0.0016325 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
8.FGC的日志信息及日志详情
(1)参数设置
(2)模拟代码
(3)代码运行相关的GC日志
(4)总结
(1)参数设置
具体参数如下：这里先不打印详情，看看Full GC出现的时候是什么时候。
-XX:InitialHeapSize=36M -XX:MaxHeapSize=36M -XX:G1HeapRegionSize=4M -XX:MaxGCPauseMillis=20 -XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+UseG1GC -Xloggc:gc.log(2)模拟代码
public class FGCDemo12 { private static final ArrayList list = new ArrayList(); public static void main(String[] args) throws Exception { while(true) { //设定一个对象为256K，如果太大，会直接走大对象分配无法模拟YGC byte[] data = new byte[1024 * 1024]; for (int i = 0; i< 36; i++) { data = new byte[1024 * 1024]; } //创建n个对象，加入到一个list中，不回收这些数组 for (int i = 0; i<= 36; i++) { byte[] data2 = new byte[1024 * 1024]; // 一部分字节数组加入到list中 list.add(data2); } Thread.sleep(1000); } } }(3)代码运行相关的GC日志
一.不加打印详情的时候，GC信息如下：
0.160: [GC pause (G1 Evacuation Pause) (young) 4096K->1808K(32M), 0.0028039 secs] 0.163: [GC pause (G1 Evacuation Pause) (young) 5904K->1976K(32M), 0.0017013 secs] 0.165: [GC pause (G1 Evacuation Pause) (young) 6072K->1997K(32M), 0.0012654 secs] 0.167: [GC pause (G1 Evacuation Pause) (young) 6093K->1819K(32M), 0.0012048 secs] 0.171: [GC pause (G1 Evacuation Pause) (young) 13M->2198K(32M), 0.0016891 secs] 0.174: [GC pause (G1 Evacuation Pause) (young) 14M->1900K(32M), 0.0013103 secs] 0.176: [GC pause (G1 Evacuation Pause) (young) 13M->2992K(32M), 0.0016521 secs] 0.179: [GC pause (G1 Evacuation Pause) (young) 14M->14M(32M), 0.0030006 secs] 0.183: [GC pause (G1 Evacuation Pause) (young)-- 30M->32M(32M), 0.0014989 secs] 0.184: [Full GC (Allocation Failure) 32M->23M(32M), 0.0052335 secs] 0.190: [Full GC (Allocation Failure) 23M->23M(32M), 0.0028101 secs] 0.193: [GC pause (G1 Evacuation Pause) (young) 23M->23M(32M), 0.0008639 secs] 0.194: [GC pause (G1 Evacuation Pause) (young) (initial-mark) 23M->23M(32M), 0.0008385 secs] 0.195: [GC concurrent-root-region-scan-start] 0.195: [GC concurrent-root-region-scan-end, 0.0000051 secs] 0.195: [GC concurrent-mark-start] //第一次Full GC压缩出1M的空间，从23M到22M；第二次Full GC没法压缩出空间了 0.195: [Full GC (Allocation Failure) 23M->22M(32M), 0.0062830 secs] 0.201: [Full GC (Allocation Failure) 22M->22M(32M), 0.0028600 secs] //终止并发标记 0.204: [GC concurrent-mark-abort] 0.204: [GC pause (G1 Evacuation Pause) (young) 22M->22M(32M), 0.0006367 secs] 0.205: [GC pause (G1 Evacuation Pause) (young) (initial-mark) 22M->22M(32M), 0.0007129 secs] 0.206: [GC concurrent-root-region-scan-start] 0.206: [GC concurrent-root-region-scan-end, 0.0000050 secs] 0.206: [GC concurrent-mark-start] //在并发标记开始时，进入了Full GC，并且进行了两次Full GC，最终并发标记终止，抛出了OOM异常； //说明我们对Full GC的分析是正确的，会分两次GC，第一次不处理软引用，第二次处理； 0.206: [Full GC (Allocation Failure) 22M->22M(32M), 0.0024892 secs] 0.208: [Full GC (Allocation Failure) 22M->22M(32M), 0.0020168 secs] 0.210: [GC concurrent-mark-abort] 二.修改参数为打印日志详情：
-XX:InitialHeapSize=36M -XX:MaxHeapSize=36M -XX:G1HeapRegionSize=4M -XX:MaxGCPauseMillis=20 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseG1GC -Xloggc:gc.log 在添加了打印日志详情 -XX:+PrintGCDetails 参数之后，日志输出如下：
CommandLine flags: -XX:G1HeapRegionSize=4194304 -XX:InitialHeapSize=37748736 -XX:MaxGCPauseMillis=20 -XX:MaxHeapSize=37748736 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation //第1次YGC 0.164: [GC pause (G1 Evacuation Pause) (young), 0.0015655 secs] [Parallel Time: 1.1 ms, GC Workers: 8] ... [Eden: 4096.0K(4096.0K)->0.0B(4096.0K) Survivors: 0.0B->4096.0K Heap: 4096.0K(36.0M)->1896.1K(36.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] //第2次YGC 0.166: [GC pause (G1 Evacuation Pause) (young), 0.0016293 secs] [Parallel Time: 1.1 ms, GC Workers: 8] ... [Eden: 4096.0K(4096.0K)->0.0B(4096.0K) Survivors: 4096.0K->4096.0K Heap: 5992.1K(36.0M)->2202.0K(36.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] //第3次YGC 0.168: [GC pause (G1 Evacuation Pause) (young), 0.0014074 secs] [Parallel Time: 0.9 ms, GC Workers: 8] ... [Eden: 4096.0K(4096.0K)->0.0B(4096.0K) Survivors: 4096.0K->4096.0K Heap: 6298.0K(36.0M)->1777.8K(36.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] //第4次YGC 0.170: [GC pause (G1 Evacuation Pause) (young), 0.0013150 secs] [Parallel Time: 0.9 ms, GC Workers: 8] ... [Eden: 4096.0K(4096.0K)->0.0B(8192.0K) Survivors: 4096.0K->4096.0K Heap: 5873.8K(36.0M)->1948.1K(36.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] //第5次YGC 0.173: [GC pause (G1 Evacuation Pause) (young), 0.0016268 secs] [Parallel Time: 1.2 ms, GC Workers: 8] ... [Eden: 8192.0K(8192.0K)->0.0B(16.0M) Survivors: 4096.0K->4096.0K Heap: 10140.1K(36.0M)->2080.7K(36.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] //第6次YGC 0.178: [GC pause (G1 Evacuation Pause) (young), 0.0015187 secs] [Parallel Time: 1.1 ms, GC Workers: 8] ... [Eden: 16.0M(16.0M)->0.0B(16.0M) Survivors: 4096.0K->4096.0K Heap: 18.0M(36.0M)->2069.6K(36.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] //第7次YGC 0.181: [GC pause (G1 Evacuation Pause) (young), 0.0018350 secs] ... [Eden: 16.0M(16.0M)->0.0B(16.0M) Survivors: 4096.0K->4096.0K Heap: 18.0M(36.0M)->6165.5K(36.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] //第8次YGC 0.183: [GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0032817 secs] [Parallel Time: 2.7 ms, GC Workers: 8] ... [Eden: 16.0M(16.0M)->0.0B(8192.0K) Survivors: 4096.0K->4096.0K Heap: 22.0M(36.0M)->24.0M(36.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] //第9次YGC，但在这里开启了Mixed GC的初始标记，然后紧接着进入了并发标记阶段 0.187: [GC pause (G1 Evacuation Pause) (young) (initial-mark) (to-space exhausted), 0.0013577 secs] [Parallel Time: 0.8 ms, GC Workers: 8] ... [Eden: 8192.0K(8192.0K)->0.0B(8192.0K) Survivors: 4096.0K->0.0B Heap: 32.0M(36.0M)->36.0M(36.0M)] [Times: user=0.13 sys=0.00, real=0.00 secs] //进入Mixed GC的并发标记阶段之后，开始并发标记时，直接进入了Full GC状态 0.189: [GC concurrent-root-region-scan-start] 0.189: [GC concurrent-root-region-scan-end, 0.0000047 secs] 0.189: [GC concurrent-mark-start] //可以看到Full GC第一次进行时，还是回收了一些垃圾的，并且对堆内存进行了整理； //在Full GC之后，就没有Eden区、Survivor区的具体细节了； //因为Full GC结束后，会把所有分区标记成Old，然后再重新选择一些Region成为Eden区； 0.189: [Full GC (Allocation Failure) 36M->23M(36M), 0.0051574 secs] [Eden: 0.0B(8192.0K)->0.0B(4096.0K) Survivors: 0.0B->0.0B Heap: 36.0M(36.0M)->23.7M(36.0M)], [Metaspace: 3445K->3445K(1056768K)] [Times: user=0.00 sys=0.00, real=0.00 secs] //然后此时并发标记就直接终止，不再进行了； 0.194: [GC concurrent-mark-abort] //程序运行一段时间后，Eden区又一次填满，此时继续进入YGC 0.194: [GC pause (G1 Evacuation Pause) (young) (to-space exhausted), 0.0007054 secs] [Parallel Time: 0.2 ms, GC Workers: 8] ... //注意：在Full GC之后，Eden区还是一个Region，并且此次YGC之后，没有回收掉任何垃圾； [Eden: 4096.0K(4096.0K)->0.0B(8192.0K) Survivors: 0.0B->0.0B Heap: 27.7M(36.0M)->27.7M(36.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] //接着程序继续运行，只能再此触发第一次的Full GC，并且仅仅压缩整理出了1M的空间 0.195: [Full GC (Allocation Failure) 27M->26M(36M), 0.0026733 secs] [Eden: 0.0B(8192.0K)->0.0B(4096.0K) Survivors: 0.0B->0.0B Heap: 27.7M(36.0M)->26.7M(36.0M)], [Metaspace: 3445K->3445K(1056768K)] [Times: user=0.00 sys=0.00, real=0.00 secs] //然后再此触发第二次的Full GC，此次回收会把软引用进行处理； //而我们的程序没有软引用，所以此次Full GC也无法腾出足够的空间； 0.198: [Full GC (Allocation Failure) 26M->26M(36M), 0.0020266 secs] [Eden: 0.0B(4096.0K)->0.0B(4096.0K) Survivors: 0.0B->0.0B Heap: 26.7M(36.0M)->26.7M(36.0M)], [Metaspace: 3445K->3445K(1056768K)] [Times: user=0.00 sys=0.00, real=0.00 secs] //然后再次进入YGC，因为Eden区为0，此时再次尝试分配失败 0.200: [GC pause (G1 Evacuation Pause) (young), 0.0007709 secs] [Parallel Time: 0.3 ms, GC Workers: 8] ... [Eden: 0.0B(4096.0K)->0.0B(8192.0K) Survivors: 0.0B->0.0B Heap: 26.7M(36.0M)->26.7M(36.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] //然后再次进入YGC，开启Mixed GC的初始标记 0.201: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0006809 secs] [Parallel Time: 0.3 ms, GC Workers: 8] ... [Eden: 0.0B(8192.0K)->0.0B(8192.0K) Survivors: 0.0B->0.0B Heap: 26.7M(36.0M)->26.7M(36.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] 0.202: [GC concurrent-root-region-scan-start] 0.202: [GC concurrent-root-region-scan-end, 0.0000054 secs] 0.202: [GC concurrent-mark-start] 0.202: [Full GC (Allocation Failure) 26M->25M(36M), 0.0067177 secs] [Eden: 0.0B(8192.0K)->0.0B(4096.0K) Survivors: 0.0B->0.0B Heap: 26.7M(36.0M)->25.7M(36.0M)], [Metaspace: 3445K->3445K(1056768K)] [Times: user=0.01 sys=0.00, real=0.01 secs] //触发Full GC 0.209: [Full GC (Allocation Failure) 25M->25M(36M), 0.0022560 secs] [Eden: 0.0B(4096.0K)->0.0B(4096.0K) Survivors: 0.0B->0.0B Heap: 25.7M(36.0M)->25.7M(36.0M)], [Metaspace: 3445K->3445K(1056768K)] [Times: user=0.00 sys=0.00, real=0.00 secs] //终止Mixed GC的并发标记 0.211: [GC concurrent-mark-abort] //触发YGC 0.211: [GC pause (G1 Evacuation Pause) (young), 0.0006518 secs] [Parallel Time: 0.3 ms, GC Workers: 8] ... [Eden: 0.0B(4096.0K)->0.0B(4096.0K) Survivors: 0.0B->0.0B Heap: 25.7M(36.0M)->25.7M(36.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] ////然后再次进入YGC，开启Mixed GC的初始标记 0.212: [GC pause (G1 Evacuation Pause) (young) (initial-mark), 0.0006747 secs] [Parallel Time: 0.3 ms, GC Workers: 8] ... [Eden: 0.0B(4096.0K)->0.0B(4096.0K) Survivors: 0.0B->0.0B Heap: 25.7M(36.0M)->25.7M(36.0M)] [Times: user=0.00 sys=0.00, real=0.00 secs] 0.213: [GC concurrent-root-region-scan-start] 0.213: [GC concurrent-root-region-scan-end, 0.0000046 secs] 0.213: [GC concurrent-mark-start] //触发第一次Full GC 0.213: [Full GC (Allocation Failure) 25M->25M(36M), 0.0025106 secs] [Eden: 0.0B(4096.0K)->0.0B(4096.0K) Survivors: 0.0B->0.0B Heap: 25.7M(36.0M)->25.7M(36.0M)], [Metaspace: 3445K->3445K(1056768K)] [Times: user=0.00 sys=0.00, real=0.00 secs] //触发第二次Full GC 0.216: [Full GC (Allocation Failure) 25M->25M(36M), 0.0020506 secs] [Eden: 0.0B(4096.0K)->0.0B(4096.0K) Survivors: 0.0B->0.0B Heap: 25.7M(36.0M)->25.7M(36.0M)], [Metaspace: 3445K->3445K(1056768K)] [Times: user=0.00 sys=0.00, real=0.00 secs] //终止Mixed GC的并发标记 0.218: [GC concurrent-mark-abort]最终经过多次尝试之后，无法分配，只能OOM。可以看到G1对于OOM其实是比较慎重的。经过很多次YGC并发标记，多次FGC的过程后，才最终抛出OOM异常。所以并不是两次FGC失败之后就进入OOM了。
注意：FGC结束后，会把所有分区标记成Old，然后再重新选择一些Region成为Eden区。
(4)总结
使用G1时发生FGC要比使用ParNew + CMS时发生FGC更加困难，并且尝试的次数日志上来看也非常多。FGC的整个过程比较简单粗暴，如果实在无法压缩出空间，就会OOM。
