G1原理—G1的GC日志分析解读

1.TLAB的GC日志解读

(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.1sSystem.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: 0B

gc 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)参数设置

对于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.1sSystem.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)参数设置

还是这么一套参数结构，主要是为了和前面做一些对比，看看模拟出来的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定为1Mpublic static void main(String[] args) throws Exception { //设定一个对象为256K的原因，如果太大，会直接走大对象分配无法模拟YGCbyte[] 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，如果太大，会直接走大对象分配无法模拟YGCbyte[] 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]
Heapgarbage-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 1056768Kclass space    used 376K, capacity 388K, committed 512K, reserved 1048576K

很明显是发生了两次GC的，并且两次GC之后Eden区的Region数量并没有发生变化。

4.打开实验选项查看YGC的详情日志信息

(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定为1Mpublic static void main(String[] args) throws Exception{//设定一个对象为256K，如果太大，会直接走大对象分配无法模拟YGCbyte[] 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.8Min: 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.2Min: 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.0Min: 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.2Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Processed Buffers:  0  0  0  0  0  0  0  0Min: 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.0Min: 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.0Min: 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.6Min: 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.4Min: 0.0, Avg: 0.4, Max: 0.4, Diff: 0.4, Sum: 2.8][Termination Attempts:  3  1  12  1  16  9  11  9Min: 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.0Min: 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.3Min: 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.1Min: 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.0Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Redirtied Cards:  0  0  0  0  0  0  0  0Min: 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.3Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Processed Buffers:  0  0  0  0  0  0  0  0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.4][Termination Attempts:  1  1  5  1  4  1  1  1Min: 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.0Min: 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.0Min: 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.3Min: 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.0Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Redirtied Cards:  67  0  0  0  0  0  0  0Min: 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]
//以下这个就是在我们程序运行结束之后，堆内存的使用状态
Heapgarbage-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 1056768Kclass 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，如果太大，会直接走大对象分配无法模拟YGCbyte[] 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)参数设置

具体参数如下：

 -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，如果太大，会直接走大对象分配无法模拟YGCbyte[] 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.3Min: 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.2Min: 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.0Min: 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.1Min: 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.0Min: 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.6Min: 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.3Min: 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.7Min: 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.0Min: 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.6Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.2][Processed Buffers:  2  1  1  0  0  1  0  0Min: 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.0Min: 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.0Min: 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.7Min: 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.1Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.7][Termination Attempts:  1  1  1  1  1  1  1  1Min: 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.0Min: 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.8Min: 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.4Min: 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.0Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Redirtied Cards:  4  0  0  0  0  0  0  0Min: 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.3Min: 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.7Min: 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)参数设置

具体参数如下：

 -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，如果太大，会直接走大对象分配无法模拟YGCbyte[] 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.8Min: 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 MB25M->25M(128M), 0.0010444 secs][Times: user=0.00 sys=0.00, real=0.00 secs]
//堆内存退出前的使用状态
Heapgarbage-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 1056768Kclass 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.8Min: 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.2Min: 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.0Min: 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.2Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 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.0Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Processed Buffers:  0  0  0  0  0  0  0  0Min: 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.0Min: 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.0Min: 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.6Min: 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.4Min: 0.0, Avg: 0.4, Max: 0.4, Diff: 0.4, Sum: 2.8][Termination Attempts:  3  1  12  1  16  9  11  9Min: 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.0Min: 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.3Min: 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.1Min: 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.0Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0][Redirtied Cards:  0  0  0  0  0  0  0  0Min: 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)参数设置

具体参数如下：这里先不打印详情，看看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，如果太大，会直接走大对象分配无法模拟YGCbyte[] 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。

文章转载自：东阳马生架构

原文链接：G1原理—7.G1的GC日志分析解读 - 东阳马生架构 - 博客园

体验地址：引迈 - JNPF快速开发平台_低代码开发平台_零代码开发平台_流程设计器_表单引擎_工作流引擎_软件架构