JVM源码级别分析G1发生FullGC元凶的是什么

思维新观察

于 2024-08-14 18:04:36 发布

阅读量6

点赞数

文章标签： java 后端

原文链接：https://juejin.cn/post/7361684907809554442

版权

问题描述

线上发生GC问题, 有不少OldGC产生, 监控截图如下

收到告警后, 立即上机器排查了, 具体排查过程如下, 还是收获颇丰的.

问题排查

我首先分析了当时的GC日志, 发现在日志中多次出现"to-space exhausted", 并且出现该日志的GC通常耗时非常高, 相关日志如下:

代码解读

复制代码

2023-11-16T19:04:02.992+0800: 459907.332: [SoftReference, 8 refs, 0.0000699 secs]2023-11-16T19:04:02.992+0800: 459907.332: [WeakReference, 3 refs, 0.0000076 secs]2023-11-16T19:04:02.992+0800: 459907.332: [FinalReference, 7371 refs, 0.0139270 secs]2023-11-16T19:04:03.006+0800: 459907.346: [PhantomReference, 0 refs, 6 refs, 0.0000206 secs]2023-11-16T19:04:03.006+0800: 459907.346: [JNI Weak Reference, 0.0000448 secs] 459908.553: [G1Ergonomics (Concurrent Cycles) do not request concurrent cycle initiation, reason: still doing mixed collections, occupancy: 20669530112 bytes, allocation request: 0 bytes, threshold: 7730941110 bytes (30.00 %), source: end of GC] 459908.553: [G1Ergonomics (Mixed GCs) start mixed GCs, reason: candidate old regions available, candidate old regions: 111 regions, reclaimable: 2193274488 bytes (8.51 %), threshold: 5.00 %] (to-space exhausted), 2.9358876 secs] [Parallel Time: 1714.2 ms, GC Workers: 13] [GC Worker Start (ms): Min: 459905617.7, Avg: 459905617.9, Max: 459905618.1, Diff: 0.4] [Ext Root Scanning (ms): Min: 2.2, Avg: 2.8, Max: 8.3, Diff: 6.1, Sum: 36.0] [Update RS (ms): Min: 162.9, Avg: 168.4, Max: 169.1, Diff: 6.2, Sum: 2188.8] [Processed Buffers: Min: 413, Avg: 439.8, Max: 463, Diff: 50, Sum: 5717] [Scan RS (ms): Min: 0.0, Avg: 0.1, Max: 0.2, Diff: 0.2, Sum: 1.5] [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1] [Object Copy (ms): Min: 1542.1, Avg: 1542.2, Max: 1542.4, Diff: 0.3, Sum: 20048.5] [Termination (ms): Min: 0.0, Avg: 0.2, Max: 0.3, Diff: 0.3, Sum: 2.4] [Termination Attempts: Min: 1, Avg: 3.3, Max: 19, Diff: 18, Sum: 43] [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3] [GC Worker Total (ms): Min: 1713.5, Avg: 1713.7, Max: 1713.8, Diff: 0.4, Sum: 22277.6] [GC Worker End (ms): Min: 459907331.5, Avg: 459907331.5, Max: 459907331.6, Diff: 0.1] [Code Root Fixup: 0.0 ms] [Code Root Purge: 0.0 ms]

所谓to-space exhausted是什么? 为什么它导致FGC呢?

查阅网上资料, 发现都讲得特别浅, 不如和我一起从JVM源码看起, 一探究竟.

to-space 耗尽问题排查

上面讲到to-space exhausted, 我们来看下JVM在什么情况下会打出上述日志.

在JVM代码中查找, 发现在G1CollectedHeap::do_collection_pause_at_safepoint中有如下代码:

c++

代码解读

复制代码

// Print the remainder of the GC log output. if (evacuation_failed()) { log_info(gc)("To-space exhausted"); }

可以看到当evacuation_failed()返回true时会打印"To-space exhausted", 那么evacuation_failed()在什么时候返回true呢?

通过对代码的追踪, 发现了这条调用链:

G1CollectedHeap::preserve_mark_during_evac_failure函数中会设置_evacuation_failed为true:

c++

代码解读

复制代码

void G1CollectedHeap::preserve_mark_during_evac_failure(uint worker_id, oop obj, markOop m) { if (!_evacuation_failed) { _evacuation_failed = true; } _evacuation_failed_info_array[worker_id].register_copy_failure(obj->size()); _preserved_marks_set.get(worker_id)->push_if_necessary(obj, m); }

接着找，在G1ParScanThreadState::handle_evacuation_failure_par中会调用preserve_mark_during_evac_failure:

c++

代码解读

复制代码

oop G1ParScanThreadState::handle_evacuation_failure_par(oop old, markOop m) { assert(_g1h->is_in_cset(old), "Object " PTR_FORMAT " should be in the CSet", p2i(old)); // 指向自己 oop forward_ptr = old->forward_to_atomic(old, m, memory_order_relaxed); if (forward_ptr == NULL) { // Forward-to-self succeeded. We are the "owner" of the object. HeapRegion* r = _g1h->heap_region_containing(old); if (!r->evacuation_failed()) { r->set_evacuation_failed(true); _g1h->hr_printer()->evac_failure(r); } // 保存旧的markword _g1h->preserve_mark_during_evac_failure(_worker_id, old, m); G1ScanInYoungSetter x(&_scanner, r->is_young()); // 扫描转移失败对象的field，将它们push到pss的队列 old->oop_iterate_backwards(&_scanner); return old; } else { return forward_ptr; } }

handle_evacuation_failure_par函数会在G1的转移阶段，将存活对象转移到Old区失败时调用：

c++

代码解读

复制代码

oop G1ParScanThreadState::copy_to_survivor_space(InCSetState const state, oop const old, markOop const old_mark) { const size_t word_sz = old->size(); HeapRegion* const from_region = _g1h->heap_region_containing(old); // +1 to make the -1 indexes valid... const int young_index = from_region->young_index_in_cset()+1; uint age = 0; InCSetState dest_state = next_state(state, old_mark, age); if (_old_gen_is_full && dest_state.is_old()) { // 第一种情况 return handle_evacuation_failure_par(old, old_mark); } HeapWord* obj_ptr = _plab_allocator->plab_allocate(dest_state, word_sz); if (obj_ptr == NULL) { bool plab_refill_failed = false; obj_ptr = _plab_allocator->allocate_direct_or_new_plab(dest_state, word_sz, &plab_refill_failed); if (obj_ptr == NULL) { obj_ptr = allocate_in_next_plab(state, &dest_state, word_sz, plab_refill_failed); if (obj_ptr == NULL) { // 第二种情况 return handle_evacuation_failure_par(old, old_mark); } } }

这是G1在转移阶段通过遍历每个对象将其转移到Survivor区的代码，可以看到如果：

对象本身在Survivor区且年龄超过晋升阈值，但是Old区满了。
或者Survivor区和Old区都没有空闲空间。

那么这个对象转移失败，在handle_evacuation_failure_par中会调用preserve_mark_during_evac_failure设置_evacuation_failed标志位为true。所以如果GC日志中出现to-space exhausted字样，我们就需要注意了，这时我们的堆空间没有足够的地方存放这些存活对象导致晋升失败（promotion failure）！

那么该怎么解决呢？通过查阅网上资源，大部分的建议都是调整G1ReservePercent这个参数，这个参数的含义在官方文档的解释是：

Sets the percentage of reserve memory to keep free so as to reduce the risk of to-space overflows. The default is 10 percent. When you increase or decrease the percentage, make sure to adjust the total Java heap by the same amount.

大意是在JVM中预留的一部分空间用于降低to-space溢出的风险。

在JVM代码里的解释是：

It determines the minimum reserve we should have in the heap to minimize the probability of promotion failure.

大意是通过设置最小预留空间来降低晋升失败的概率。

但是你可能还是一头雾水，这个所谓最小预留空间到底是如何保证晋升成功的? 这里我们还是需要代码来说话。接下来我们来分析JVM源码搞清楚G1ReservePercent的原理是什么，增加它会给JVM带来什么影响，以及它能解决我们上面的问题吗？

G1ReservePercent参数的作用及原理

在G1Policy::record_new_heap_size中通过G1ReservePercent（即_reserve_factor）计算出需要保留的region数量：_reserve_regions，

c++

代码解读

复制代码

void G1Policy::record_new_heap_size(uint new_number_of_regions) { // re-calculate the necessary reserve double reserve_regions_d = (double) new_number_of_regions * _reserve_factor; // We use ceiling so that if reserve_regions_d is > 0.0 (but // smaller than 1.0) we'll get 1. _reserve_regions = (uint) ceil(reserve_regions_d);

在G1Policy::young_list_target_lengths函数中，使用_reserve_regions计算Young区最大regions数量，这里使用Young区全部空闲的region数量减去保留的region数量，得到一个Young区的最大值：absolute_max_length

c++

代码解读

复制代码

if (_free_regions_at_end_of_collection > _reserve_regions) { absolute_max_length = _free_regions_at_end_of_collection - _reserve_regions; }

那么absolute_max_length这个值在什么地方起作用呢？

答案是在分配新Region的时候：

c++

代码解读

复制代码

HeapRegion* G1CollectedHeap::new_mutator_alloc_region(size_t word_size, bool force) { assert_heap_locked_or_at_safepoint(true /* should_be_vm_thread */); bool should_allocate = g1_policy()->should_allocate_mutator_region(); // 当前young区region数量是否小于_young_list_target_length if (force || should_allocate) { HeapRegion* new_alloc_region = new_region(word_size, HeapRegionType::Eden, false /* do_expand */); if (new_alloc_region != NULL) { set_region_short_lived_locked(new_alloc_region); _hr_printer.alloc(new_alloc_region, !should_allocate); _verifier->check_bitmaps("Mutator Region Allocation", new_alloc_region); _g1_policy->remset_tracker()->update_at_allocate(new_alloc_region); return new_alloc_region; } } return NULL; }

在决定是否可以分配的时候调用了g1_policy()->should_allocate_mutator_region()函数，接下来看这个函数是如何实现的：

c++

代码解读

复制代码

bool G1Policy::should_allocate_mutator_region() const { uint young_list_length = _g1h->young_regions_count(); uint young_list_target_length = _young_list_target_length; return young_list_length < young_list_target_length; }

可以看到这里使用当前young区region数量大小是否小于_young_list_target_length，而_young_list_target_length这个变量就是在：_free_regions_at_end_of_collection - _reserve_regions;这一步计算出来的。

由此可见，JVM通过G1ReservePercent参数确实预留出了一部分空间用于晋升，但增加这个配置意味着可用于对象分配的区域变少了, 所以往往在增加这个配置的同时也要增加堆大小.

但这个配置默认就是10%，我们线上Heap大小为24G，总共预留出了2.4G，但为什么还会出现to-space exhausted问题吗？难道是对象超过2.4G？

其实G1ReservePercent这个参数并不是在所有情况下都有效, 比如其在分配大对象时是不起作用的。（大对象是指超过region大小一半的对象），下面来看怎么回事

大对象分配

首先看大对象分配的代码，调用链：

G1CollectedHeap::attempt_allocation_humongous -> G1CollectedHeap::humongous_obj_allocate -> G1CollectedHeap::new_region, 在这个调用链上是不存在类似should_allocate_mutator_region的函数判断的，也就是说大对象分配的空间会占用reserve region的空间！

相关代码：

c++

代码解读

复制代码

HeapWord* G1CollectedHeap::attempt_allocation_humongous(size_t word_size) { ResourceMark rm; // For retrieving the thread names in log messages. if (g1_policy()->need_to_start_conc_mark("concurrent humongous allocation", word_size)) { collect(GCCause::_g1_humongous_allocation); } result = humongous_obj_allocate(word_size); HeapWord* G1CollectedHeap::humongous_obj_allocate(size_t word_size) { assert_heap_locked_or_at_safepoint(true /* should_be_vm_thread */); _verifier->verify_region_sets_optional(); uint first = G1_NO_HRM_INDEX; uint obj_regions = (uint) humongous_obj_size_in_regions(word_size); if (obj_regions == 1) { // Only one region to allocate, try to use a fast path by directly allocating // from the free lists. Do not try to expand here, we will potentially do that // later. HeapRegion* hr = new_region(word_size, HeapRegionType::Humongous, false /* do_expand */); HeapRegion* G1CollectedHeap::new_region(size_t word_size, HeapRegionType type, bool do_expand) { assert(!is_humongous(word_size) || word_size <= HeapRegion::GrainWords, "the only time we use this to allocate a humongous region is " "when we are allocating a single humongous region"); HeapRegion* res = _hrm->allocate_free_region(type);

而在我们的GC日志里也发现了大对象的踪影：

代码解读

复制代码

2023-11-16T19:03:47.107+0800: 459891.447: Application time: 5.0003976 seconds 459891.490: [G1Ergonomics (Concurrent Cycles) do not request concurrent cycle initiation, reason: still doing mixed collections, occupancy: 7683964928 bytes, allocation request: 47852800 bytes, threshold: 7660476810 bytes (30.00 %), source: concurrent humongous allocation] 459891.499: [G1Ergonomics (Concurrent Cycles) do not request concurrent cycle initiation, reason: still doing mixed collections, occupancy: 7751073792 bytes, allocation request: 71779192 bytes, threshold: 7660476810 bytes (30.00 %), source: concurrent humongous allocation] 459891.518: [G1Ergonomics (Concurrent Cycles) do not request concurrent cycle initiation, reason: still doing mixed collections, occupancy: 7851737088 bytes, allocation request: 23926408 bytes, threshold: 7660476810 bytes (30.00 %), source: concurrent humongous allocation] 459892.274: [G1Ergonomics (Concurrent Cycles) do not request concurrent cycle initiation, reason: still doing mixed collections, occupancy: 7885291520 bytes, allocation request: 56455480 bytes, threshold: 7660476810 bytes (30.00 %), source: concurrent humongous allocation] 459892.327: [G1Ergonomics (Concurrent Cycles) do not request concurrent cycle initiation, reason: still doing mixed collections, occupancy: 7952400384 bytes, allocation request: 362587112 bytes, threshold: 7660476810 bytes (30.00 %), source: concurrent humongous allocation] 459893.207: [G1Ergonomics (Concurrent Cycles) do not request concurrent cycle initiation, reason: still doing mixed collections, occupancy: 8321499136 bytes, allocation request: 24613616 bytes, threshold: 7660476810 bytes (30.00 %), source: concurrent humongous allocation] 2023-11-16T19:03:50.110+0800: 459894.451: Application time: 3.0002494 seconds 2023-11-16T19:03:50.207+0800: 459894.547: Application time: 0.0937297 seconds 2023-11-16T19:03:50.225+0800: 459894.566: Application time: 0.0153778 seconds 2023-11-16T19:03:50.231+0800: 459894.572: Application time: 0.0031969 seconds 459894.583: [G1Ergonomics (Concurrent Cycles) do not request concurrent cycle initiation, reason: still doing mixed collections, occupancy: 8355053568 bytes, allocation request: 16778256 bytes, threshold: 7660476810 bytes (30.00 %), source: concurrent humongous allocation]

合理猜想：由于大对象分配导致reserve regions的空间被占用，对象晋升到Old区但没有足够空间导致to-space exhausted。