Repository navigation
share jdk8_other_time
ceragon edited this page Dec 28, 2021
·
5 revisions
原始问题：g1 gc 'Other' take a long time ，为了防止链接失效，内容记录如下
G1 gc 'Other' takes a long time. What is the most possible cause and how to solve it?
jvm params:
-XX:+UseG1GC -XX:MaxGCPauseMillis=10 -Xmx2048m -Xms2048m -Xss512k -XX:NewRatio=2 -XX:MetaspaceSize=256m -XX:MaxMetaspaceSize=512m -XX:ReservedCodeCacheSize=256m -XX:InitialCodeCacheSize=256m -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -XX:+PrintTenuringDistribution -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=5 -XX:GCLogFileSize=128M -Xloggc:/med/log/mall-product.gc.log -XX:+HeapDumpOnOutOfMemoryError
2021-11-04T12:37:22.250+0800: 96601.445: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 45088768 bytes, new threshold 15 (max 15)
- age 1: 3170160 bytes, 3170160 total
- age 2: 1426024 bytes, 4596184 total
- age 3: 396136 bytes, 4992320 total
- age 4: 67992 bytes, 5060312 total
- age 5: 123112 bytes, 5183424 total
- age 6: 64320 bytes, 5247744 total
- age 7: 75640 bytes, 5323384 total
- age 8: 56656 bytes, 5380040 total
- age 9: 87560 bytes, 5467600 total
- age 10: 79568 bytes, 5547168 total
- age 11: 34016 bytes, 5581184 total
- age 12: 47432 bytes, 5628616 total
- age 13: 115944 bytes, 5744560 total
- age 14: 133456 bytes, 5878016 total
- age 15: 477016 bytes, 6355032 total
, 0.1573301 secs]
[Parallel Time: 12.2 ms, GC Workers: 4]
[GC Worker Start (ms): Min: 96601587.8, Avg: 96601587.9, Max: 96601587.9, Diff: 0.1]
[Ext Root Scanning (ms): Min: 4.0, Avg: 4.3, Max: 4.7, Diff: 0.7, Sum: 17.1]
[Update RS (ms): Min: 2.0, Avg: 2.1, Max: 2.1, Diff: 0.0, Sum: 8.3]
[Processed Buffers: Min: 30, Avg: 38.5, Max: 46, Diff: 16, Sum: 154]
[Scan RS (ms): Min: 0.9, Avg: 0.9, Max: 1.0, Diff: 0.1, Sum: 3.6]
[Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Object Copy (ms): Min: 4.3, Avg: 4.7, Max: 5.0, Diff: 0.7, Sum: 19.0]
[Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
[Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 4]
[GC Worker Other (ms): Min: 0.0, Avg: 0.1, Max: 0.1, Diff: 0.1, Sum: 0.3]
[GC Worker Total (ms): Min: 12.0, Avg: 12.1, Max: 12.1, Diff: 0.1, Sum: 48.3]
[GC Worker End (ms): Min: 96601599.9, Avg: 96601599.9, Max: 96601600.0, Diff: 0.1]
[Code Root Fixup: 0.0 ms]
[Code Root Purge: 0.0 ms]
[Clear CT: 0.3 ms]
[Other: 144.8 ms]
[Choose CSet: 0.0 ms]
[Ref Proc: 1.3 ms]
[Ref Enq: 0.1 ms]
[Redirty Cards: 0.1 ms]
[Humongous Register: 0.1 ms]
[Humongous Reclaim: 0.0 ms]
[Free CSet: 0.7 ms]
[Eden: 674.0M(674.0M)->0.0B(674.0M) Survivors: 8192.0K->8192.0K Heap: 1430.5M(2048.0M)->756.7M(2048.0M)]
Heap after GC invocations=2670 (full 0):
garbage-first heap total 2097152K, used 774853K [0x0000000080000000, 0x0000000080104000, 0x0000000100000000)
region size 1024K, 8 young (8192K), 8 survivors (8192K)
Metaspace used 133822K, capacity 141304K, committed 141440K, reserved 1173504K
class space used 16174K, capacity 17421K, committed 17536K, reserved 1048576K
}
[Times: user=0.05 sys=0.00, real=0.16 secs]
{Heap before GC invocations=2670 (full 0):
garbage-first heap total 2097152K, used 1465029K [0x0000000080000000, 0x0000000080104000, 0x0000000100000000)
region size 1024K, 682 young (698368K), 8 survivors (8192K)
Metaspace used 133824K, capacity 141304K, committed 141440K, reserved 1173504K
class space used 16174K, capacity 17421K, committed 17536K, reserved 1048576K
- GC 的总耗时 157.3301ms
- Other 的耗时 144.8ms
- 两者相差 12.5301ms
- 源码如下
void G1GCPhaseTimes::print(double pause_time_sec) {
// 计算出 other 的耗时
double misc_time_ms = pause_time_sec * MILLIUNITS - accounted_time_ms();
print_stats(1, "Other", misc_time_ms);
}
double G1GCPhaseTimes::accounted_time_ms() {
// 除 other 之外的时间占用统计
double misc_time_ms = _root_region_scan_wait_time_ms;
misc_time_ms += _cur_collection_par_time_ms;
misc_time_ms += _cur_collection_code_root_fixup_time_ms;
misc_time_ms += _cur_strong_code_root_purge_time_ms;
if (G1StringDedup::is_enabled()) {
misc_time_ms += _cur_string_dedup_fixup_time_ms;
}
misc_time_ms += _cur_clear_ct_time_ms;
return misc_time_ms;
}- 涉及相关变量及耗时的整理如下
| 日志名称 | 变量名称 | 耗时(ms) |
|---|---|---|
| Root Region Scan Waiting | _root_region_scan_wait_time_ms | 0 |
| Parallel Time | _cur_collection_par_time_ms | 12.2 |
| Code Root Fixup | _cur_collection_code_root_fixup_time_ms | 0.0 |
| Code Root Purge | _cur_strong_code_root_purge_time_ms | 0.0 |
| String Dedup Fixup | _cur_string_dedup_fixup_time_ms | 0 |
| Clear CT | _cur_clear_ct_time_ms | 0.3 |
| 合计 | 12.5 |
- 合计耗时 12.5ms，与上一步的差值 12.5301ms 基本吻合。日志中剩余时间统计如下
| 日志名称 | 变量名称 | 耗时(ms) |
|---|---|---|
| Choose CSet | _recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms | 0.0 |
| Ref Proc | _cur_ref_proc_time_ms | 1.3 |
| Ref Enq | _cur_ref_enq_time_ms | 0.1 |
| Redirty Cards | _recorded_redirty_logged_cards_time_ms | 0.1 |
| Humongous Register | _cur_fast_reclaim_humongous_register_time_ms | 0.1 |
| Humongous Reclaim | _cur_fast_reclaim_humongous_time_ms | 0.0 |
| Free CSet | _recorded_young_free_cset_time_ms + _recorded_non_young_free_cset_time_ms | 0.7 |
| 合计 | 2.3 |
- 如果想定位 Other 中包含哪些步骤，首先需要知道 print 方法中 pause_time_sec 的赋值
bool G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
double pause_start_sec = os::elapsedTime();
// 省略中间代码
// 下面代码中， os::elapsedTime() - pause_start_sec 就是 pause_time_sec
// 也就是本次 GC 的总暂停时间
log_gc_footer(os::elapsedTime() - pause_start_sec);
}- 可以看到 pause_time_sec 涵盖了 GC 的主要工作
bool G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
double pause_start_sec = os::elapsedTime();
g1_policy()->phase_times()->note_gc_start(active_workers, mark_in_progress());
// 打印 GC 日志的头信息
// [GC pause (G1 Evacuation Pause) (young)
log_gc_header();
TraceCollectorStats tcs(g1mm()->incremental_collection_counters());
TraceMemoryManagerStats tms(false /* fullGC */, gc_cause(),
yc_type() == Mixed /* allMemoryPoolsAffected */);
// 默认为 false，所以此处为真
if (!G1StressConcRegionFreeing) {
// _secondary_free_list 为空，所以不会执行
append_secondary_free_list_if_not_empty_with_lock();
}
{
IsGCActiveMark x;
gc_prologue(false);
// 统计 GC 次数
increment_total_collections(false /* full gc */);
increment_gc_time_stamp();
// 校验记忆集，默认是 false
if (VerifyRememberedSets) {
if (!VerifySilently) {
gclog_or_tty->print_cr("[Verifying RemSets before GC]");
}
VerifyRegionRemSetClosure v_cl;
heap_region_iterate(&v_cl);
}
verify_before_gc();
// 校验标记的信息
check_bitmaps("GC Start");
COMPILER2_PRESENT(DerivedPointerTable::clear());
ref_processor_stw()->enable_discovery(true /*verify_disabled*/,
true /*verify_no_refs*/);
{
NoRefDiscovery no_cm_discovery(ref_processor_cm());
_allocator->release_mutator_alloc_region();
_hr_printer.start_gc(false /* full */, (size_t) total_collections());
double sample_start_time_sec = os::elapsedTime();
g1_policy()->record_collection_pause_start(sample_start_time_sec, *_gc_tracer_stw);
// region ----------------- _root_region_scan_wait_time_ms = 0 ------------
// 名称 Root Region Scan Waiting 的赋值代码
double scan_wait_start = os::elapsedTime();
bool waited = _cm->root_regions()->wait_until_scan_finished();
double wait_time_ms = 0.0;
if (waited) {
double scan_wait_end = os::elapsedTime();
wait_time_ms = (scan_wait_end - scan_wait_start) * 1000.0;
}
g1_policy()->phase_times()->record_root_region_scan_wait_time(wait_time_ms);
// endregion
// 本次是 完全 young gc，且不包含初始标记,这里是 false
if (g1_policy()->during_initial_mark_pause()) {
concurrent_mark()->checkpointRootsInitialPre();
}
// target_pause_time_ms 为本次预期的暂停时间
// region --------- _recorded_young_cset_choice_time_ms + _recorded_non_young_cset_choice_time_ms = 0 --------
// 名称 Choose CSet 的赋值代码
g1_policy()->finalize_cset(target_pause_time_ms, evacuation_info);
// endregion
// 由于 Humongous Register 只花费了 0.1ms，所以只要 humongous region 不多，这里应该也不会太耗时
g1_rem_set()->cleanupHRRS();
// region ---------- _cur_fast_reclaim_humongous_register_time_ms = 0.1 --------
// 名称 Humongous Register
register_humongous_regions_with_in_cset_fast_test();
// endregion
_cm->note_start_of_gc();
_cm->verify_no_cset_oops();
// region 这里是 G1PrintHeapRegions 参数的值，默认是 false
if (_hr_printer.is_active()) {
HeapRegion* hr = g1_policy()->collection_set();
while (hr != NULL) {
_hr_printer.cset(hr);
hr = hr->next_in_collection_set();
}
}
// endregion
setup_surviving_young_words();
_allocator->init_gc_alloc_regions(evacuation_info);
// region ------------ 合计 14 ms ---------------
// Parallel Time : _cur_collection_par_time_ms = 12.2
// Code Root Fixup : _cur_collection_code_root_fixup_time_ms = 0.0
// Ref Proc : _cur_ref_proc_time_ms = 1.3
// Code Root Purge : _cur_strong_code_root_purge_time_ms = 0.0
// Ref Enq : _cur_ref_enq_time_ms = 0.1
// String Dedup Fixup : _cur_string_dedup_fixup_time_ms = 0.0
// Clear CT : _cur_clear_ct_time_ms = 0.3
// Redirty Cards : _recorded_redirty_logged_cards_time_ms = 0.1
// 真正执行转移到代码，执行时会调用并行处理线程
evacuate_collection_set(evacuation_info);
// 需要说明的是，上面的代码有一部分未计时
// endregion
// region ------- _recorded_young_free_cset_time_ms + _recorded_non_young_free_cset_time_ms = 0.7 --------
// 名称 Free CSet 的赋值代码
free_collection_set(g1_policy()->collection_set(), evacuation_info);
// endregion
// region ----- _cur_fast_reclaim_humongous_time_ms = 0.0 ----------
// 名称 Humongous Reclaim 的赋值代码
eagerly_reclaim_humongous_regions();
// endregion
// 纯赋值 清理回收集合
g1_policy()->clear_collection_set();
// 纯赋值
cleanup_surviving_young_words();
// 纯赋值
g1_policy()->start_incremental_cset_building();
// 清理数组
clear_cset_fast_test();
// 纯赋值
_young_list->reset_sampled_info();
// 纯赋值
g1_policy()->record_survivor_regions(_young_list->survivor_length(),
_young_list->first_survivor_region(),
_young_list->last_survivor_region());
_young_list->reset_auxilary_lists();
// region 本次转移没有失败
if (evacuation_failed()) {
_allocator->set_used(recalculate_used());
uint n_queues = MAX2((int)ParallelGCThreads, 1);
for (uint i = 0; i < n_queues; i++) {
if (_evacuation_failed_info_array[i].has_failed()) {
_gc_tracer_stw->report_evacuation_failed(_evacuation_failed_info_array[i]);
}
}
// endregion
} else {
// 纯赋值
_allocator->increase_used(g1_policy()->bytes_copied_during_gc());
}
// region 本次没有执行初始标记
if (g1_policy()->during_initial_mark_pause()) {
concurrent_mark()->checkpointRootsInitialPost();
set_marking_started();
}
// endregion
// region 由于 G1DummyRegionsPerGC 参数的默认值是 0，所以里面的代码只是纯赋值
allocate_dummy_regions();
// endregion
// 纯赋值
_allocator->init_mutator_alloc_region();
{
// 判断本次是否需要扩展空间
// 不需要扩充，因为已经扩充到最大了
size_t expand_bytes = g1_policy()->expansion_amount();
if (expand_bytes > 0) {
size_t bytes_before = capacity();
if (!expand(expand_bytes)) {
}
}
}
_cm->verify_no_cset_oops();
// 纯赋值
_cm->note_end_of_gc();
double sample_end_time_sec = os::elapsedTime();
double pause_time_ms = (sample_end_time_sec - sample_start_time_sec) * MILLIUNITS;
g1_policy()->record_collection_pause_end(pause_time_ms, evacuation_info);
MemoryService::track_memory_usage();
increment_gc_time_stamp();
// 默认值是 false
if (VerifyRememberedSets) {
if (!VerifySilently) {
gclog_or_tty->print_cr("[Verifying RemSets after GC]");
}
VerifyRegionRemSetClosure v_cl;
heap_region_iterate(&v_cl);
}
// region ---------- _cur_verify_after_time_ms = 0 ---------------
// 名称 Verify After 的赋值
verify_after_gc();
// endregion
// G1VerifyBitmaps 的参数是 false
check_bitmaps("GC End");
// 在生产环境不会执行
ref_processor_stw()->verify_no_references_recorded();
}
// 打印日志
_hr_printer.end_gc(false /* full */, (size_t) total_collections());
gc_epilogue(false);
}
log_gc_footer(os::elapsedTime() - pause_start_sec);
print_heap_after_gc();
}- 过滤掉一些代码，过滤条件如下。将剩余代码进行分块罗列，且以下代码的耗时大概在 142.5 ms (144.8 - 2.3 = 142.5) 左右
- GC 日志中明确记录了时间的代码
- 纯赋值的代码
- 在当前不会被执行到的代码
bool G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
double pause_start_sec = os::elapsedTime();
g1_policy()->phase_times()->note_gc_start(active_workers, mark_in_progress());
// 打印 GC 日志的头信息
// [GC pause (G1 Evacuation Pause) (young)
log_gc_header();
TraceMemoryManagerStats tms(false /* fullGC */, gc_cause(), yc_type() == Mixed /* allMemoryPoolsAffected */);
{
gc_prologue(false);
{
// ——————————————————————————————————————
_allocator->release_mutator_alloc_region();
// ——————————————————————————————————————
_hr_printer.start_gc(false /* full */, (size_t) total_collections());
double sample_start_time_sec = os::elapsedTime();
g1_policy()->record_collection_pause_start(sample_start_time_sec, *_gc_tracer_stw);
// 申请一个数组的空间，且数组大小是 682，讲道理不会太耗时
setup_surviving_young_words();
// 初始化可分配的 region
_allocator->init_gc_alloc_regions(evacuation_info);
// 保留该方法，因为有一部分未纳入统计
evacuate_collection_set(evacuation_info);
// 清理数组
clear_cset_fast_test();
_young_list->reset_auxilary_lists();
double sample_end_time_sec = os::elapsedTime();
double pause_time_ms = (sample_end_time_sec - sample_start_time_sec) * MILLIUNITS;
g1_policy()->record_collection_pause_end(pause_time_ms, evacuation_info);
MemoryService::track_memory_usage();
}
// 打印日志
_hr_printer.end_gc(false /* full */, (size_t) total_collections());
}
log_gc_footer(os::elapsedTime() - pause_start_sec);
}
G1CollectedHeap::setup_surviving_young_words() {
uint array_length = g1_policy()->young_cset_region_length();
_surviving_young_words = NEW_C_HEAP_ARRAY(size_t, (size_t) array_length, mtGC);
if (_surviving_young_words == NULL) {
vm_exit_out_of_memory(sizeof(size_t) * array_length, OOM_MALLOC_ERROR,
"Not enough space for young surv words summary.");
}
memset(_surviving_young_words, 0, (size_t) array_length * sizeof(size_t));
}
void G1CollectedHeap::evacuate_collection_set(EvacuationInfo& evacuation_info) {
g1_rem_set()->prepare_for_oops_into_collection_set_do();
init_for_evac_failure(NULL);
rem_set()->prepare_for_younger_refs_iterate(true);
_allocator->release_gc_alloc_regions(n_workers, evacuation_info);
g1_rem_set()->cleanup_after_oops_into_collection_set_do();
COMPILER2_PRESENT(DerivedPointerTable::update_pointers());
}
void G1RemSet::cleanup_after_oops_into_collection_set_do() {
guarantee( _cards_scanned != NULL, "invariant" );
_total_cards_scanned = 0;
for (uint i = 0; i < n_workers(); ++i) {
_total_cards_scanned += _cards_scanned[i];
}
FREE_C_HEAP_ARRAY(size_t, _cards_scanned, mtGC);
_cards_scanned = NULL;
_g1->set_refine_cte_cl_concurrency(true);
DirtyCardQueueSet& into_cset_dcqs = _g1->into_cset_dirty_card_queue_set();
int into_cset_n_buffers = into_cset_dcqs.completed_buffers_num();
_g1->into_cset_dirty_card_queue_set().clear();
_g1->into_cset_dirty_card_queue_set().clear_n_completed_buffers();
}