G1 原理—G1 的 GC 日志分析解读
作者：EquatorCoco
- 2025-01-15 福建
本文字数：41506 字
阅读完需：约 136 分钟
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.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:-UseLargePagesIndividualAllocation2.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: 0BTLAB: 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: 0BTLAB: 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: 0BTLAB: 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: 0BTLAB 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.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)参数设置
还是这么一套参数结构，主要是为了和前面做一些对比，看看模拟出来的 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给了survivorHeap 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:-UseLargePagesIndividualAllocation0.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)参数设置
具体参数如下：
-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定为1Mpublic 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)参数设置
具体参数如下：
-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定为1Mpublic 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初始标记后的并发标记阶段会和系统程序一起并发运行，所以这里是系统程序触发的YGC9.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 GC10.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分区，从这里的日志可以看出来，没有清理掉任何一个Region8.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)参数设置
具体参数如下：
-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:-UseLargePagesIndividualAllocation0.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分区，从这里的日志可以看出来，没有清理掉任何一个Region8.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，如果太大，会直接走大对象分配无法模拟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次YGC0.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次YGC0.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次YGC0.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次YGC0.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次YGC0.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次YGC0.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次YGC0.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区又一次填满，此时继续进入YGC0.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 GC0.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]
//触发YGC0.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 GC0.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 GC0.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。
文章转载自：东阳马生架构
划线
评论
复制
发布于: 刚刚阅读数: 4
EquatorCoco
关注
还未添加个人签名 2023-06-19 加入
还未添加个人简介
评论