8227084: Add timing information for merge heap root preparation

Reviewed-by: sangheki, kbarrett
This commit is contained in:
Thomas Schatzl 2019-07-17 16:33:19 +02:00
parent 5a0525a560
commit ffe79a37c3
6 changed files with 57 additions and 28 deletions

View File

@ -3683,7 +3683,7 @@ void G1CollectedHeap::evacuate_initial_collection_set(G1ParScanThreadStateSet* p
{
Ticks start = Ticks::now();
rem_set()->merge_heap_roots(false /* remset_only */, G1GCPhaseTimes::MergeRS);
rem_set()->merge_heap_roots(true /* initial_evacuation */);
p->record_merge_heap_roots_time((Ticks::now() - start).seconds() * 1000.0);
}
@ -3759,7 +3759,7 @@ void G1CollectedHeap::evacuate_optional_collection_set(G1ParScanThreadStateSet*
{
Ticks start = Ticks::now();
rem_set()->merge_heap_roots(true /* remset_only */, G1GCPhaseTimes::OptMergeRS);
rem_set()->merge_heap_roots(false /* initial_evacuation */);
phase_times()->record_or_add_optional_merge_heap_roots_time((Ticks::now() - start).seconds() * 1000.0);
}

View File

@ -166,6 +166,8 @@ void G1GCPhaseTimes::reset() {
_cur_strong_code_root_purge_time_ms = 0.0;
_cur_merge_heap_roots_time_ms = 0.0;
_cur_optional_merge_heap_roots_time_ms = 0.0;
_cur_prepare_merge_heap_roots_time_ms = 0.0;
_cur_optional_prepare_merge_heap_roots_time_ms = 0.0;
_cur_evac_fail_recalc_used = 0.0;
_cur_evac_fail_remove_self_forwards = 0.0;
_cur_string_deduplication_time_ms = 0.0;
@ -413,6 +415,8 @@ double G1GCPhaseTimes::print_evacuate_optional_collection_set() const {
const double sum_ms = _cur_optional_evac_ms + _cur_optional_merge_heap_roots_time_ms;
if (sum_ms > 0) {
info_time("Merge Optional Heap Roots", _cur_optional_merge_heap_roots_time_ms);
debug_time("Prepare Optional Merge Heap Roots", _cur_optional_prepare_merge_heap_roots_time_ms);
debug_phase(_gc_par_phases[OptMergeRS]);
info_time("Evacuate Optional Collection Set", _cur_optional_evac_ms);
@ -427,6 +431,7 @@ double G1GCPhaseTimes::print_evacuate_optional_collection_set() const {
double G1GCPhaseTimes::print_evacuate_initial_collection_set() const {
info_time("Merge Heap Roots", _cur_merge_heap_roots_time_ms);
debug_time("Prepare Merge Heap Roots", _cur_prepare_merge_heap_roots_time_ms);
debug_phase(_gc_par_phases[MergeRS]);
if (G1HotCardCache::default_use_cache()) {
debug_phase(_gc_par_phases[MergeHCC]);

View File

@ -164,6 +164,9 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
double _cur_merge_heap_roots_time_ms;
double _cur_optional_merge_heap_roots_time_ms;
double _cur_prepare_merge_heap_roots_time_ms;
double _cur_optional_prepare_merge_heap_roots_time_ms;
double _cur_prepare_tlab_time_ms;
double _cur_resize_tlab_time_ms;
@ -308,6 +311,14 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
_cur_optional_merge_heap_roots_time_ms += ms;
}
void record_prepare_merge_heap_roots_time(double ms) {
_cur_prepare_merge_heap_roots_time_ms += ms;
}
void record_or_add_optional_prepare_merge_heap_roots_time(double ms) {
_cur_optional_prepare_merge_heap_roots_time_ms += ms;
}
void record_evac_fail_recalc_used_time(double ms) {
_cur_evac_fail_recalc_used = ms;
}

View File

@ -1078,28 +1078,29 @@ class G1MergeHeapRootsTask : public AbstractGangTask {
HeapRegionClaimer _hr_claimer;
G1RemSetScanState* _scan_state;
bool _remembered_set_only;
G1GCPhaseTimes::GCParPhases _merge_phase;
bool _initial_evacuation;
volatile bool _fast_reclaim_handled;
public:
G1MergeHeapRootsTask(G1RemSetScanState* scan_state, uint num_workers, bool remembered_set_only, G1GCPhaseTimes::GCParPhases merge_phase) :
G1MergeHeapRootsTask(G1RemSetScanState* scan_state, uint num_workers, bool initial_evacuation) :
AbstractGangTask("G1 Merge Heap Roots"),
_hr_claimer(num_workers),
_scan_state(scan_state),
_remembered_set_only(remembered_set_only),
_merge_phase(merge_phase),
_initial_evacuation(initial_evacuation),
_fast_reclaim_handled(false) { }
virtual void work(uint worker_id) {
G1CollectedHeap* g1h = G1CollectedHeap::heap();
G1GCPhaseTimes* p = g1h->phase_times();
G1GCPhaseTimes::GCParPhases merge_remset_phase = _initial_evacuation ?
G1GCPhaseTimes::MergeRS :
G1GCPhaseTimes::OptMergeRS;
// We schedule flushing the remembered sets of humongous fast reclaim candidates
// onto the card table first to allow the remaining parallelized tasks hide it.
if (!_remembered_set_only &&
if (_initial_evacuation &&
p->fast_reclaim_humongous_candidates() > 0 &&
!_fast_reclaim_handled &&
!Atomic::cmpxchg(true, &_fast_reclaim_handled, false)) {
@ -1107,33 +1108,33 @@ public:
G1FlushHumongousCandidateRemSets cl(_scan_state);
g1h->heap_region_iterate(&cl);
p->record_or_add_thread_work_item(_merge_phase, worker_id, cl.merged_sparse(), G1GCPhaseTimes::MergeRSMergedSparse);
p->record_or_add_thread_work_item(_merge_phase, worker_id, cl.merged_fine(), G1GCPhaseTimes::MergeRSMergedFine);
p->record_or_add_thread_work_item(_merge_phase, worker_id, cl.merged_coarse(), G1GCPhaseTimes::MergeRSMergedCoarse);
p->record_or_add_thread_work_item(merge_remset_phase, worker_id, cl.merged_sparse(), G1GCPhaseTimes::MergeRSMergedSparse);
p->record_or_add_thread_work_item(merge_remset_phase, worker_id, cl.merged_fine(), G1GCPhaseTimes::MergeRSMergedFine);
p->record_or_add_thread_work_item(merge_remset_phase, worker_id, cl.merged_coarse(), G1GCPhaseTimes::MergeRSMergedCoarse);
}
// Merge remembered sets of current candidates.
{
G1GCParPhaseTimesTracker x(p, _merge_phase, worker_id, !_remembered_set_only /* must_record */);
G1GCParPhaseTimesTracker x(p, merge_remset_phase, worker_id, _initial_evacuation /* must_record */);
G1MergeCardSetClosure cl(_scan_state);
g1h->collection_set_iterate_increment_from(&cl, &_hr_claimer, worker_id);
p->record_or_add_thread_work_item(_merge_phase, worker_id, cl.merged_sparse(), G1GCPhaseTimes::MergeRSMergedSparse);
p->record_or_add_thread_work_item(_merge_phase, worker_id, cl.merged_fine(), G1GCPhaseTimes::MergeRSMergedFine);
p->record_or_add_thread_work_item(_merge_phase, worker_id, cl.merged_coarse(), G1GCPhaseTimes::MergeRSMergedCoarse);
p->record_or_add_thread_work_item(merge_remset_phase, worker_id, cl.merged_sparse(), G1GCPhaseTimes::MergeRSMergedSparse);
p->record_or_add_thread_work_item(merge_remset_phase, worker_id, cl.merged_fine(), G1GCPhaseTimes::MergeRSMergedFine);
p->record_or_add_thread_work_item(merge_remset_phase, worker_id, cl.merged_coarse(), G1GCPhaseTimes::MergeRSMergedCoarse);
}
// Apply closure to log entries in the HCC.
if (!_remembered_set_only && G1HotCardCache::default_use_cache()) {
assert(_merge_phase == G1GCPhaseTimes::MergeRS, "Wrong merge phase");
if (_initial_evacuation && G1HotCardCache::default_use_cache()) {
assert(merge_remset_phase == G1GCPhaseTimes::MergeRS, "Wrong merge phase");
G1GCParPhaseTimesTracker x(p, G1GCPhaseTimes::MergeHCC, worker_id);
G1MergeLogBufferCardsClosure cl(g1h, _scan_state);
g1h->iterate_hcc_closure(&cl, worker_id);
}
// Now apply the closure to all remaining log entries.
if (!_remembered_set_only) {
assert(_merge_phase == G1GCPhaseTimes::MergeRS, "Wrong merge phase");
if (_initial_evacuation) {
assert(merge_remset_phase == G1GCPhaseTimes::MergeRS, "Wrong merge phase");
G1GCParPhaseTimesTracker x(p, G1GCPhaseTimes::MergeLB, worker_id);
G1MergeLogBufferCardsClosure cl(g1h, _scan_state);
@ -1162,19 +1163,30 @@ void G1RemSet::print_merge_heap_roots_stats() {
percent_of(num_visited_cards, total_old_region_cards));
}
void G1RemSet::merge_heap_roots(bool remembered_set_only, G1GCPhaseTimes::GCParPhases merge_phase) {
void G1RemSet::merge_heap_roots(bool initial_evacuation) {
G1CollectedHeap* g1h = G1CollectedHeap::heap();
{
Ticks start = Ticks::now();
_scan_state->prepare_for_merge_heap_roots();
Tickspan total = Ticks::now() - start;
if (initial_evacuation) {
g1h->phase_times()->record_prepare_merge_heap_roots_time(total.seconds() * 1000.0);
} else {
g1h->phase_times()->record_or_add_optional_prepare_merge_heap_roots_time(total.seconds() * 1000.0);
}
}
WorkGang* workers = G1CollectedHeap::heap()->workers();
size_t const increment_length = G1CollectedHeap::heap()->collection_set()->increment_length();
WorkGang* workers = g1h->workers();
size_t const increment_length = g1h->collection_set()->increment_length();
uint const num_workers = !remembered_set_only ? workers->active_workers() :
MIN2(workers->active_workers(), (uint)increment_length);
uint const num_workers = initial_evacuation ? workers->active_workers() :
MIN2(workers->active_workers(), (uint)increment_length);
{
G1MergeHeapRootsTask cl(_scan_state, num_workers, remembered_set_only, merge_phase);
G1MergeHeapRootsTask cl(_scan_state, num_workers, initial_evacuation);
log_debug(gc, ergo)("Running %s using %u workers for " SIZE_FORMAT " regions",
cl.name(), num_workers, increment_length);
workers->run_task(&cl, num_workers);

View File

@ -95,8 +95,8 @@ public:
// Merge cards from various sources (remembered sets, hot card cache, log buffers)
// and calculate the cards that need to be scanned later (via scan_heap_roots()).
// If remembered_set_only is set, only merge remembered set cards.
void merge_heap_roots(bool remembered_set_only, G1GCPhaseTimes::GCParPhases merge_phase);
// If initial_evacuation is set, this is called during the initial evacuation.
void merge_heap_roots(bool initial_evacuation);
// Prepare for and cleanup after scanning the heap roots. Must be called
// once before and after in sequential code.

View File

@ -97,6 +97,7 @@ public class TestGCLogMessages {
// Merge Heap Roots
new LogMessageWithLevel("Merge Heap Roots", Level.INFO),
new LogMessageWithLevel("Prepare Merge Heap Roots", Level.DEBUG),
new LogMessageWithLevel("Remembered Sets", Level.DEBUG),
new LogMessageWithLevel("Merged Sparse", Level.DEBUG),
new LogMessageWithLevel("Merged Fine", Level.DEBUG),