问题描述
线上发生GC问题, 有不少OldGC产生, 监控截图如下
收到告警后, 立即上机器排查了, 具体排查过程如下, 还是收获颇丰的.
问题排查
我首先分析了当时的GC日志, 发现在日志中多次出现"to-space exhausted", 并且出现该日志的GC通常耗时非常高, 相关日志如下:
js
代码解读
复制代码
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日志里也发现了大对象的踪影：
js
代码解读
复制代码
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。
验证猜想 & 问题解决
既然知道大对象是可能的原因，我们就来看如何解决。首先我们通过JFR查看大对象分配事件：
修改JFR配置文件：
xml
代码解读
复制代码
...
<event name="jdk.ObjectAllocationOutsideTLAB">
<setting name="enabled">true</setting>
<setting name="stackTrace">true</setting>
</event>
...
开启采集TLAB外分配对象的事件（大对象分配时不会在线程的TLAB里分配，而是会在TLAB外分配），然后通过：
shell
代码解读
复制代码
jcmd $(pgrep java) JFR.start duration=600s filename=/data/applogs/cat/logs/flight.jfr settings=/usr/java/default/lib/jfr/all_tlab_17.jfc
filename是最终输出的jfr文件路径，开启JFR（注意JVM参数需要加上：-XX:+UnlockCommercialFeatures），最终得到文件，可以通过Java Mission Control打开：
通过这张图可以看到在问题发生的时刻确实发生了大量的TLAB分配，其中第一个线程TLAB外分配量最高，我们接着分析下面的火焰图，找到对应的方法继续分析：
通过分析代码发现是由于我们定期生成的报表序列化在JVM内存中导致的，这里我们通过使用堆外内存作为序列化的输出减少了JVM大对象的分配，最终解决了这个问题：
优化后：
可以看到OldGC全部消失.
总结
本篇文章从一个线上GC故障开始，从JVM源码级别分析了to-space问题的产生原因，和G1ReservePercent参数的作用，最后我们通过JFR分析出了问题的根因并通过堆外内存最终解决了这个问题。
