阿狗工具
CMS算法实现 - 4
2024-04-10 12:40:05 阅读数 420
从年轻代和老年代的collect方法的调用方出发，来总结GC是如何被触发的。
1、GenCollectedHeap::do_collection
do_collection方法是调用各Genaration的collect方法的直接上层方法，其主要流程如下：
image.png
其中计算start_level的逻辑如下：
image.png
DefNewGeneration采用父类Generation的默认实现，返回false，ConcurrentMarkSweepGeneration的实现如下，在默认配置下该方法返回true，即full为true，max_level为1的时候，start_level也为1，max_level是方法入参，表示执行GC的最大level。
//UseCMSCompactAtFullCollection默认为true，表示FullGC时所使用Mark-Sweep-Compact算法
//CollectGen0First默认为false，表示是否在FullGC前收集年轻代
virtual bool full_collects_younger_generations() const {
return UseCMSCompactAtFullCollection && !CollectGen0First;
}
其中是否complete的判断逻辑如下：
bool complete = full && (max_level == (n_gens()-1));
int max_level_collected = starting_level;
complete = complete || (max_level_collected == n_gens() - 1);
即只要max_level等于1的时候complete就为true，如果为1则为false。
补充说明如下：
- 将Reference实例链表中剩余的Reference实例加入pending列表只适用于堆内存压缩式GC，正常的前台GC和后台GC都是在FinalMarking环节完成了该操作。
- 在各Genaration执行gc_epilogue时都会清理ChunkPool，在do_collection中还执行了一遍，主要是释放do_collection方法本身占用的ChunkPool内存。
- 通过老年代collect方法触发的堆内存压缩和前台GC都不会执行compute_new_size方法，该方法就是后台GC的Resizing步骤的核心，会根据当前占用的内存和配置的内存最大空闲率，内存最小空闲率来做必要的扩容和缩容。
- 如果start_level为0时，年轻代GC完成后会将size置为0，当进入老年代的should_collect方法时，因为size为0，该方法返回false，就不会触发老年代的GC。什么情况下start_level为0了？full为false时或者full为true，max_level为0时。
- 结合上面start_level的分析，可知max_level为1的时候，full为false时do_collection只调用年轻代GC，full为true时实际只调用老年代GC，当max_level为0的时候只调用年轻代的collect方法，虽然代码中是循环调用start_level到max_level之间的Genaration的collect方法，但是实际只调用一次。
2、CollectedHeap::collect_as_vm_thread
collect_as_vm_thread方法是给VMThread使用的执行GC的内部方法，该方法假定已经获取了Heap_lock锁，其实现如下：
void CollectedHeap::collect_as_vm_thread(GCCause::Cause cause) {
//校验是VMThread
assert(Thread::current()->is_VM_thread(), "Precondition#1");
//校验获取了Heap_lock
assert(Heap_lock->is_locked(), "Precondition#2");
//临时设置GCCause
GCCauseSetter gcs(this, cause);
switch (cause) {
case GCCause::_heap_inspection: //表示打印堆内存中包含的类的直方图
case GCCause::_heap_dump: //堆内存dump
case GCCause::_metadata_GC_threshold : { //表示元空间内存分配失败
HandleMark hm;
do_full_collection(false); //false表示不需要清除软引用
break;
}
case GCCause::_last_ditch_collection: { //执行过do_full_collection(false)后再次尝试从元空间分配内存，分配失败后就尝试扩容再分配，依然失败就会使用这个GCCause
HandleMark hm;
do_full_collection(true); //true表示清除软引用
break;
}
default:
ShouldNotReachHere(); // Unexpected use of this function
}
}
void GenCollectedHeap::do_full_collection(bool clear_all_soft_refs,
int max_level) {
int local_max_level;
if (!incremental_collection_will_fail(false /* don't consult_young */) &&
gc_cause() == GCCause::_gc_locker) {
local_max_level = 0;
} else {
local_max_level = max_level;
}
do_collection(true /* full */,
clear_all_soft_refs /* clear_all_soft_refs */,
0 /* size */,
false /* is_tlab */,
local_max_level /* max_level */);
if (local_max_level == 0 && gc_cause() == GCCause::_gc_locker &&
incremental_collection_will_fail(false /* don't consult_young */)) {
if (PrintGCDetails) {
gclog_or_tty->print_cr("GC locker: Trying a full collection "
"because scavenge failed");
}
//如果老年代空间不足，则回收老年代
do_collection(true /* full */,
clear_all_soft_refs /* clear_all_soft_refs */,
0 /* size */,
false /* is_tlab */,
n_gens() - 1 /* max_level */);
}
}
在collect_as_vm_thread场景下do_full_collection方法实际就只执行do_collection，其中full为true，max_level就是1，即只回收老年代。collect_as_vm_thread的调用链如下：
image.png
3、VM_CollectForMetadataAllocation
VM_CollectForMetadataAllocation是元空间内存分配失败后触发GC的实现，参考其构造方法的调用链，如下：
image.png
该类的核心doit方法的主流程如下：
image.png
补充说明如下：
- 上述步骤中每次尝试分配成功后就会立即返回，分配失败则继续走下一步。第一步尝试直接分配而不是触发GC是因为一旦元空间不足了，可能会触发多个线程执行VM_CollectForMetadataAllocation，但是VMThread一次只处理一个，即存在其他线程已经触发GC释放了足够的内存，所以这里再做一次尝试分配。
- 第二步判断时，只有CMS算法和G1算法在GC时会卸载Klass，这两种算法在默认配置下返回true，其他的返回false。以CMS的实现为例，在调用该方法判断时，会将MetaspaceGC的_should_concurrent_collect属性置为false，CMSCollector::shouldConcurrentCollect()方法返回true，CMS Thread开始执行老年代的后台GC并将_should_concurrent_collect置为true，即此时CMS Thread与VMThread在并行执行，CMS Thread可能已经释放了一部分内存，所以该判断返回true以后，会多尝试一次元空间扩容再分配。
- 此场景下触发的老年代GC执行完后，元空间也会执行compute_new_size，即会根据GC后的元空间内存占用量做必要的扩容或者缩容，一般不会是最大容量，所以在GC完成后直接尝试内存分配失败会再尝试扩容元空间并分配。
- 清除软引用本身释放的内存并不多，所以第一次时并不清除，而是在第一次不清楚的情况下依然分配失败了才会考虑清除软引用，这里的清除是指全部清除，即使是刚创建不久的，默认情况下一段时间内不再访问的软引用本身会被自动清除，这个时间在默认配置下是由根据上一次GC后的堆内存计算出来的最大空间内存计算出来的。
- satisfy_failed_metadata_allocation方法是在一个while(true)循环里执行VM_CollectForMetadataAllocation的，即会不断的GC直到内存分配成功，上述流程的最后一步实际就是通知satisfy_failed_metadata_allocation方法GC后内存依然不足，然后重新触发下一轮的VM_CollectForMetadataAllocation调用。
4、GenCollectedHeap::collect
该方法主要用于JNI场景下触发GC，其调用链如下：
image.png
第一个方法是最后一个从JNI关键区退出的线程触发GC，调用入参是GCCause::_gc_locker，第二个是System.gc()的底层实现，调用入参是GCCause::_java_lang_system_gc，第三个方法是从命令行触发GC的实现，调用入参也是GCCause::_java_lang_system_gc，最后两个都是用于白盒测试的WhiteBox类的native方法，调用入参分别是GCCause::_last_ditch_collection和GCCause::_wb_young_gc。
该方法的实现如下：
void GenCollectedHeap::collect(GCCause::Cause cause) {
//在默认配置下，should_do_concurrent_full_gc返回false
if (should_do_concurrent_full_gc(cause)) {
collect_mostly_concurrent(cause);
} else if (cause == GCCause::_wb_young_gc) {
collect(cause, 0);
} else {
collect(cause, n_gens() - 1);
}
}
bool GenCollectedHeap::should_do_concurrent_full_gc(GCCause::Cause cause) {
//UseConcMarkSweepGC表示使用CMS GC算法,GCLockerInvokesConcurrent的默认值为false,表示从JNI关键区中退出时是否触发后台GC
//ExplicitGCInvokesConcurrent的默认值也是false,表示调用System.gc时是否触发后台GC
return UseConcMarkSweepGC &&
((cause == GCCause::_gc_locker && GCLockerInvokesConcurrent) ||
(cause == GCCause::_java_lang_system_gc && ExplicitGCInvokesConcurrent));
}
void GenCollectedHeap::collect(GCCause::Cause cause, int max_level) {
assert(!Heap_lock->owned_by_self(), "this thread should not own the Heap_lock");
//获取Heap_lock
MutexLocker ml(Heap_lock);
collect_locked(cause, max_level);
}
void GenCollectedHeap::collect_locked(GCCause::Cause cause, int max_level) {
//获取GC前的gc次数
unsigned int gc_count_before = total_collections();
unsigned int full_gc_count_before = total_full_collections();
{
//此方法通常都是JavaThread调用的，因此需要通过VM_Operation和VMThread来执行GC
//执行完大括号包含的逻辑后自动释放Heap_lock
MutexUnlocker mu(Heap_lock); // give up heap lock, execute gets it back
VM_GenCollectFull op(gc_count_before, full_gc_count_before,
cause, max_level);
VMThread::execute(&op);
}
}
实际触发GC通过VM_GenCollectFull类完成，其关键doit方法的实现如下：
void VM_GenCollectFull::doit() {
SvcGCMarker sgcm(SvcGCMarker::FULL);
GenCollectedHeap* gch = GenCollectedHeap::heap();
GCCauseSetter gccs(gch, _gc_cause);
gch->do_full_collection(gch->must_clear_all_soft_refs(), _max_level);
}
bool GenCollectedHeap::must_clear_all_soft_refs() {
return _gc_cause == GCCause::_last_ditch_collection;
}
综上，只有GCCause::_wb_young_gc触发年轻代GC，其他场景都是触发老年代GC，并且只有WB_FullGC时会清理所有的软引用，其他的都不清理。
5、mem_allocate_work
mem_allocate_work是Java堆对外内存分配的底层入口，其调用链如下：
image.png
代码实现可以参考垃圾回收之CollectorPolicy ，主要流程如下：
image.png
其中判断是否在老年代尝试内存分配的实现如下：
//如果first_only为true则只在年轻代分配，如果分配失败则直接返回NULL,不再尝试
//在老年代分配，否则会再次尝试在老年代分配
bool first_only = ! should_try_older_generation_allocation(size);
bool GenCollectorPolicy::should_try_older_generation_allocation(
size_t word_size) const {
GenCollectedHeap* gch = GenCollectedHeap::heap();
size_t gen0_capacity = gch->get_gen(0)->capacity_before_gc();
//只有这三个条件都为false，first_only才会为true，只要有一个条件为true，first_only为false
return (word_size > heap_word_size(gen0_capacity))
|| GC_locker::is_active_and_needs_gc() //如果后台GC被触发了且有线程处于JNI关键区返回true
|| gch->incremental_collection_failed(); //老年代空间不足导致前一次的年轻GC promote失败，返回true
}
即如果first_only为true时会触发年轻代GC，否则会尝试在老年代分配，如果分配失败触发老年代GC。
判断是否有扩展空间的实现如下：
//只要有一个Generation有扩展空间，则返回false，表示有扩展空间
bool GenCollectedHeap::is_maximal_no_gc() const {
for (int i = 0; i < _n_gens; i++) {
if (!_gens[i]->is_maximal_no_gc()) {
return false;
}
}
return true;
}
//返回true，表示无扩展空间，返回false表示有扩展空间
virtual bool is_maximal_no_gc() const {
//uncommitted_size表示还未向操作系统申请分配内存的容量
return _virtual_space.uncommitted_size() == 0;
}
补充说明如下：
- 上述流程中，每一次尝试分配，如果分配成功则会直接返回，如果都分配失败则会开始下一次循环
- 如果有线程处于JNI关键区且后台GC被触发了，此时如果待分配的内存用于TLAB，则直接返回NULL，调用方会重新调用此方法尝试分配；此时如果当前线程就处于JNI关键区中则直接返回NULL，从而让该线程从关键区中退出，如果不在JNI关键区中则阻塞直到所有线程从JNI关键区中退出，最后一个退出的线程会触发GC。
- 上述for循环是有次数限制的的，一旦full GC即老年代的GC次数超过AdaptiveSizePolicyGCTimeLimitThreshold，默认值是5，JVM会认为系统内存不足然后抛出异常终止Java进程，full GC执行完成后会通过check_gc_overhead_limit方法检查是否超过限制，如果是则将_gc_overhead_limit_exceeded置为true，参考set_gc_overhead_limit_exceeded方法的调用链，如下：
image.png
mem_allocate_work判断该属性为true后终止循环，通知调用方次数超了后将该属性重置为false，最后返回NULL，外层调用方识别full GC次数超了依然分配失败抛出异常。
6、VM_GenCollectForAllocation
VM_CollectForMetadataAllocation是从元空间分配内存失败时触发GC的实现，VM_GenCollectForAllocation与之对应，是从Java堆分配内存失败触发GC的实现，其调用链如下：
image.png
其核心doit方法的实现如下：
void VM_GenCollectForAllocation::doit() {
SvcGCMarker sgcm(SvcGCMarker::MINOR);
GenCollectedHeap* gch = GenCollectedHeap::heap();
//临时设置gc_cause属性
GCCauseSetter gccs(gch, _gc_cause);
_result = gch->satisfy_failed_allocation(_word_size, _tlab);
assert(gch->is_in_reserved_or_null(_result), "result not in heap");
if (_result == NULL && GC_locker::is_active_and_needs_gc()) {
//如果GC后分配失败，则设置标识通知调用方GC后分配失败，需要再次GC
set_gc_locked();
}
}
HeapWord* GenCollectedHeap::satisfy_failed_allocation(size_t size, bool is_tlab) {
return collector_policy()->satisfy_failed_allocation(size, is_tlab);
}
GenCollectorPolicy::satisfy_failed_allocation的实现可以参考, 其主要流程如下：
image.png
补充说明如下：
- 正常情况下进入satisfy_failed_allocation前会检查是否有线程处于JNI关键区，如果有则阻塞直到最后所有线程从JNI关键区中退出，但是并发下不排除从JNI关键区退出后到VMThread开始执行VM_CollectForMetadataAllocation时又有新的线程进入到JNI关键区中，所以在开始处做了一道检查，此时如果有未扩展的空间则尝试扩展并分配，如果分配失败直接返回NULL
- 上述流程中尝试分配都是先尝试在年轻代分配，如果分配失败，再尝试在老年代分配
- 正常情况下内存分配失败会触发年轻代的GC，如果老年代内存充足，年轻代GC顺利完成，则下一步直接分配内存成功顺利返回；如果老年代内存不足，年轻代GC执行因为promote会失败而终止，这时下一步直接分配内存，年轻代肯定内存不足，通常就在老年代分配了，这种情形下虽然分配成功了，但是年轻代并没有GC，等下一次再进入该方法时，就会触发老年代的GC但是不清除软引用，老年代GC完成，正常这种情形下也是会在老年代分配，注意此时年轻代GC还未执行；再下一次进入该方法时就会触发年轻代的GC，因为上一次的老年代GC已经回收了足够的空间，可以正常执行年轻代GC了，然后正常从年轻代分配内存。上述分析中如果在老年代分配内存失败了，则会触发清理软引用的老年代GC，GC完成后尝试分配内存，如果还是失败则会循环多执行几次，直到超过full GC的次数限制。
7、 Debug日志分析
可以通过在源码中增加调试日志然后重新编译的的方式来进一步深入了解程序的运行逻辑，测试用例如下：
import java.util.Date;
import java.util.HashSet;
import java.util.Set;
public class CMSTest {
public static void main(String[] args) {
Set<Object> obj=new HashSet<>(10000);
int count=1;
for(int i=0;i<100000000;i++){
long start=new Date().getTime();
long[] a=new long[1000000];
long time=new Date().getTime()-start;
System.out.println("create long[] end,time->"+time+",count="+count+",now->"+new Date());
if(time>10){
//如果超过10ms，就意味着发生了young GC，之前创建的对象会promote到老年代
//此处clear则老年代GC时又会将这些promote到老年代的对象清理掉
obj.clear();
try {
Thread.sleep(25000);
count=0;
} catch (Exception e) {
}
}
obj.add(a);
count++;
}
}
}
启动脚本如下：
/home/openjdk/cppTest/bin/java -server -Xmx256M -Xms128M -XX:+UseConcMarkSweepGC -Xloggc:/home/openjdk/cppTest/gc.log -XX:+PrintGC -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCID -XX:+Verbose -XX:+TraceCMSState CMSTest
注意/home/openjdk/cppTest/bin/java指向的是我们自己编译源码后生成的java命令，debug版的，而不是正常的生产版本的。上述参数中Verbose是专门用于调试的，会打印更加信息的日志，TraceCMSState是跟踪CMS 老年代GC时的状态流转。通过sudo nohup sh cmsTest.h >./cms.log 2>&1 &命令可启动上述程序的运行，cms.log输出程序的控制台日志，gc.log打印gc的日志。
为了跟踪对象的分配，在分配内存的入口方法CollectedHeap::common_mem_allocate_noinit中加了如下日志：
image.png
同时也在年轻代的should_allocate方法和老年代的should_collect方法增加日志，如果不走TLAB走堆内存分配就会进入这两个方法，日志如下：
image.png
image.png
截取gc.log中一个完整的GC过程的日志说明如下：
OpenJDK 64-Bit Server VM (25.71-b00-debug) for linux-amd64 JRE (1.8.0-internal-root_2019_05_27_19_56-b00), built on Mar 8 2020 11:57:16 by "root" with gcc 4.4.7 20120313 (Red Hat 4.4.7-4)
Memory: 4k page, physical 4194304k(1280560k free), swap 0k(0k free)
CommandLine flags: -XX:InitialHeapSize=134217728 -XX:MaxHeapSize=268435456 -XX:MaxNewSize=89481216 -XX:MaxTenuringThreshold=6 -XX:NewSize=89481216 -XX:OldPLABSize=16 -XX:OldSize=178954240 -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCID -XX:+PrintGCTimeStamps -XX:+TraceCMSState -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseConcMarkSweepGC -XX:+UseParNewGC -XX:+Verbose
Minimum heap 134217728 Initial heap 134217728 Maximum heap 268435456
1: Minimum gen0 89456640 Initial gen0 89456640 Maximum gen0 89456640
Minimum gen1 44761088 Initial gen1 44761088 Maximum gen1 178978816
//创建int数组
CollectedHeap::common_mem_allocate_noinit: klass->[I,size->2
//创建TLAB
DefNewGeneration::should_allocate->1,size->179079,tlab->1
//创建已加载类对应的class实例，用来保存该类的静态属性
CollectedHeap::common_mem_allocate_noinit: klass->Ljava/lang/Class;,size->13
//创建Universe,SystemDictionary等组件中维护的一些常用的类实例
CollectedHeap::common_mem_allocate_noinit: klass->Ljava/lang/OutOfMemoryError;,size->4
CollectedHeap::common_mem_allocate_noinit: klass->Ljava/lang/OutOfMemoryError;,size->4
CollectedHeap::common_mem_allocate_noinit: klass->Ljava/lang/OutOfMemoryError;,size->4
CollectedHeap::common_mem_allocate_noinit: klass->Ljava/lang/OutOfMemoryError;,size->4
CollectedHeap::common_mem_allocate_noinit: klass->Ljava/lang/OutOfMemoryError;,size->4
CollectedHeap::common_mem_allocate_noinit: klass->Ljava/lang/OutOfMemoryError;,size->4
CollectedHeap::common_mem_allocate_noinit: klass->Ljava/lang/Class;,size->14
CollectedHeap::common_mem_allocate_noinit: klass->[I,size->2
CollectedHeap::common_mem_allocate_noinit: klass->Ljava/lang/NullPointerException;,size->4
CollectedHeap::common_mem_allocate_noinit: klass->Ljava/lang/Class;,size->14
CollectedHeap::common_mem_allocate_noinit: klass->[I,size->2
CollectedHeap::common_mem_allocate_noinit: klass->Ljava/lang/ArithmeticException;,size->4
CollectedHeap::common_mem_allocate_noinit: klass->[Ljava/lang/Object;,size->4
CollectedHeap::common_mem_allocate_noinit: klass->[Ljava/lang/Object;,size->11
CollectedHeap::common_mem_allocate_noinit: klass->Ljava/lang/VirtualMachineError;,size->4
CollectedHeap::common_mem_allocate_noinit: klass->Ljava/lang/VirtualMachineError;,size->4
CollectedHeap::common_mem_allocate_noinit: klass->Ljava/lang/String;,size->3
CollectedHeap::common_mem_allocate_noinit: klass->[C,size->6
//创建源代码中字符串对应的String对象
CollectedHeap::common_mem_allocate_noinit: klass->Ljava/lang/String;,size->3
CollectedHeap::common_mem_allocate_noinit: klass->[C,size->5
//创建代码及其API依赖的类实例
CollectedHeap::common_mem_allocate_noinit: klass->Ljava/util/HashSet;,size->2
CollectedHeap::common_mem_allocate_noinit: klass->Ljava/util/HashMap;,size->6
CollectedHeap::common_mem_allocate_noinit: klass->Ljava/util/HashMap;,size->6
CollectedHeap::common_mem_allocate_noinit: klass->Ljava/util/WeakHashMap;,size->6
CollectedHeap::common_mem_allocate_noinit: klass->[Ljava/util/WeakHashMap$Entry;,size->10
//最后一个从年轻代成功分配的数组
CollectedHeap::common_mem_allocate_noinit: klass->[J,size->1000002
DefNewGeneration::should_allocate->1,size->1000002,tlab->0
//分配下一个时，年轻代内存不足了
CollectedHeap::common_mem_allocate_noinit: klass->[J,size->1000002
DefNewGeneration::should_allocate->1,size->1000002,tlab->0
TwoGenerationCollectorPolicy::mem_allocate_work: attempting locked slow path allocation
//first_only为true，表示只尝试在年轻代分配
TwoGenerationCollectorPolicy::mem_allocate_work: first_only->1
DefNewGeneration::should_allocate->1,size->1000002,tlab->0
//年轻代eden区分配失败，尝试从from区分配，但是属性should_allocate_from_space为false，不能从from区分配，所以返回NULL
DefNewGeneration::allocate_from_space(1000002): will_fail: false heap_lock: locked free: 8912896 should_allocate_from_space: NOT
returns NULL
//进入GenCollectedHeap::do_collection方法了，准备执行年轻代GC
2020-03-08T11:59:43.864+0800: 0.717: #0: [GC (Allocation Failure) Allocated 0 objects, 0 bytes concurrently
//判断是否需要执行年轻代GC
DefNewGeneration::should_allocate->1,size->1000002,tlab->0
//执行年轻代GC
2020-03-08T11:59:43.865+0800: 0.718: #0: [ParNewlevel=0 invoke=1 size=8000016
Expanding concurrent mark-sweep generation from 43712K by 7816K to 51528K
Expanded CMS gen for Par LAB
Expanding concurrent mark-sweep generation from 51528K by 7816K to 59344K
Expanded CMS gen for Par LAB
: 66865400->8677848(80543744), 0.1086520 secs]
//判断是否需要执行老年代GC，size为0，所以不需要
ConcurrentMarkSweepGeneration::should_collect->0,full->0,size->0,tlab->0
66865400->64682152(141312000)
//进入到老年代的gc_epilogue_work方法，这里只promote 了7个对象，因为这7个太大了，from区装不了，所以放到老年代了，后面的Contiguous available是老年代的未扩容空间
Promoted 7 objects, 56000112 bytes Contiguous available 118210560 bytes , 0.1097238 secs] [Times: user=0.14 sys=0.02, real=0.11 secs]
//GenCollectedHeap::do_collection结束，年轻代GC完成尝试分配，程序再次正常执行
DefNewGeneration::should_allocate->1,size->1000002,tlab->0
//因为老年代内存使用率超过初始设置值50%，触发老年代的后台GC
CMSCollector: collect for bootstrapping statistics: occupancy = 0.921605, boot occupancy = 0.500000
//执行InitialMarking
Thread 0x00007fe0e405a000 in CMS state 3
CMS Thread 0x00007fe0e405a000 continuing at CMS state 3
2020-03-08T11:59:43.989+0800: 0.842: #1: [GC (CMS Initial Mark) 2020-03-08T11:59:43.991+0800: 0.844: #1: [
checkpointRootsInitialWork, 0.0035132 secs]
[1 CMS-initial-mark: 56004304(60768256)] 74800512(141312000), 0.0052655 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
Thread 0x00007fe0e405a000 done - next CMS state 4
//执行Marking
Thread 0x00007fe0e405a000 in CMS state 4
CMS Thread 0x00007fe0e405a000 continuing at CMS state 4
2020-03-08T11:59:43.994+0800: 0.847: #1: [CMS-concurrent-mark-start]
2020-03-08T11:59:43.997+0800: 0.849: #1: [CMS-concurrent-mark: 0.002/0.002 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
Thread 0x00007fe0e405a000 done - next CMS state 5
//执行Precleaning
Thread 0x00007fe0e405a000 in CMS state 5
CMS Thread 0x00007fe0e405a000 continuing at CMS state 5
2020-03-08T11:59:43.997+0800: 0.850: #1: [CMS-concurrent-preclean-start]
(modUnionTable: 0 cards)2020-03-08T11:59:43.997+0800: 0.850: #1: [CMS-concurrent-preclean: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.01 secs]
Thread 0x00007fe0e405a000 done - next CMS state 6
//执行AbortablePreclean
Thread 0x00007fe0e405a000 in CMS state 6
CMS Thread 0x00007fe0e405a000 continuing at CMS state 6
2020-03-08T11:59:43.997+0800: 0.850: #1: [CMS-concurrent-abortable-preclean-start]
//执行preclean_work时，会多次遍历modUnionTable，而外层的abortable_preclean会多次调用preclean_work，所以看到打印了多个modUnionTable: 0 cards
(modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards) (modUnionTable: 0 cards)
//因为到了最长的循环时间了，退出循环
CMS: abort preclean due to time 2020-03-08T11:59:49.153+0800: 6.006: #1: [CMS-concurrent-abortable-preclean: 2.053/5.155 secs] [Times: user=2.06 sys=0.00, real=5.15 secs]
Thread 0x00007fe0e405a000 done - next CMS state 7
//执行FinalMarking
Thread 0x00007fe0e405a000 in CMS state 7
CMS Thread 0x00007fe0e405a000 continuing at CMS state 7
2020-03-08T11:59:49.153+0800: 6.006: #1: [GC (CMS Final Remark) [YG occupancy: 18355 K (78656 K)]2020-03-08T11:59:49.153+0800: 6.006: #1: [checkpointRootsFinalWork2020-03-08T11:59:49.153+0800: 6.006: #1: [Rescan (parallel) , 0.0035317 secs]
//Reference实例处理
2020-03-08T11:59:49.157+0800: 6.009: #1: [refProcessingWork2020-03-08T11:59:49.157+0800: 6.009: #1: [weak refs processing, 0.0000320 secs]
//执行类卸载
2020-03-08T11:59:49.157+0800: 6.009: #1: [class unloading, 0.0020820 secs]2020-03-08T11:59:49.159+0800: 6.011: #1: [scrub symbol table, 0.0024840 secs]2020-03-08T11:59:49.161+0800: 6.014: #1: [scrub string table, 0.0016912 secs], 0.0063388 secs], 0.0116460 secs][1 CMS-remark: 56004304(60768256)] 74800512(141312000), 0.0117099 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
Thread 0x00007fe0e405a000 done - next CMS state 8
//执行Sweeping
Thread 0x00007fe0e405a000 in CMS state 8
CMS Thread 0x00007fe0e405a000 continuing at CMS state 8
2020-03-08T11:59:49.165+0800: 6.018: #1: [CMS-concurrent-sweep-start]
Collected 0 objects, 0 bytes
//当前老年代总共存活7个对象，释放了4个对象，这个7个就是最开始promote到老年代的七个
Live 7 objects, 56000112 bytes Already free 4 objects, 4768144 bytes
Total sweep: 60768256 bytes
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 579110
Max Chunk Size: 579110
Number of Blocks: 1
Av. Block Size: 579110
Tree Height: 1
2020-03-08T11:59:49.166+0800: 6.019: #1: [CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
//执行Resizing
//计算元空间是否需要扩容
MetaspaceGC::compute_new_size:
minimum_free_percentage: 0.40 maximum_used_percentage: 0.60
used_after_gc : 4864.0KB
maximum_free_percentage: 0.70 minimum_used_percentage: 0.30
minimum_desired_capacity: 21296.0KB maximum_desired_capacity: 21296.0KB
//计算老年代是否需要扩容
From compute_new_size:
Free fraction 0.078395
Desired free fraction 0.400000
Maximum free fraction 0.700000
Capactiy 60768
Desired capacity 93340
Younger gen size 80543
unsafe_max_alloc_nogc 4632
contiguous available 118210
Expand by 32572250 (bytes)
//扩容老年代
Expanding concurrent mark-sweep generation from 59344K by 31812K to 91156K
Expanded CMS gen for Free ratio
Expanded free fraction 0.400021
Thread 0x00007fe0e405a000 done - next CMS state 1
//执行Resetting
Thread 0x00007fe0e405a000 in CMS state 1
CMS Thread 0x00007fe0e405a000 continuing at CMS state 1
2020-03-08T11:59:49.212+0800: 6.065: #1: [CMS-concurrent-reset-start]
2020-03-08T11:59:49.214+0800: 6.067: #1: [CMS-concurrent-reset: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
Thread 0x00007fe0e405a000 done - next CMS state 2
//进入Idling，GC完成
CMS Thread 0x00007fe0e405a000 exiting collection CMS state 2