G1原理—7.G1的GC日志分析解读
大纲1.TLAB的GC日志解读
2.YGC的GC日志解读
3.模拟YGC(单次GC及多次GC的不同场景)
4.打开实验选项查看YGC的详情日志信息
5.Mixed GC日志信息之初始标记过程
6.Mixed GC日志信息之混合回收过程
7.Mixed GC日志信息之Region的详细信息和标记过程的详细信息
8.FGC的日志信息及日志详情
1.TLAB的GC日志解读
(1)一套基本的参数设置
(2)针对这个参数设置写一套简单的Demo代码
(3)TLAB相关的运行日志
(1)一套基本的参数设置
首先参数上要有一套基本的设置：
-XX:InitialHeapSize=128M -XX:MaxHeapSize=128M -XX:+UseG1GC-XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTLAB-XX:+UnlockExperimentalVMOptions -XX:G1LogLevel=finest-XX:MaxGCPauseMillis=20 -Xloggc:gc.log堆内存的大小设置为128M是因为：G1本身的Region都要最小1M，总共就没有几个Region。如果设置成10MB这种值，不好做实验。
-XX:+UnlockExperimentalVMOptions这个参数是一个实验选项，打开以后才可以使用-XX:G1LogLevel这个参数，-XX:G1LogLevel=finest表示设置日志的输出级别为最详细级别。
(2)针对这个参数设置写一套简单的Demo代码
public class TLABDemo { private static final ArrayList<String> strs = new ArrayList<String>(); public static void main(String[] args) throws Exception { for (int n = 0 ;; n++) { //外层循环100次，每次内层循环创建10个字符串 for (int i = 0; i<100; i++) { //内层循环10次 for (int j = 0; j < 10; j++) { strs.add(new String("NO." + j + "Str" )); } } //无限循环，每次循环间隔0.1s System.out.println("第" + n + "次循环"); Thread.sleep(100); } }}这段代码的意思是：无限循环去创建字符串，放到一个list去。每次循环会执行1000次创建字符串，并把字符串加入到list的操作。通过这段代码，看看TLAB相关的GC日志信息。
(3)TLAB相关的运行日志
//这一部分是我们设置的一些参数信息CommandLine flags: -XX:G1LogLevel=finest -XX:InitialHeapSize=134217728 -XX:MaxGCPauseMillis=20 -XX:MaxHeapSize=134217728 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintTLAB -XX:+UnlockExperimentalVMOptions -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation2.236: desired_size: 122KB slow allocs: 0refill waste: 1960B alloc: 0.99996 6144KB refills: 1 waste1.4% gc: 1704B slow: 0B fast: 0BTLAB: gc thread: 0x00000000181fa000 desired_size: 122KB slow allocs: 2refill waste: 1960B alloc: 0.99996 6144KB refills: 3 waste 25.0% gc: 91168B slow: 3104B fast: 0BTLAB: gc thread: 0x00000000181bb000 desired_size: 122KB slow allocs: 2refill waste: 1960B alloc: 0.99996 6144KB refills: 7 waste2.0% gc: 13992B slow: 3624B fast: 0BTLAB: gc thread: 0x0000000003683800 desired_size: 122KB slow allocs: 6refill waste: 1960B alloc: 0.99996 6144KB refills: 41 waste0.1% gc: 0B slow: 7584B fast: 0BTLAB totals: thrds: 4refills: 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: desired_size: 122KB slow allocs: 0refill waste: 1960B alloc: 0.99996 6144KB refills: 1 waste1.4% gc: 1704B slow: 0B fast: 0Bgc thread：表示是哪个线程的TLAB。
desired_size：122KB指的是期望分配的TLAB的大小。这个值，其实就是我们前面讲解TLAB计算公式的时候，计算出来的值。TLABSize = Eden * 2 * 1% / 线程个数。
slow allocs：0，指的是慢速分配的次数。0说明每次都使用了TLAB快速分配，没有直接使用堆内存去分配。注意慢速TLAB分配也算是快速分配。
refill waste：1960B，代表可浪费的内存，也是重新申请一个TLAB的阈值。
alloc: 0.99996，表示当前这个线程在一个分区中分配对象占用的比例，Region使用的比例。
refills: 1，代表出现多少次废弃TLAB，重新申请一个TLAB的次数。refills次数为1表示只做了一次TLAB申请。每次废弃TLAB时，都会填充一个dummy对象。注意：refills的次数就是填充TLAB的次数，可理解为申请新的TLAB的次数。
waste 1.4% gc: 1704B slow: 0B fast: 0B，waste代表的是浪费的空间，这个浪费的空间分为三个层面：
一.gc表示：GC时还没有使用的TLAB的空间，现在正处于GC的状态中，TLAB还剩下多少空间没使用。
二.slow表示：申请新的TLAB时，旧的TLAB浪费的空间。这里就是0B，因为只产生了1次。
三.fast表示：在出现需要调整TLAB的大小时，即refill_waste不合理时，旧的TLAB浪费的空间，也就是dummy对象造成的浪费。
2.236: desired_size: 122KB slow allocs: 0refill waste: 1960B alloc: 0.99996 6144KB refills: 1 waste1.4% gc: 1704B slow: 0B fast: 0B 观察这个TLAB状态，refill次数还是非常有用的。refill次数可以帮助我们调整TLAB相关参数的设置，有助于优化性能。
比如，经过压测通过GC日志发现：当TLAB的大小设置成 1/4 RegionSize时会出现更少的TLAB动态调整情况，并且这个值能够保证大多数对象能够直接走TLAB分配。那么就可手动设置TLAB的大小，不使用G1自动推断的值，避免动态调整。因为自动调整是需要代价的，每次自动调整都会有一定的性能损耗。
2.YGC的GC日志解读
(1)参数设置
(2)沿用简单的Demo代码
(3)代码及YGC时机分析
(4)YGC相关的运行日志
(1)参数设置
对于YGC来说，我们只是要模拟YGC的整个过程。并且要打印出YGC整个过程的一些GC细节，所以才设置这么一套参数：
-Xmx256M -XX:+UseG1GC-XX:+PrintGCTimeStamps -XX:+PrintGCDetails-XX:MaxGCPauseMillis=20 -Xloggc:gc.log(2)沿用简单的Demo代码
public class TLABDemo { private static final ArrayList<String> strs = new ArrayList<String>(); public static void main(String[] args) throws Exception { for (int n = 0 ;; n++) { //外层循环100次，每次内层循环创建10个字符串 for (int i = 0; i<100; i++) { //内层循环10次 for (int j = 0; j < 10; j++) { strs.add(new String("NO." + j + "Str" )); } } //无限循环，每次循环间隔0.1s System.out.println("第" + n + "次循环"); Thread.sleep(100); } }}(3)代码及YGC时机分析
首先，运行这个代码时，没有设置新生代占用多少空间就会发生YGC，所以具体什么时候会发生YGC暂时不确定。
不过可以简单的思考YGC的发生时机，尤其是第一次。第一次发生YGC时，应该是256M * 5%的新生代被使用的时候。大概是这个值，当然，实际可能会比这个值略小一点。因为新生代第一次GC时Survivor区是没有存活对象的，并且堆内存会有一部分被其他的一些描述信息占用，所以256M堆内存不会全部都用来分配对象。程序运行一段时间后：大量字符串对象会填满Eden区，此时就会触发一次YGC。
(4)YGC相关的运行日志
可以看到，G1的GC日志看起来非常复杂，中间有非常复杂的处理步骤。比如，roots扫描，RS扫描等操作。每一步的操作都会有各自的耗时时长。接下来一步一步分析这个日志。
//这一部分是我们设置的一些参数信息CommandLine flags: -XX:InitialHeapSize=266064256 -XX:MaxGCPauseMillis=20 -XX:MaxHeapSize=268435456 -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC -XX:-UseLargePagesIndividualAllocation//从这里开始，出现了第一次GC，大概是在程序启动6.193s之后，停顿时间是0.0048641秒，也就是4.8ms左右；6.193: //这里很明显看到GC线程并行工作的时间是2.9ms，并且使用了8个GCWorkers线程；//因为此时电脑是8核的，不同的电脑，会有不同的结果，因为没有设置GC的GCParallelThreads线程数量的值； //这些是线程启动，GC Roots扫描，RSet扫描，对象拷贝等操作的一些耗时情况； //卡表更新 //大对象相关的操作时间 //在第一次GC之后，Eden区从使用12M，到使用0M，从总大小12M，到总大小10M，发生了动态变化；//Survivor区从0变为了2048K，也就是本次GC之后有2048K的对象存活下来；//堆内存从12M的使用量，降为了4424K的使用量，说明本次回收的效果还是不错的，基本上回收了百分之九十以上的垃圾； //第二次GC发生的时机，对于第二次GC，着重关注一下Eden Survivor 的大小，看看它是否有变化；17.261: //从这里并没有发现新生代的变化，说明此时还没有进行新生代的调整；//但是有一个现象，新生代使用从10MB降为了2048K，而堆内存，从14.9降为了12.9；//也就是说，本次只回收了2M左右的对象，那么肯定是有一部分对象进入了老年代分区的； 38.020: 58.728: 从多次GC的结果来看，新生代GC的情况相对比较稳定，每次的时长都在1ms左右(除了第一次时间比较长)，并且由于我们的代码是没有对象置为null的操作的，所以基本上所有的对象都能存活下来晋升到老年代。
3.模拟YGC(单次GC及多次GC的不同场景)
(1)参数设置
(2)模拟代码
(3)代码运行相关的GC日志
(4)接下来把代码改造一下
(5)观察GC日志
(1)参数设置
还是这么一套参数结构，主要是为了和前面做一些对比，看看模拟出来的GC场景是否符合前面对日志的解读。
-Xmx256M -XX:+UseG1GC -XX:+PrintGCTimeStamps -XX:+PrintGCDetails -XX:MaxGCPauseMillis=20 -Xloggc:gc.log(2)模拟代码
public class YGCDemo1 { //5% * 256 = 12M左右是第一次发生YGC的时机 //因为堆内存256M / 2048小于1，根据G1的处理，会把一个Region定为1M public static void main(String[] args) throws Exception { //设定一个对象为256K的原因，如果太大，会直接走大对象分配无法模拟YGC byte[] data = new byte; for (int i = 0; i< 36; i++) { data = new byte; } data = new byte; }}下面来解析一下代码：
一.首先第一段创建了一个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前，Eden区使用了12MB的内存，也就是12个Region；//在本次GC之后，Survivor从GC开始前的0使用量，到了2048K，也就是Survivor使用了2个Region//注意，这里不是说S区就有这么多的对象，而是S区总共使用了2个Region；//堆内存的使用，从12M最后变为了1120K，大概1M左右 //堆内存的最终使用状态是这样的，总共256MB，使用了3MB左右，region size是1MB，5个region给了新生代，两个region给了survivorHeapgarbage-first heap total 260096K, used 3168K (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; for (int i = 0; i< 36; i++) { data = new byte; } //创建n个对象，加入到一个list中，不回收这些数组； ArrayList list = new ArrayList(); for (int i = 0; i<= 36; i++) { byte[] data2 = new byte; //一部分字节数组加入到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; //一部分字节数组加入到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: 0.153: 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 1056768Kclass space used 376K, capacity 388K, committed 512K, reserved 1048576K 很明显是发生了两次GC的，并且两次GC之后Eden区的Region数量并没有发生变化。
4.打开实验选项查看YGC的详情日志信息
(1)参数设置
(2)模拟代码
(3)代码运行相关的GC日志
(4)问题
(1)参数设置
具体参数如下：
-Xmx256M -XX:+UseG1GC-XX:+PrintGCTimeStamps -XX:+PrintGCDetails-XX:+UnlockExperimentalVMOptions -XX:G1LogLevel=finest-XX:MaxGCPauseMillis=20 -Xloggc:gc.log在参数上没有什么特别的变化，主要是添加了两个参数。一个是开启实验选项，用于设置日志的输出级别，日志的输出级别设置为-XX:G1LogLevel=finest
(2)模拟代码
public class YGCDemo1FinestLog { //5% * 256 = 12M左右 //因为256M / 2048小于1 ，根据G1的处理，会把一个Region定为1M public static void main(String[] args) throws Exception{ //设定一个对象为256K，如果太大，会直接走大对象分配无法模拟YGC byte[] data = new byte; for (int i = 0; i< 36; i++) { data = new byte; } //创建n个对象，加入到一个list中，不回收这些数组 ArrayList list = new ArrayList(); for (int i = 0; i<= 36; i++) { byte[] data2 = new byte; //一部分字节数组加入到list中 if (i % 3 == 0) { list.add(data2); byte[] bigData1 = new byte; byte[] bigData2 = new byte; } //随机某次，我们把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; //一部分字节数组加入到list中 if (i % 3 == 0) { list.add(data2); byte[] bigData1 = new byte; byte[] bigData2 = new byte; } ... }代码运行中，这个地方会模拟出每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: //注意，下面这一行信息是说我们这8个线程开始的时间，min表示最早开始的线程时间，avg表示平均开始时间，max表示最晚开始时间，diff表示最早和最晚的时间差，这个diff越大就说明线程启动时间越不均衡，一般这个地方的时间不会差别很大； //8个线程对根(GC Roots)扫描处理的时间，可以注意到，根的类型非常多。除了经常说的Java静态变量、方法局部变量外还有很多其他的一些根 //更新RSet的操作，前面提过要先更新RSet后，再进行RSet的扫描，其实在这个日志里就能看的出来；//对象引用关系更新之后，要通过Refine线程 + 系统程序的线程 + DCQ更新RSet//下面显示的是GC线程时间都为0.0，说明这块更新没问题//因为引用更新导致RSet更新的这些操作，都已经由Refine线程提前处理完了； //扫描RSet，处理存活对象； //这一步很关键，对象拷贝，就是把存活对象拷贝到一个新的分区，可以看出来，拷贝消耗的时间非常长；//注意：对象拷贝消耗的时间占了GC绝大部分的时间 //GC线程关闭的一些信息 //GC线程的一些其他工作的处理时间，通常是JVM析构释放资源 //并行GC过程花费的总体时间； //清理卡表 //选择Cset时间，对YGC来说，一般都是0，因为不需要选 //重构RSet花费的时间 //大对象的处理时间 //如果大对象要回收，回收花费的时间以及回收了多少个大对象 //释放CSet中的分区花费的时间 //本次回收之后，Eden区和Survivor区的状态 0.199: //以下这个就是在我们程序运行结束之后，堆内存的使用状态Heap garbage-first heap total 260096K, used 15133K (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; for (int i = 0; i< 36; i++) { data = new byte; } //创建n个对象，加入到一个list中，不回收这些数组 ArrayList list = new ArrayList(); for (int i = 0; i<= 36; i++) { byte[] data2 = new byte; //一部分字节数组加入到list中 if (i % 3 == 0) { list.add(data2); byte[] bigData1 = new byte; byte[] bigData2 = new byte; } //随机某次把list直接清空掉，最终可能会留下一些存活对象 //这块主要是模拟程序正常运行过程中对象可能会被回收 if (i % Math.random()*10 == 0) { list.clear(); } } }}
5.Mixed GC日志信息之初始标记过程
(1)参数设置
(2)模拟代码
(3)代码运行相关的GC日志
(1)参数设置
具体参数如下：
-Xmx256M -XX:+UseG1GC-XX:+PrintGCTimeStamps -XX:+PrintGCDetails-XX:+UnlockExperimentalVMOptions-XX:G1LogLevel=finest -XX:MaxGCPauseMillis=20 -Xloggc:gc.log 在参数上没有什么特别的变化，主要是添加了两个参数。一个是开启实验选项，用于设置日志的输出级别，日志的输出级别设置为-XX:G1LogLevel=finest
(2)模拟代码
private static final ArrayList list = new ArrayList();//5% * 256 = 12M左右//因为256M / 2048小于1，根据G1的处理，会把一个Region定为1Mpublic static void main(String[] args) throws Exception { while(true) { //设定一个对象为256K，如果太大，会直接走大对象分配无法模拟YGC byte[] data = new byte; for (int i = 0; i< 36; i++) { data = new byte; } //创建n个对象，加入到一个list中，不回收这些数组 for (int i = 0; i<= 36; i++) { byte[] data2 = new byte; //一部分字节数组加入到list中 if (i % 2 == 0) { list.add(data2); byte[] bigData1 = new byte; } } 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; }代码运行中，这个地方模拟出，每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: // 启动了8个线程去执行，并且并行的执行时间1.2ms ... ...//从这里可以看出，这次GC是一次非常常规的YGC，GC之前，S区没有，GC之后，下一次S区是1个，也就是1M的空间；//堆内存在回收前是6144K垃圾，回收后是1048K垃圾 //第二次回收，我们着重看一下对象的增涨速度0.180: ... ...//从下面这里可以看到：//对象增涨的速度其实并不快，并且Eden区的个数，调大了一个 //接下来省略很多次普通的YGC，YGC的过程没必要放出来了，因为太多了；............//到了这次YGC，依然是很正常的YGC，还是常规的YGC结果；7.289: ... ...//注意这里，此时堆内存的使用已经非常多了；//Eden区在回收以后是0B，S区扩展到了6M左右，堆内存总使用量47.5M，此时这个使用量其实已经比较高了； //重点看这里，发现已经开启了初始标记(可见此时也还是一次YGC)；8.309: ... ...//从这次回收之后的数据可以看到，确实是遵循45%这个规则；//YGC垃圾回收后，即将分配的对象 + 老年代的所有对象占用的空间达到了45%时，就会触发Mixed GC，也就是开启并发标记； //并发根扫描的开始和结束8.311: 8.311: //并发标记的开始和结束8.311: 8.313: //重新标记阶段8.313: 8.313: 8.313: 8.313: 8.314: , 0.0006416 secs], 0.0014267 secs] //预清理阶段8.314: //又进行了一次YGC，因为Mixed GC初始标记后的并发标记阶段会和系统程序一起并发运行，所以这里是系统程序触发的YGC9.331: ... ... //接下来才是打印触发的Mixed GC10.347: ... ... 10.350: ... ... //又出现了一次Mixed GC的初始标记10.353: ... ... 10.354: 10.354: 10.354: 10.356: 10.356: 10.357: 10.357: 10.357: 10.357: , 0.0006318 secs], 0.0014424 secs] 10.358:
6.Mixed GC日志信息之混合回收过程
继续前面的Mixed GC日志分析：
...//到了这次YGC，依然是很正常的YGC；7.289: ...//注意，此时堆内存的使用已经非常多了；//Eden区在回收以后，是0B，S区扩展到了6M左右，堆内存总使用量47.5M，此时这个使用量其实已经比较高了； //接下来这里，发现已经开启了初始标记；8.309: ...//这次回收之后的数据如下一行所示；//从数据中可以看到，确实是遵循45%这个规则来的；//垃圾回收后，即将分配的对象 + 老年代的所有对象占用的空间达到了45%的时候，就会触发Mixed GC，也就是开启并发标记； //从这里也可以看出来，初始标记状态，其实就是一次YGC，但是需要注意的是，初始标记之后，并不一定会执行Mixed GC//初始标记之后会进入并发标记；//下面这几行实际上做的是从YHR中的Survivor分区开始进行并发标记的GC Roots扫描；//可以理解成，找到Survivor区的所有存活对象，并作为根对象，这一部分还没有对GC Roots直接引用的老年代对象做扫描8.311: //扫描结束，用时0.0000467秒，这个扫描过程需要注意的是：它是和应用程序同时进行的，并且有多个线程参与8.311: //并发标记的全量扫描过程，就是以Survivor + GC Roots(方法栈里面的局部变量，静态变量等)，标记整个堆里面的所有存活对象8.311: //并发标记结束，花费了0.0018565秒8.313: //最终标记阶段，标记程序创建出来的新对象，软引用、弱引用等的处理；8.313: 8.313: 8.313: 8.313: 8.314: , 0.0006416 secs], 0.0014267 secs] //预清理处理，这个地方清除的是全部都是垃圾的那些Region分区，从这里的日志可以看出来，没有清理掉任何一个Region8.314: //紧接着，又进入了YGC(此时S区不足需要清空S区)；//而且是标明了to-space exhausted，这说明to区在本次GC之后不够用了，要做一些对象升入老年代的操作，调整S区大小9.331: ... ...//这里可以看出来，在本次回收之后，S区已经变成了0了 //然后开始进入混合回收阶段，混合回收的内容和YGC的内容其实差不多10.347: //并行时间1.2ms，8个线程参与 //由上述可见，Mixed GC的回收阶段的过程和YGC几乎一模一样，什么原因呢？//其实就是复用了代码，然后主要的区别在于选择的Cset不同//下面又是一次Mixed GC，因为会分批次，默认最多分8次10.350: ... ... //又一次触发了初始标记//其实看到这里触发初始标记，也可以大概猜到，后续的Mixed GC也会非常频繁，并且初始标记也会经常发生，因为老年代的存活对象太多了；10.353: ... ... 10.354: 10.354: 10.354: 10.356: 10.356: 10.357: 10.357: 10.357: 10.357: , 0.0006318 secs], 0.0014424 secs] 10.358: Mixed GC的过程相对复杂。在触发了初始标记以后，并不一定紧跟的就是Mixed GC的回收阶段。有可能会继续进行YGC的过程，然后才进入Mixd GC的回收阶段。
由此可见，对于Mixed GC来说：从初始标记到并发标记到回收阶段整个流程，不一定是连续的整个流程。因为在并发标记阶段程序会运行，接下来有可能再触发一次YGC。并且在可回收的垃圾不足5%时，也不会触发Mixed GC的回收阶段。同时如果进行了多次GC后，小于了这个5%，也可能不继续进行混合回收。当然这个5%不太好模拟，如果是线上的程序其实更好模拟一些。
7.Mixed GC日志信息之Region的详细信息和标记过程的详细信息
(1)参数设置
(2)模拟代码
(3)代码运行相关的GC日志
(4)这些数据有什么作用
(1)参数设置
具体参数如下：
-Xmx128M -XX:+UseG1GC-XX:+PrintGCTimeStamps -XX:+PrintGCDetails-XX:+UnlockExperimentalVMOptions -XX:G1LogLevel=finest-XX:+UnlockDiagnosticVMOptions -XX:+G1PrintRegionLivenessInfo-XX:+G1SummarizeConcMark -XX:MaxGCPauseMillis=20-Xloggc:gc.log和前面设置的JVM参数有区别的是如下这几个：
打开数据分析选项：-XX:+UnlockDiagnosticVMOptions打印所有的region的使用详情信息：-XX:+G1PrintRegionLivenessInfo打开并发标记的详细信息：-XX:+G1SummarizeConcMark(2)模拟代码
public static void main(String[] args) throws Exception { while(true) { //设定一个对象为256K，如果太大，会直接走大对象分配无法模拟YGC byte[] data = new byte; for (int i = 0; i< 36; i++) { data = new byte; } //创建n个对象，加入到一个list中，不回收这些数组 for (int i = 0; i<= 36; i++) { byte[] data2 = new byte; //一部分字节数组加入到list中 if (i % 2 == 0) { list.add(data2); byte[] bigData1 = new byte; } } 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: ... ... 0.132: 0.133: 0.133: 0.133: 0.133: 0.134: 0.134: 0.134: 0.134: , 0.0005701 secs], 0.0016329 secs] 0.135: //堆内存退出前的使用状态Heap garbage-first heap total 131072K, used 65513K 2final marks: total time = 0.00 s (avg = 0.21 ms). 2 weak refs: total time = 0.00 s (avg = 1.14 ms). 2 cleanups: total time = 0.00 s (avg = 0.78 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: //注意，下面这一行信息是说我们这8个线程开始的时间，min表示最早开始的线程时间，avg表示平均开始时间，max表示最晚开始时间，diff表示最早和最晚的时间差，这个diff越大就说明线程启动时间越不均衡，一般这个地方的时间不会差别很大； //8个线程对根(GC Roots)扫描处理的时间，可以注意到，根的类型非常多，除了经常说的Java静态变量、方法局部变量外还有很多其他的一些根 //更新RSet的操作，前面提过要先更新RSet后，再进行RSet的扫描，其实在这个日志里就能看的出来； //对象引用关系更新之后，要通过Refine线程 + 系统程序的线程 + DCQ更新RSet //下面显示的是GC线程时间都为0.0，说明这块更新没问题 //因为引用更新导致RSet更新的这些操作，都已经由Refine线程提前处理完了； //扫描RSet，处理存活对象； //这一步很关键，对象拷贝，就是把存活对象拷贝到一个新的分区，可以看出来，拷贝消耗的时间非常长； //注意：对象拷贝消耗的时间占了GC绝大部分的时间 //GC线程关闭的一些信息 //GC线程的一些其他工作的处理时间，通常是JVM析构释放资源 //并行GC过程花费的总体时间； //清理卡表 //选择Cset时间，对YGC来说，一般都是0，因为不需要选 //重构RSet花费的时间 //大对象的处理时间 //如果大对象要回收，回收花费的时间以及回收了多少个大对象 //释放CSet中的分区花费的时间 //Mixed GC各阶段耗时//初始标记之后会进入并发标记；//下面这几行实际上做的是从YHR中的Survivor分区开始进行并发标记的GC Roots扫描；//可以理解成，找到Survivor区的所有存活对象，并作为根对象，这一部分还没有对GC Roots直接引用的老年代对象做扫描8.311: //扫描结束，用时0.0000467秒，这个扫描过程需要注意的是：它是和应用程序同时进行的，并且有多个线程参与8.311: //并发标记的全量扫描过程，就是以Survivor + GC Roots(方法栈里面的局部变量，静态变量等)，标记整个堆里面的所有存活对象8.311: //并发标记结束，花费了0.0018565秒8.313: //最终标记阶段，标记程序创建出来的新对象，软引用、弱引用等的处理；8.313: 8.313: 8.313: 8.313: 8.314: , 0.0006416 secs], 0.0014267 secs] //预清理处理，这个地方清除的是全部都是垃圾的那些Region分区，从这里的日志可以看出来，没有清理掉任何一个Region8.314:
8.FGC的日志信息及日志详情
(1)参数设置
(2)模拟代码
(3)代码运行相关的GC日志
(4)总结
(1)参数设置
具体参数如下：这里先不打印详情，看看Full GC出现的时候是什么时候。
-XX:InitialHeapSize=36M -XX:MaxHeapSize=36M-XX:G1HeapRegionSize=4M-XX:MaxGCPauseMillis=20-XX:+PrintGC -XX:+PrintGCTimeStamps -XX:+UseG1GC-Xloggc:gc.log(2)模拟代码
public class FGCDemo12 { private static final ArrayList list = new ArrayList(); public static void main(String[] args) throws Exception { while(true) { //设定一个对象为256K，如果太大，会直接走大对象分配无法模拟YGC byte[] data = new byte; for (int i = 0; i< 36; i++) { data = new byte; } //创建n个对象，加入到一个list中，不回收这些数组 for (int i = 0; i<= 36; i++) { byte[] data2 = new byte; // 一部分字节数组加入到list中 list.add(data2); } Thread.sleep(1000); } }}(3)代码运行相关的GC日志
一.不加打印详情的时候，GC信息如下：
0.160: 0.163: 0.165: 0.167: 0.171: 0.174: 0.176: 0.179: 0.183: 0.184: 0.190: 0.193: 0.194: 0.195: 0.195: 0.195: //第一次Full GC压缩出1M的空间，从23M到22M；第二次Full GC没法压缩出空间了0.195: 0.201: //终止并发标记0.204: 0.204: 0.205: 0.206: 0.206: 0.206: //在并发标记开始时，进入了Full GC，并且进行了两次Full GC，最终并发标记终止，抛出了OOM异常；//说明我们对Full GC的分析是正确的，会分两次GC，第一次不处理软引用，第二次处理；0.206: 0.208: 0.210: 二.修改参数为打印日志详情：
-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: ... //第2次YGC0.166: ... //第3次YGC0.168: ... //第4次YGC0.170: ... //第5次YGC0.173: ... //第6次YGC0.178: ... //第7次YGC0.181: ... //第8次YGC 0.183: ... //第9次YGC，但在这里开启了Mixed GC的初始标记，然后紧接着进入了并发标记阶段0.187: ... //进入Mixed GC的并发标记阶段之后，开始并发标记时，直接进入了Full GC状态0.189: 0.189: 0.189: //可以看到Full GC第一次进行时，还是回收了一些垃圾的，并且对堆内存进行了整理；//在Full GC之后，就没有Eden区、Survivor区的具体细节了；//因为Full GC结束后，会把所有分区标记成Old，然后再重新选择一些Region成为Eden区；0.189: , //然后此时并发标记就直接终止，不再进行了；0.194: //程序运行一段时间后，Eden区又一次填满，此时继续进入YGC0.194: ...//注意：在Full GC之后，Eden区还是一个Region，并且此次YGC之后，没有回收掉任何垃圾； //接着程序继续运行，只能再此触发第一次的Full GC，并且仅仅压缩整理出了1M的空间0.195: , //然后再此触发第二次的Full GC，此次回收会把软引用进行处理；//而我们的程序没有软引用，所以此次Full GC也无法腾出足够的空间；0.198: , //然后再次进入YGC，因为Eden区为0，此时再次尝试分配失败0.200: ... //然后再次进入YGC，开启Mixed GC的初始标记0.201: ... 0.202: 0.202: 0.202: 0.202: , //触发Full GC0.209: , //终止Mixed GC的并发标记0.211: //触发YGC0.211: ... ////然后再次进入YGC，开启Mixed GC的初始标记0.212: ... 0.213: 0.213: 0.213: //触发第一次Full GC0.213: , //触发第二次Full GC0.216: , //终止Mixed GC的并发标记0.218: 最终经过多次尝试之后，无法分配，只能OOM。可以看到G1对于OOM其实是比较慎重的。经过很多次YGC并发标记，多次FGC的过程后，才最终抛出OOM异常。所以并不是两次FGC失败之后就进入OOM了。
注意：FGC结束后，会把所有分区标记成Old，然后再重新选择一些Region成为Eden区。
(4)总结
使用G1时发生FGC要比使用ParNew + CMS时发生FGC更加困难，并且尝试的次数日志上来看也非常多。FGC的整个过程比较简单粗暴，如果实在无法压缩出空间，就会OOM。
页:
[1]