mirror of
https://github.com/openjdk/jdk.git
synced 2026-02-20 23:36:18 +00:00
7178363: G1: Remove the serial code for PrintGCDetails and make it a special case of the parallel code
Also reviewed by vitalyd@gmail.com. Introduced the WorkerDataArray class. Fixed some minor logging bugs. Reviewed-by: johnc, mgerdin
This commit is contained in:
parent
2271c9dfad
commit
68bbfe24e7
@ -1246,6 +1246,31 @@ void G1CollectedHeap::print_hrs_post_compaction() {
|
||||
heap_region_iterate(&cl);
|
||||
}
|
||||
|
||||
double G1CollectedHeap::verify(bool guard, const char* msg) {
|
||||
double verify_time_ms = 0.0;
|
||||
|
||||
if (guard && total_collections() >= VerifyGCStartAt) {
|
||||
double verify_start = os::elapsedTime();
|
||||
HandleMark hm; // Discard invalid handles created during verification
|
||||
gclog_or_tty->print(msg);
|
||||
prepare_for_verify();
|
||||
Universe::verify(false /* silent */, VerifyOption_G1UsePrevMarking);
|
||||
verify_time_ms = (os::elapsedTime() - verify_start) * 1000;
|
||||
}
|
||||
|
||||
return verify_time_ms;
|
||||
}
|
||||
|
||||
void G1CollectedHeap::verify_before_gc() {
|
||||
double verify_time_ms = verify(VerifyBeforeGC, " VerifyBeforeGC:");
|
||||
g1_policy()->phase_times()->record_verify_before_time_ms(verify_time_ms);
|
||||
}
|
||||
|
||||
void G1CollectedHeap::verify_after_gc() {
|
||||
double verify_time_ms = verify(VerifyAfterGC, " VerifyAfterGC:");
|
||||
g1_policy()->phase_times()->record_verify_after_time_ms(verify_time_ms);
|
||||
}
|
||||
|
||||
bool G1CollectedHeap::do_collection(bool explicit_gc,
|
||||
bool clear_all_soft_refs,
|
||||
size_t word_size) {
|
||||
@ -1304,14 +1329,8 @@ bool G1CollectedHeap::do_collection(bool explicit_gc,
|
||||
size_t g1h_prev_used = used();
|
||||
assert(used() == recalculate_used(), "Should be equal");
|
||||
|
||||
if (VerifyBeforeGC && total_collections() >= VerifyGCStartAt) {
|
||||
HandleMark hm; // Discard invalid handles created during verification
|
||||
gclog_or_tty->print(" VerifyBeforeGC:");
|
||||
prepare_for_verify();
|
||||
Universe::verify(/* silent */ false,
|
||||
/* option */ VerifyOption_G1UsePrevMarking);
|
||||
verify_before_gc();
|
||||
|
||||
}
|
||||
pre_full_gc_dump();
|
||||
|
||||
COMPILER2_PRESENT(DerivedPointerTable::clear());
|
||||
@ -1378,14 +1397,7 @@ bool G1CollectedHeap::do_collection(bool explicit_gc,
|
||||
|
||||
MemoryService::track_memory_usage();
|
||||
|
||||
if (VerifyAfterGC && total_collections() >= VerifyGCStartAt) {
|
||||
HandleMark hm; // Discard invalid handles created during verification
|
||||
gclog_or_tty->print(" VerifyAfterGC:");
|
||||
prepare_for_verify();
|
||||
Universe::verify(/* silent */ false,
|
||||
/* option */ VerifyOption_G1UsePrevMarking);
|
||||
|
||||
}
|
||||
verify_after_gc();
|
||||
|
||||
assert(!ref_processor_stw()->discovery_enabled(), "Postcondition");
|
||||
ref_processor_stw()->verify_no_references_recorded();
|
||||
@ -2327,8 +2339,7 @@ void G1CollectedHeap::iterate_dirty_card_closure(CardTableEntryClosure* cl,
|
||||
while (dcqs.apply_closure_to_completed_buffer(cl, worker_i, 0, true)) {
|
||||
n_completed_buffers++;
|
||||
}
|
||||
g1_policy()->phase_times()->record_update_rs_processed_buffers(worker_i,
|
||||
(double) n_completed_buffers);
|
||||
g1_policy()->phase_times()->record_update_rs_processed_buffers(worker_i, n_completed_buffers);
|
||||
dcqs.clear_n_completed_buffers();
|
||||
assert(!dcqs.completed_buffers_exist_dirty(), "Completed buffers exist!");
|
||||
}
|
||||
@ -3735,8 +3746,9 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
|
||||
|
||||
int active_workers = (G1CollectedHeap::use_parallel_gc_threads() ?
|
||||
workers()->active_workers() : 1);
|
||||
g1_policy()->phase_times()->note_gc_start(os::elapsedTime(), active_workers,
|
||||
g1_policy()->gcs_are_young(), g1_policy()->during_initial_mark_pause(), gc_cause());
|
||||
double pause_start_sec = os::elapsedTime();
|
||||
g1_policy()->phase_times()->note_gc_start(active_workers);
|
||||
bool initial_mark_gc = g1_policy()->during_initial_mark_pause();
|
||||
|
||||
TraceCollectorStats tcs(g1mm()->incremental_collection_counters());
|
||||
TraceMemoryManagerStats tms(false /* fullGC */, gc_cause());
|
||||
@ -3765,13 +3777,7 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
|
||||
increment_total_collections(false /* full gc */);
|
||||
increment_gc_time_stamp();
|
||||
|
||||
if (VerifyBeforeGC && total_collections() >= VerifyGCStartAt) {
|
||||
HandleMark hm; // Discard invalid handles created during verification
|
||||
gclog_or_tty->print(" VerifyBeforeGC:");
|
||||
prepare_for_verify();
|
||||
Universe::verify(/* silent */ false,
|
||||
/* option */ VerifyOption_G1UsePrevMarking);
|
||||
}
|
||||
verify_before_gc();
|
||||
|
||||
COMPILER2_PRESENT(DerivedPointerTable::clear());
|
||||
|
||||
@ -3984,10 +3990,6 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
|
||||
true /* verify_fingers */);
|
||||
_cm->note_end_of_gc();
|
||||
|
||||
// Collect thread local data to allow the ergonomics to use
|
||||
// the collected information
|
||||
g1_policy()->phase_times()->collapse_par_times();
|
||||
|
||||
// This timing is only used by the ergonomics to handle our pause target.
|
||||
// It is unclear why this should not include the full pause. We will
|
||||
// investigate this in CR 7178365.
|
||||
@ -4020,13 +4022,7 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
|
||||
// scanning cards (see CR 7039627).
|
||||
increment_gc_time_stamp();
|
||||
|
||||
if (VerifyAfterGC && total_collections() >= VerifyGCStartAt) {
|
||||
HandleMark hm; // Discard invalid handles created during verification
|
||||
gclog_or_tty->print(" VerifyAfterGC:");
|
||||
prepare_for_verify();
|
||||
Universe::verify(/* silent */ false,
|
||||
/* option */ VerifyOption_G1UsePrevMarking);
|
||||
}
|
||||
verify_after_gc();
|
||||
|
||||
assert(!ref_processor_stw()->discovery_enabled(), "Postcondition");
|
||||
ref_processor_stw()->verify_no_references_recorded();
|
||||
@ -4050,10 +4046,35 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
|
||||
|
||||
gc_epilogue(false);
|
||||
|
||||
g1_policy()->phase_times()->note_gc_end(os::elapsedTime());
|
||||
if (G1Log::fine()) {
|
||||
if (PrintGCTimeStamps) {
|
||||
gclog_or_tty->stamp();
|
||||
gclog_or_tty->print(": ");
|
||||
}
|
||||
|
||||
// We have to do this after we decide whether to expand the heap or not.
|
||||
GCCauseString gc_cause_str = GCCauseString("GC pause", gc_cause())
|
||||
.append(g1_policy()->gcs_are_young() ? " (young)" : " (mixed)")
|
||||
.append(initial_mark_gc ? " (initial-mark)" : "");
|
||||
|
||||
double pause_time_sec = os::elapsedTime() - pause_start_sec;
|
||||
|
||||
if (G1Log::finer()) {
|
||||
if (evacuation_failed()) {
|
||||
gc_cause_str.append(" (to-space exhausted)");
|
||||
}
|
||||
gclog_or_tty->print_cr("[%s, %3.7f secs]", (const char*)gc_cause_str, pause_time_sec);
|
||||
g1_policy()->phase_times()->note_gc_end();
|
||||
g1_policy()->phase_times()->print(pause_time_sec);
|
||||
g1_policy()->print_detailed_heap_transition();
|
||||
} else {
|
||||
if (evacuation_failed()) {
|
||||
gc_cause_str.append("--");
|
||||
}
|
||||
gclog_or_tty->print("[%s", (const char*)gc_cause_str);
|
||||
g1_policy()->print_heap_transition();
|
||||
gclog_or_tty->print_cr(", %3.7f secs]", pause_time_sec);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// It is not yet to safe to tell the concurrent mark to
|
||||
@ -4863,7 +4884,7 @@ public:
|
||||
evac.do_void();
|
||||
double elapsed_ms = (os::elapsedTime()-start)*1000.0;
|
||||
double term_ms = pss.term_time()*1000.0;
|
||||
_g1h->g1_policy()->phase_times()->record_obj_copy_time(worker_id, elapsed_ms-term_ms);
|
||||
_g1h->g1_policy()->phase_times()->add_obj_copy_time(worker_id, elapsed_ms-term_ms);
|
||||
_g1h->g1_policy()->phase_times()->record_termination(worker_id, term_ms, pss.term_attempts());
|
||||
}
|
||||
_g1h->g1_policy()->record_thread_age_table(pss.age_table());
|
||||
@ -4991,27 +5012,28 @@ g1_process_strong_roots(bool collecting_perm_gen,
|
||||
buf_scan_non_heap_roots.done();
|
||||
buf_scan_perm.done();
|
||||
|
||||
double ext_roots_end = os::elapsedTime();
|
||||
|
||||
g1_policy()->phase_times()->reset_obj_copy_time(worker_i);
|
||||
double obj_copy_time_sec = buf_scan_perm.closure_app_seconds() +
|
||||
buf_scan_non_heap_roots.closure_app_seconds();
|
||||
g1_policy()->phase_times()->record_obj_copy_time(worker_i, obj_copy_time_sec * 1000.0);
|
||||
|
||||
double ext_root_time_ms =
|
||||
((ext_roots_end - ext_roots_start) - obj_copy_time_sec) * 1000.0;
|
||||
((os::elapsedTime() - ext_roots_start) - obj_copy_time_sec) * 1000.0;
|
||||
|
||||
g1_policy()->phase_times()->record_ext_root_scan_time(worker_i, ext_root_time_ms);
|
||||
|
||||
// During conc marking we have to filter the per-thread SATB buffers
|
||||
// to make sure we remove any oops into the CSet (which will show up
|
||||
// as implicitly live).
|
||||
double satb_filtering_ms = 0.0;
|
||||
if (!_process_strong_tasks->is_task_claimed(G1H_PS_filter_satb_buffers)) {
|
||||
if (mark_in_progress()) {
|
||||
double satb_filter_start = os::elapsedTime();
|
||||
|
||||
JavaThread::satb_mark_queue_set().filter_thread_buffers();
|
||||
|
||||
satb_filtering_ms = (os::elapsedTime() - satb_filter_start) * 1000.0;
|
||||
}
|
||||
}
|
||||
double satb_filtering_ms = (os::elapsedTime() - ext_roots_end) * 1000.0;
|
||||
g1_policy()->phase_times()->record_satb_filtering_time(worker_i, satb_filtering_ms);
|
||||
|
||||
// Now scan the complement of the collection set.
|
||||
@ -5647,11 +5669,6 @@ void G1CollectedHeap::evacuate_collection_set() {
|
||||
|
||||
if (evacuation_failed()) {
|
||||
remove_self_forwarding_pointers();
|
||||
if (G1Log::finer()) {
|
||||
gclog_or_tty->print(" (to-space exhausted)");
|
||||
} else if (G1Log::fine()) {
|
||||
gclog_or_tty->print("--");
|
||||
}
|
||||
}
|
||||
|
||||
// Enqueue any remaining references remaining on the STW
|
||||
|
||||
@ -405,6 +405,10 @@ private:
|
||||
// heap after a compaction.
|
||||
void print_hrs_post_compaction();
|
||||
|
||||
double verify(bool guard, const char* msg);
|
||||
void verify_before_gc();
|
||||
void verify_after_gc();
|
||||
|
||||
// These are macros so that, if the assert fires, we get the correct
|
||||
// line number, file, etc.
|
||||
|
||||
|
||||
@ -795,7 +795,7 @@ void G1CollectorPolicy::record_collection_pause_start(double start_time_sec,
|
||||
_trace_gen0_time_data.record_start_collection(s_w_t_ms);
|
||||
_stop_world_start = 0.0;
|
||||
|
||||
phase_times()->_cur_collection_start_sec = start_time_sec;
|
||||
phase_times()->record_cur_collection_start_sec(start_time_sec);
|
||||
_cur_collection_pause_used_at_start_bytes = start_used;
|
||||
_cur_collection_pause_used_regions_at_start = _g1->used_regions();
|
||||
_pending_cards = _g1->pending_card_num();
|
||||
@ -947,7 +947,7 @@ void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) {
|
||||
_trace_gen0_time_data.record_end_collection(pause_time_ms, phase_times());
|
||||
// this is where we update the allocation rate of the application
|
||||
double app_time_ms =
|
||||
(phase_times()->_cur_collection_start_sec * 1000.0 - _prev_collection_pause_end_ms);
|
||||
(phase_times()->cur_collection_start_sec() * 1000.0 - _prev_collection_pause_end_ms);
|
||||
if (app_time_ms < MIN_TIMER_GRANULARITY) {
|
||||
// This usually happens due to the timer not having the required
|
||||
// granularity. Some Linuxes are the usual culprits.
|
||||
@ -1035,7 +1035,7 @@ void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) {
|
||||
if (update_stats) {
|
||||
double cost_per_card_ms = 0.0;
|
||||
if (_pending_cards > 0) {
|
||||
cost_per_card_ms = phase_times()->_update_rs_time / (double) _pending_cards;
|
||||
cost_per_card_ms = phase_times()->average_last_update_rs_time() / (double) _pending_cards;
|
||||
_cost_per_card_ms_seq->add(cost_per_card_ms);
|
||||
}
|
||||
|
||||
@ -1043,7 +1043,7 @@ void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) {
|
||||
|
||||
double cost_per_entry_ms = 0.0;
|
||||
if (cards_scanned > 10) {
|
||||
cost_per_entry_ms = phase_times()->_scan_rs_time / (double) cards_scanned;
|
||||
cost_per_entry_ms = phase_times()->average_last_scan_rs_time() / (double) cards_scanned;
|
||||
if (_last_gc_was_young) {
|
||||
_cost_per_entry_ms_seq->add(cost_per_entry_ms);
|
||||
} else {
|
||||
@ -1083,7 +1083,7 @@ void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) {
|
||||
size_t copied_bytes = surviving_bytes;
|
||||
double cost_per_byte_ms = 0.0;
|
||||
if (copied_bytes > 0) {
|
||||
cost_per_byte_ms = phase_times()->_obj_copy_time / (double) copied_bytes;
|
||||
cost_per_byte_ms = phase_times()->average_last_obj_copy_time() / (double) copied_bytes;
|
||||
if (_in_marking_window) {
|
||||
_cost_per_byte_ms_during_cm_seq->add(cost_per_byte_ms);
|
||||
} else {
|
||||
@ -1092,21 +1092,22 @@ void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) {
|
||||
}
|
||||
|
||||
double all_other_time_ms = pause_time_ms -
|
||||
(phase_times()->_update_rs_time + phase_times()->_scan_rs_time + phase_times()->_obj_copy_time + phase_times()->_termination_time);
|
||||
(phase_times()->average_last_update_rs_time() + phase_times()->average_last_scan_rs_time()
|
||||
+ phase_times()->average_last_obj_copy_time() + phase_times()->average_last_termination_time());
|
||||
|
||||
double young_other_time_ms = 0.0;
|
||||
if (young_cset_region_length() > 0) {
|
||||
young_other_time_ms =
|
||||
phase_times()->_recorded_young_cset_choice_time_ms +
|
||||
phase_times()->_recorded_young_free_cset_time_ms;
|
||||
phase_times()->young_cset_choice_time_ms() +
|
||||
phase_times()->young_free_cset_time_ms();
|
||||
_young_other_cost_per_region_ms_seq->add(young_other_time_ms /
|
||||
(double) young_cset_region_length());
|
||||
}
|
||||
double non_young_other_time_ms = 0.0;
|
||||
if (old_cset_region_length() > 0) {
|
||||
non_young_other_time_ms =
|
||||
phase_times()->_recorded_non_young_cset_choice_time_ms +
|
||||
phase_times()->_recorded_non_young_free_cset_time_ms;
|
||||
phase_times()->non_young_cset_choice_time_ms() +
|
||||
phase_times()->non_young_free_cset_time_ms();
|
||||
|
||||
_non_young_other_cost_per_region_ms_seq->add(non_young_other_time_ms /
|
||||
(double) old_cset_region_length());
|
||||
@ -1133,7 +1134,8 @@ void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) {
|
||||
|
||||
// Note that _mmu_tracker->max_gc_time() returns the time in seconds.
|
||||
double update_rs_time_goal_ms = _mmu_tracker->max_gc_time() * MILLIUNITS * G1RSetUpdatingPauseTimePercent / 100.0;
|
||||
adjust_concurrent_refinement(phase_times()->_update_rs_time, phase_times()->_update_rs_processed_buffers, update_rs_time_goal_ms);
|
||||
adjust_concurrent_refinement(phase_times()->average_last_update_rs_time(),
|
||||
phase_times()->sum_last_update_rs_processed_buffers(), update_rs_time_goal_ms);
|
||||
|
||||
_collectionSetChooser->verify();
|
||||
}
|
||||
@ -1144,7 +1146,11 @@ void G1CollectorPolicy::record_collection_pause_end(double pause_time_ms) {
|
||||
proper_unit_for_byte_size((bytes))
|
||||
|
||||
void G1CollectorPolicy::print_heap_transition() {
|
||||
if (G1Log::finer()) {
|
||||
_g1->print_size_transition(gclog_or_tty,
|
||||
_cur_collection_pause_used_at_start_bytes, _g1->used(), _g1->capacity());
|
||||
}
|
||||
|
||||
void G1CollectorPolicy::print_detailed_heap_transition() {
|
||||
YoungList* young_list = _g1->young_list();
|
||||
size_t eden_bytes = young_list->eden_used_bytes();
|
||||
size_t survivor_bytes = young_list->survivor_used_bytes();
|
||||
@ -1171,11 +1177,6 @@ void G1CollectorPolicy::print_heap_transition() {
|
||||
EXT_SIZE_PARAMS(capacity));
|
||||
|
||||
_prev_eden_capacity = eden_capacity;
|
||||
} else if (G1Log::fine()) {
|
||||
_g1->print_size_transition(gclog_or_tty,
|
||||
_cur_collection_pause_used_at_start_bytes,
|
||||
_g1->used(), _g1->capacity());
|
||||
}
|
||||
}
|
||||
|
||||
void G1CollectorPolicy::adjust_concurrent_refinement(double update_rs_time,
|
||||
@ -1900,8 +1901,7 @@ void G1CollectorPolicy::finalize_cset(double target_pause_time_ms) {
|
||||
set_recorded_rs_lengths(_inc_cset_recorded_rs_lengths);
|
||||
|
||||
double young_end_time_sec = os::elapsedTime();
|
||||
phase_times()->_recorded_young_cset_choice_time_ms =
|
||||
(young_end_time_sec - young_start_time_sec) * 1000.0;
|
||||
phase_times()->record_young_cset_choice_time_ms((young_end_time_sec - young_start_time_sec) * 1000.0);
|
||||
|
||||
// Set the start of the non-young choice time.
|
||||
double non_young_start_time_sec = young_end_time_sec;
|
||||
@ -2015,8 +2015,7 @@ void G1CollectorPolicy::finalize_cset(double target_pause_time_ms) {
|
||||
predicted_pause_time_ms, target_pause_time_ms);
|
||||
|
||||
double non_young_end_time_sec = os::elapsedTime();
|
||||
phase_times()->_recorded_non_young_cset_choice_time_ms =
|
||||
(non_young_end_time_sec - non_young_start_time_sec) * 1000.0;
|
||||
phase_times()->record_non_young_cset_choice_time_ms((non_young_end_time_sec - non_young_start_time_sec) * 1000.0);
|
||||
}
|
||||
|
||||
void TraceGen0TimeData::record_start_collection(double time_to_stop_the_world_ms) {
|
||||
@ -2035,25 +2034,25 @@ void TraceGen0TimeData::record_end_collection(double pause_time_ms, G1GCPhaseTim
|
||||
if(TraceGen0Time) {
|
||||
_total.add(pause_time_ms);
|
||||
_other.add(pause_time_ms - phase_times->accounted_time_ms());
|
||||
_root_region_scan_wait.add(phase_times->_root_region_scan_wait_time_ms);
|
||||
_parallel.add(phase_times->_cur_collection_par_time_ms);
|
||||
_ext_root_scan.add(phase_times->_ext_root_scan_time);
|
||||
_satb_filtering.add(phase_times->_satb_filtering_time);
|
||||
_update_rs.add(phase_times->_update_rs_time);
|
||||
_scan_rs.add(phase_times->_scan_rs_time);
|
||||
_obj_copy.add(phase_times->_obj_copy_time);
|
||||
_termination.add(phase_times->_termination_time);
|
||||
_root_region_scan_wait.add(phase_times->root_region_scan_wait_time_ms());
|
||||
_parallel.add(phase_times->cur_collection_par_time_ms());
|
||||
_ext_root_scan.add(phase_times->average_last_ext_root_scan_time());
|
||||
_satb_filtering.add(phase_times->average_last_satb_filtering_times_ms());
|
||||
_update_rs.add(phase_times->average_last_update_rs_time());
|
||||
_scan_rs.add(phase_times->average_last_scan_rs_time());
|
||||
_obj_copy.add(phase_times->average_last_obj_copy_time());
|
||||
_termination.add(phase_times->average_last_termination_time());
|
||||
|
||||
double parallel_known_time = phase_times->_ext_root_scan_time +
|
||||
phase_times->_satb_filtering_time +
|
||||
phase_times->_update_rs_time +
|
||||
phase_times->_scan_rs_time +
|
||||
phase_times->_obj_copy_time +
|
||||
+ phase_times->_termination_time;
|
||||
double parallel_known_time = phase_times->average_last_ext_root_scan_time() +
|
||||
phase_times->average_last_satb_filtering_times_ms() +
|
||||
phase_times->average_last_update_rs_time() +
|
||||
phase_times->average_last_scan_rs_time() +
|
||||
phase_times->average_last_obj_copy_time() +
|
||||
+ phase_times->average_last_termination_time();
|
||||
|
||||
double parallel_other_time = phase_times->_cur_collection_par_time_ms - parallel_known_time;
|
||||
double parallel_other_time = phase_times->cur_collection_par_time_ms() - parallel_known_time;
|
||||
_parallel_other.add(parallel_other_time);
|
||||
_clear_ct.add(phase_times->_cur_clear_ct_time_ms);
|
||||
_clear_ct.add(phase_times->cur_clear_ct_time_ms());
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
@ -683,6 +683,7 @@ public:
|
||||
|
||||
void record_collection_pause_end(double pause_time);
|
||||
void print_heap_transition();
|
||||
void print_detailed_heap_transition();
|
||||
|
||||
// Record the fact that a full collection occurred.
|
||||
void record_full_collection_start();
|
||||
|
||||
@ -79,119 +79,145 @@ public:
|
||||
}
|
||||
};
|
||||
|
||||
G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) :
|
||||
_max_gc_threads(max_gc_threads),
|
||||
_min_clear_cc_time_ms(-1.0),
|
||||
_max_clear_cc_time_ms(-1.0),
|
||||
_cur_clear_cc_time_ms(0.0),
|
||||
_cum_clear_cc_time_ms(0.0),
|
||||
_num_cc_clears(0L)
|
||||
{
|
||||
assert(max_gc_threads > 0, "Must have some GC threads");
|
||||
_par_last_gc_worker_start_times_ms = new double[_max_gc_threads];
|
||||
_par_last_ext_root_scan_times_ms = new double[_max_gc_threads];
|
||||
_par_last_satb_filtering_times_ms = new double[_max_gc_threads];
|
||||
_par_last_update_rs_times_ms = new double[_max_gc_threads];
|
||||
_par_last_update_rs_processed_buffers = new double[_max_gc_threads];
|
||||
_par_last_scan_rs_times_ms = new double[_max_gc_threads];
|
||||
_par_last_obj_copy_times_ms = new double[_max_gc_threads];
|
||||
_par_last_termination_times_ms = new double[_max_gc_threads];
|
||||
_par_last_termination_attempts = new double[_max_gc_threads];
|
||||
_par_last_gc_worker_end_times_ms = new double[_max_gc_threads];
|
||||
_par_last_gc_worker_times_ms = new double[_max_gc_threads];
|
||||
_par_last_gc_worker_other_times_ms = new double[_max_gc_threads];
|
||||
}
|
||||
|
||||
void G1GCPhaseTimes::note_gc_start(double pause_start_time_sec, uint active_gc_threads,
|
||||
bool is_young_gc, bool is_initial_mark_gc, GCCause::Cause gc_cause) {
|
||||
assert(active_gc_threads > 0, "The number of threads must be > 0");
|
||||
assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max nubmer of threads");
|
||||
_active_gc_threads = active_gc_threads;
|
||||
_pause_start_time_sec = pause_start_time_sec;
|
||||
_is_young_gc = is_young_gc;
|
||||
_is_initial_mark_gc = is_initial_mark_gc;
|
||||
_gc_cause = gc_cause;
|
||||
|
||||
#ifdef ASSERT
|
||||
// initialise the timing data to something well known so that we can spot
|
||||
// if something is not set properly
|
||||
|
||||
for (uint i = 0; i < _max_gc_threads; ++i) {
|
||||
_par_last_gc_worker_start_times_ms[i] = -1234.0;
|
||||
_par_last_ext_root_scan_times_ms[i] = -1234.0;
|
||||
_par_last_satb_filtering_times_ms[i] = -1234.0;
|
||||
_par_last_update_rs_times_ms[i] = -1234.0;
|
||||
_par_last_update_rs_processed_buffers[i] = -1234.0;
|
||||
_par_last_scan_rs_times_ms[i] = -1234.0;
|
||||
_par_last_obj_copy_times_ms[i] = -1234.0;
|
||||
_par_last_termination_times_ms[i] = -1234.0;
|
||||
_par_last_termination_attempts[i] = -1234.0;
|
||||
_par_last_gc_worker_end_times_ms[i] = -1234.0;
|
||||
_par_last_gc_worker_times_ms[i] = -1234.0;
|
||||
_par_last_gc_worker_other_times_ms[i] = -1234.0;
|
||||
}
|
||||
#endif
|
||||
}
|
||||
|
||||
void G1GCPhaseTimes::note_gc_end(double pause_end_time_sec) {
|
||||
if (G1Log::fine()) {
|
||||
double pause_time_ms = (pause_end_time_sec - _pause_start_time_sec) * MILLIUNITS;
|
||||
|
||||
for (uint i = 0; i < _active_gc_threads; i++) {
|
||||
_par_last_gc_worker_times_ms[i] = _par_last_gc_worker_end_times_ms[i] -
|
||||
_par_last_gc_worker_start_times_ms[i];
|
||||
|
||||
double worker_known_time = _par_last_ext_root_scan_times_ms[i] +
|
||||
_par_last_satb_filtering_times_ms[i] +
|
||||
_par_last_update_rs_times_ms[i] +
|
||||
_par_last_scan_rs_times_ms[i] +
|
||||
_par_last_obj_copy_times_ms[i] +
|
||||
_par_last_termination_times_ms[i];
|
||||
|
||||
_par_last_gc_worker_other_times_ms[i] = _par_last_gc_worker_times_ms[i] -
|
||||
worker_known_time;
|
||||
}
|
||||
|
||||
print(pause_time_ms);
|
||||
template <class T>
|
||||
void WorkerDataArray<T>::print(int level, const char* title) {
|
||||
if (_length == 1) {
|
||||
// No need for min, max, average and sum for only one worker
|
||||
LineBuffer buf(level);
|
||||
buf.append("[%s: ", title);
|
||||
buf.append(_print_format, _data[0]);
|
||||
buf.append_and_print_cr("]");
|
||||
return;
|
||||
}
|
||||
|
||||
}
|
||||
T min = _data[0];
|
||||
T max = _data[0];
|
||||
T sum = 0;
|
||||
|
||||
void G1GCPhaseTimes::print_par_stats(int level,
|
||||
const char* str,
|
||||
double* data,
|
||||
bool showDecimals) {
|
||||
double min = data[0], max = data[0];
|
||||
double total = 0.0;
|
||||
LineBuffer buf(level);
|
||||
buf.append("[%s (ms):", str);
|
||||
for (uint i = 0; i < _active_gc_threads; ++i) {
|
||||
double val = data[i];
|
||||
if (val < min)
|
||||
min = val;
|
||||
if (val > max)
|
||||
max = val;
|
||||
total += val;
|
||||
buf.append("[%s:", title);
|
||||
for (uint i = 0; i < _length; ++i) {
|
||||
T val = _data[i];
|
||||
min = MIN2(val, min);
|
||||
max = MAX2(val, max);
|
||||
sum += val;
|
||||
if (G1Log::finest()) {
|
||||
if (showDecimals) {
|
||||
buf.append(" %.1lf", val);
|
||||
} else {
|
||||
buf.append(" %d", (int)val);
|
||||
}
|
||||
buf.append(" ");
|
||||
buf.append(_print_format, val);
|
||||
}
|
||||
}
|
||||
|
||||
if (G1Log::finest()) {
|
||||
buf.append_and_print_cr("");
|
||||
}
|
||||
double avg = total / (double) _active_gc_threads;
|
||||
if (showDecimals) {
|
||||
buf.append_and_print_cr(" Min: %.1lf, Avg: %.1lf, Max: %.1lf, Diff: %.1lf, Sum: %.1lf]",
|
||||
min, avg, max, max - min, total);
|
||||
} else {
|
||||
buf.append_and_print_cr(" Min: %d, Avg: %d, Max: %d, Diff: %d, Sum: %d]",
|
||||
(int)min, (int)avg, (int)max, (int)max - (int)min, (int)total);
|
||||
|
||||
double avg = (double)sum / (double)_length;
|
||||
buf.append(" Min: ");
|
||||
buf.append(_print_format, min);
|
||||
buf.append(", Avg: ");
|
||||
buf.append("%.1lf", avg); // Always print average as a double
|
||||
buf.append(", Max: ");
|
||||
buf.append(_print_format, max);
|
||||
buf.append(", Diff: ");
|
||||
buf.append(_print_format, max - min);
|
||||
if (_print_sum) {
|
||||
// for things like the start and end times the sum is not
|
||||
// that relevant
|
||||
buf.append(", Sum: ");
|
||||
buf.append(_print_format, sum);
|
||||
}
|
||||
buf.append_and_print_cr("]");
|
||||
}
|
||||
|
||||
#ifdef ASSERT
|
||||
|
||||
template <class T>
|
||||
void WorkerDataArray<T>::reset() {
|
||||
for (uint i = 0; i < _length; i++) {
|
||||
_data[i] = (T)-1;
|
||||
}
|
||||
}
|
||||
|
||||
template <class T>
|
||||
void WorkerDataArray<T>::verify() {
|
||||
for (uint i = 0; i < _length; i++) {
|
||||
assert(_data[i] >= (T)0, err_msg("Invalid data for worker %d", i));
|
||||
}
|
||||
}
|
||||
|
||||
#endif
|
||||
|
||||
G1GCPhaseTimes::G1GCPhaseTimes(uint max_gc_threads) :
|
||||
_max_gc_threads(max_gc_threads),
|
||||
_min_clear_cc_time_ms(-1.0),
|
||||
_max_clear_cc_time_ms(-1.0),
|
||||
_cur_clear_cc_time_ms(0.0),
|
||||
_cum_clear_cc_time_ms(0.0),
|
||||
_num_cc_clears(0L),
|
||||
_last_gc_worker_start_times_ms(_max_gc_threads, "%.1lf", false),
|
||||
_last_ext_root_scan_times_ms(_max_gc_threads, "%.1lf"),
|
||||
_last_satb_filtering_times_ms(_max_gc_threads, "%.1lf"),
|
||||
_last_update_rs_times_ms(_max_gc_threads, "%.1lf"),
|
||||
_last_update_rs_processed_buffers(_max_gc_threads, "%d"),
|
||||
_last_scan_rs_times_ms(_max_gc_threads, "%.1lf"),
|
||||
_last_obj_copy_times_ms(_max_gc_threads, "%.1lf"),
|
||||
_last_termination_times_ms(_max_gc_threads, "%.1lf"),
|
||||
_last_termination_attempts(_max_gc_threads, SIZE_FORMAT),
|
||||
_last_gc_worker_end_times_ms(_max_gc_threads, "%.1lf", false),
|
||||
_last_gc_worker_times_ms(_max_gc_threads, "%.1lf"),
|
||||
_last_gc_worker_other_times_ms(_max_gc_threads, "%.1lf")
|
||||
{
|
||||
assert(max_gc_threads > 0, "Must have some GC threads");
|
||||
}
|
||||
|
||||
void G1GCPhaseTimes::note_gc_start(uint active_gc_threads) {
|
||||
assert(active_gc_threads > 0, "The number of threads must be > 0");
|
||||
assert(active_gc_threads <= _max_gc_threads, "The number of active threads must be <= the max nubmer of threads");
|
||||
_active_gc_threads = active_gc_threads;
|
||||
|
||||
_last_gc_worker_start_times_ms.reset();
|
||||
_last_ext_root_scan_times_ms.reset();
|
||||
_last_satb_filtering_times_ms.reset();
|
||||
_last_update_rs_times_ms.reset();
|
||||
_last_update_rs_processed_buffers.reset();
|
||||
_last_scan_rs_times_ms.reset();
|
||||
_last_obj_copy_times_ms.reset();
|
||||
_last_termination_times_ms.reset();
|
||||
_last_termination_attempts.reset();
|
||||
_last_gc_worker_end_times_ms.reset();
|
||||
_last_gc_worker_times_ms.reset();
|
||||
_last_gc_worker_other_times_ms.reset();
|
||||
}
|
||||
|
||||
void G1GCPhaseTimes::note_gc_end() {
|
||||
_last_gc_worker_start_times_ms.verify();
|
||||
_last_ext_root_scan_times_ms.verify();
|
||||
_last_satb_filtering_times_ms.verify();
|
||||
_last_update_rs_times_ms.verify();
|
||||
_last_update_rs_processed_buffers.verify();
|
||||
_last_scan_rs_times_ms.verify();
|
||||
_last_obj_copy_times_ms.verify();
|
||||
_last_termination_times_ms.verify();
|
||||
_last_termination_attempts.verify();
|
||||
_last_gc_worker_end_times_ms.verify();
|
||||
|
||||
for (uint i = 0; i < _active_gc_threads; i++) {
|
||||
double worker_time = _last_gc_worker_end_times_ms.get(i) - _last_gc_worker_start_times_ms.get(i);
|
||||
_last_gc_worker_times_ms.set(i, worker_time);
|
||||
|
||||
double worker_known_time = _last_ext_root_scan_times_ms.get(i) +
|
||||
_last_satb_filtering_times_ms.get(i) +
|
||||
_last_update_rs_times_ms.get(i) +
|
||||
_last_scan_rs_times_ms.get(i) +
|
||||
_last_obj_copy_times_ms.get(i) +
|
||||
_last_termination_times_ms.get(i);
|
||||
|
||||
double worker_other_time = worker_time - worker_known_time;
|
||||
_last_gc_worker_other_times_ms.set(i, worker_other_time);
|
||||
}
|
||||
|
||||
_last_gc_worker_times_ms.verify();
|
||||
_last_gc_worker_other_times_ms.verify();
|
||||
}
|
||||
|
||||
void G1GCPhaseTimes::print_stats(int level, const char* str, double value) {
|
||||
@ -202,73 +228,6 @@ void G1GCPhaseTimes::print_stats(int level, const char* str, double value, int w
|
||||
LineBuffer(level).append_and_print_cr("[%s: %.1lf ms, GC Workers: %d]", str, value, workers);
|
||||
}
|
||||
|
||||
void G1GCPhaseTimes::print_stats(int level, const char* str, int value) {
|
||||
LineBuffer(level).append_and_print_cr("[%s: %d]", str, value);
|
||||
}
|
||||
|
||||
double G1GCPhaseTimes::avg_value(double* data) {
|
||||
if (G1CollectedHeap::use_parallel_gc_threads()) {
|
||||
double ret = 0.0;
|
||||
for (uint i = 0; i < _active_gc_threads; ++i) {
|
||||
ret += data[i];
|
||||
}
|
||||
return ret / (double) _active_gc_threads;
|
||||
} else {
|
||||
return data[0];
|
||||
}
|
||||
}
|
||||
|
||||
double G1GCPhaseTimes::max_value(double* data) {
|
||||
if (G1CollectedHeap::use_parallel_gc_threads()) {
|
||||
double ret = data[0];
|
||||
for (uint i = 1; i < _active_gc_threads; ++i) {
|
||||
if (data[i] > ret) {
|
||||
ret = data[i];
|
||||
}
|
||||
}
|
||||
return ret;
|
||||
} else {
|
||||
return data[0];
|
||||
}
|
||||
}
|
||||
|
||||
double G1GCPhaseTimes::sum_of_values(double* data) {
|
||||
if (G1CollectedHeap::use_parallel_gc_threads()) {
|
||||
double sum = 0.0;
|
||||
for (uint i = 0; i < _active_gc_threads; i++) {
|
||||
sum += data[i];
|
||||
}
|
||||
return sum;
|
||||
} else {
|
||||
return data[0];
|
||||
}
|
||||
}
|
||||
|
||||
double G1GCPhaseTimes::max_sum(double* data1, double* data2) {
|
||||
double ret = data1[0] + data2[0];
|
||||
|
||||
if (G1CollectedHeap::use_parallel_gc_threads()) {
|
||||
for (uint i = 1; i < _active_gc_threads; ++i) {
|
||||
double data = data1[i] + data2[i];
|
||||
if (data > ret) {
|
||||
ret = data;
|
||||
}
|
||||
}
|
||||
}
|
||||
return ret;
|
||||
}
|
||||
|
||||
void G1GCPhaseTimes::collapse_par_times() {
|
||||
_ext_root_scan_time = avg_value(_par_last_ext_root_scan_times_ms);
|
||||
_satb_filtering_time = avg_value(_par_last_satb_filtering_times_ms);
|
||||
_update_rs_time = avg_value(_par_last_update_rs_times_ms);
|
||||
_update_rs_processed_buffers =
|
||||
sum_of_values(_par_last_update_rs_processed_buffers);
|
||||
_scan_rs_time = avg_value(_par_last_scan_rs_times_ms);
|
||||
_obj_copy_time = avg_value(_par_last_obj_copy_times_ms);
|
||||
_termination_time = avg_value(_par_last_termination_times_ms);
|
||||
}
|
||||
|
||||
double G1GCPhaseTimes::accounted_time_ms() {
|
||||
// Subtract the root region scanning wait time. It's initialized to
|
||||
// zero at the start of the pause.
|
||||
@ -286,58 +245,37 @@ double G1GCPhaseTimes::accounted_time_ms() {
|
||||
return misc_time_ms;
|
||||
}
|
||||
|
||||
void G1GCPhaseTimes::print(double pause_time_ms) {
|
||||
|
||||
if (PrintGCTimeStamps) {
|
||||
gclog_or_tty->stamp();
|
||||
gclog_or_tty->print(": ");
|
||||
}
|
||||
|
||||
GCCauseString gc_cause_str = GCCauseString("GC pause", _gc_cause)
|
||||
.append(_is_young_gc ? " (young)" : " (mixed)")
|
||||
.append(_is_initial_mark_gc ? " (initial-mark)" : "");
|
||||
gclog_or_tty->print_cr("[%s, %3.7f secs]", (const char*)gc_cause_str, pause_time_ms / 1000.0);
|
||||
|
||||
if (!G1Log::finer()) {
|
||||
return;
|
||||
}
|
||||
|
||||
void G1GCPhaseTimes::print(double pause_time_sec) {
|
||||
if (_root_region_scan_wait_time_ms > 0.0) {
|
||||
print_stats(1, "Root Region Scan Waiting", _root_region_scan_wait_time_ms);
|
||||
}
|
||||
if (G1CollectedHeap::use_parallel_gc_threads()) {
|
||||
print_stats(1, "Parallel Time", _cur_collection_par_time_ms, _active_gc_threads);
|
||||
print_par_stats(2, "GC Worker Start", _par_last_gc_worker_start_times_ms);
|
||||
print_par_stats(2, "Ext Root Scanning", _par_last_ext_root_scan_times_ms);
|
||||
if (_satb_filtering_time > 0.0) {
|
||||
print_par_stats(2, "SATB Filtering", _par_last_satb_filtering_times_ms);
|
||||
_last_gc_worker_start_times_ms.print(2, "GC Worker Start (ms)");
|
||||
_last_ext_root_scan_times_ms.print(2, "Ext Root Scanning (ms)");
|
||||
if (_last_satb_filtering_times_ms.sum() > 0.0) {
|
||||
_last_satb_filtering_times_ms.print(2, "SATB Filtering (ms)");
|
||||
}
|
||||
print_par_stats(2, "Update RS", _par_last_update_rs_times_ms);
|
||||
_last_update_rs_times_ms.print(2, "Update RS (ms)");
|
||||
_last_update_rs_processed_buffers.print(3, "Processed Buffers");
|
||||
_last_scan_rs_times_ms.print(2, "Scan RS (ms)");
|
||||
_last_obj_copy_times_ms.print(2, "Object Copy (ms)");
|
||||
_last_termination_times_ms.print(2, "Termination (ms)");
|
||||
if (G1Log::finest()) {
|
||||
print_par_stats(3, "Processed Buffers", _par_last_update_rs_processed_buffers,
|
||||
false /* showDecimals */);
|
||||
_last_termination_attempts.print(3, "Termination Attempts");
|
||||
}
|
||||
print_par_stats(2, "Scan RS", _par_last_scan_rs_times_ms);
|
||||
print_par_stats(2, "Object Copy", _par_last_obj_copy_times_ms);
|
||||
print_par_stats(2, "Termination", _par_last_termination_times_ms);
|
||||
if (G1Log::finest()) {
|
||||
print_par_stats(3, "Termination Attempts", _par_last_termination_attempts,
|
||||
false /* showDecimals */);
|
||||
}
|
||||
print_par_stats(2, "GC Worker Other", _par_last_gc_worker_other_times_ms);
|
||||
print_par_stats(2, "GC Worker Total", _par_last_gc_worker_times_ms);
|
||||
print_par_stats(2, "GC Worker End", _par_last_gc_worker_end_times_ms);
|
||||
_last_gc_worker_other_times_ms.print(2, "GC Worker Other (ms)");
|
||||
_last_gc_worker_times_ms.print(2, "GC Worker Total (ms)");
|
||||
_last_gc_worker_end_times_ms.print(2, "GC Worker End (ms)");
|
||||
} else {
|
||||
print_stats(1, "Ext Root Scanning", _ext_root_scan_time);
|
||||
if (_satb_filtering_time > 0.0) {
|
||||
print_stats(1, "SATB Filtering", _satb_filtering_time);
|
||||
_last_ext_root_scan_times_ms.print(1, "Ext Root Scanning (ms)");
|
||||
if (_last_satb_filtering_times_ms.sum() > 0.0) {
|
||||
_last_satb_filtering_times_ms.print(1, "SATB Filtering (ms)");
|
||||
}
|
||||
print_stats(1, "Update RS", _update_rs_time);
|
||||
if (G1Log::finest()) {
|
||||
print_stats(2, "Processed Buffers", (int)_update_rs_processed_buffers);
|
||||
}
|
||||
print_stats(1, "Scan RS", _scan_rs_time);
|
||||
print_stats(1, "Object Copying", _obj_copy_time);
|
||||
_last_update_rs_times_ms.print(1, "Update RS (ms)");
|
||||
_last_update_rs_processed_buffers.print(2, "Processed Buffers");
|
||||
_last_scan_rs_times_ms.print(1, "Scan RS (ms)");
|
||||
_last_obj_copy_times_ms.print(1, "Object Copy (ms)");
|
||||
}
|
||||
print_stats(1, "Code Root Fixup", _cur_collection_code_root_fixup_time_ms);
|
||||
print_stats(1, "Clear CT", _cur_clear_ct_time_ms);
|
||||
@ -350,8 +288,11 @@ void G1GCPhaseTimes::print(double pause_time_ms) {
|
||||
print_stats(1, "Avg Clear CC", _cum_clear_cc_time_ms / ((double)_num_cc_clears));
|
||||
}
|
||||
}
|
||||
double misc_time_ms = pause_time_ms - accounted_time_ms();
|
||||
double misc_time_ms = pause_time_sec * MILLIUNITS - accounted_time_ms();
|
||||
print_stats(1, "Other", misc_time_ms);
|
||||
if (_cur_verify_before_time_ms > 0.0) {
|
||||
print_stats(2, "Verify Before", _cur_verify_before_time_ms);
|
||||
}
|
||||
print_stats(2, "Choose CSet",
|
||||
(_recorded_young_cset_choice_time_ms +
|
||||
_recorded_non_young_cset_choice_time_ms));
|
||||
@ -360,6 +301,9 @@ void G1GCPhaseTimes::print(double pause_time_ms) {
|
||||
print_stats(2, "Free CSet",
|
||||
(_recorded_young_free_cset_time_ms +
|
||||
_recorded_non_young_free_cset_time_ms));
|
||||
if (_cur_verify_after_time_ms > 0.0) {
|
||||
print_stats(2, "Verify After", _cur_verify_after_time_ms);
|
||||
}
|
||||
}
|
||||
|
||||
void G1GCPhaseTimes::record_cc_clear_time_ms(double ms) {
|
||||
|
||||
@ -28,52 +28,109 @@
|
||||
#include "memory/allocation.hpp"
|
||||
#include "gc_interface/gcCause.hpp"
|
||||
|
||||
template <class T>
|
||||
class WorkerDataArray : public CHeapObj<mtGC> {
|
||||
T* _data;
|
||||
uint _length;
|
||||
const char* _print_format;
|
||||
bool _print_sum;
|
||||
|
||||
// We are caching the sum and average to only have to calculate them once.
|
||||
// This is not done in an MT-safe way. It is intetened to allow single
|
||||
// threaded code to call sum() and average() multiple times in any order
|
||||
// without having to worry about the cost.
|
||||
bool _has_new_data;
|
||||
T _sum;
|
||||
double _average;
|
||||
|
||||
public:
|
||||
WorkerDataArray(uint length, const char* print_format, bool print_sum = true) :
|
||||
_length(length), _print_format(print_format), _print_sum(print_sum), _has_new_data(true) {
|
||||
assert(length > 0, "Must have some workers to store data for");
|
||||
_data = NEW_C_HEAP_ARRAY(T, _length, mtGC);
|
||||
}
|
||||
|
||||
~WorkerDataArray() {
|
||||
FREE_C_HEAP_ARRAY(T, _data, mtGC);
|
||||
}
|
||||
|
||||
void set(uint worker_i, T value) {
|
||||
assert(worker_i < _length, err_msg("Worker %d is greater than max: %d", worker_i, _length));
|
||||
assert(_data[worker_i] == (T)-1, err_msg("Overwriting data for worker %d", worker_i));
|
||||
_data[worker_i] = value;
|
||||
_has_new_data = true;
|
||||
}
|
||||
|
||||
T get(uint worker_i) {
|
||||
assert(worker_i < _length, err_msg("Worker %d is greater than max: %d", worker_i, _length));
|
||||
assert(_data[worker_i] != (T)-1, err_msg("No data to add to for worker %d", worker_i));
|
||||
return _data[worker_i];
|
||||
}
|
||||
|
||||
void add(uint worker_i, T value) {
|
||||
assert(worker_i < _length, err_msg("Worker %d is greater than max: %d", worker_i, _length));
|
||||
assert(_data[worker_i] != (T)-1, err_msg("No data to add to for worker %d", worker_i));
|
||||
_data[worker_i] += value;
|
||||
_has_new_data = true;
|
||||
}
|
||||
|
||||
double average(){
|
||||
if (_has_new_data) {
|
||||
calculate_totals();
|
||||
}
|
||||
return _average;
|
||||
}
|
||||
|
||||
T sum() {
|
||||
if (_has_new_data) {
|
||||
calculate_totals();
|
||||
}
|
||||
return _sum;
|
||||
}
|
||||
|
||||
void print(int level, const char* title);
|
||||
|
||||
void reset() PRODUCT_RETURN;
|
||||
void verify() PRODUCT_RETURN;
|
||||
|
||||
private:
|
||||
|
||||
void calculate_totals(){
|
||||
_sum = (T)0;
|
||||
for (uint i = 0; i < _length; ++i) {
|
||||
_sum += _data[i];
|
||||
}
|
||||
_average = (double)_sum / (double)_length;
|
||||
_has_new_data = false;
|
||||
}
|
||||
};
|
||||
|
||||
class G1GCPhaseTimes : public CHeapObj<mtGC> {
|
||||
friend class G1CollectorPolicy;
|
||||
friend class TraceGen0TimeData;
|
||||
|
||||
private:
|
||||
uint _active_gc_threads;
|
||||
uint _max_gc_threads;
|
||||
|
||||
GCCause::Cause _gc_cause;
|
||||
bool _is_young_gc;
|
||||
bool _is_initial_mark_gc;
|
||||
|
||||
double _pause_start_time_sec;
|
||||
|
||||
double* _par_last_gc_worker_start_times_ms;
|
||||
double* _par_last_ext_root_scan_times_ms;
|
||||
double* _par_last_satb_filtering_times_ms;
|
||||
double* _par_last_update_rs_times_ms;
|
||||
double* _par_last_update_rs_processed_buffers;
|
||||
double* _par_last_scan_rs_times_ms;
|
||||
double* _par_last_obj_copy_times_ms;
|
||||
double* _par_last_termination_times_ms;
|
||||
double* _par_last_termination_attempts;
|
||||
double* _par_last_gc_worker_end_times_ms;
|
||||
double* _par_last_gc_worker_times_ms;
|
||||
double* _par_last_gc_worker_other_times_ms;
|
||||
WorkerDataArray<double> _last_gc_worker_start_times_ms;
|
||||
WorkerDataArray<double> _last_ext_root_scan_times_ms;
|
||||
WorkerDataArray<double> _last_satb_filtering_times_ms;
|
||||
WorkerDataArray<double> _last_update_rs_times_ms;
|
||||
WorkerDataArray<int> _last_update_rs_processed_buffers;
|
||||
WorkerDataArray<double> _last_scan_rs_times_ms;
|
||||
WorkerDataArray<double> _last_obj_copy_times_ms;
|
||||
WorkerDataArray<double> _last_termination_times_ms;
|
||||
WorkerDataArray<size_t> _last_termination_attempts;
|
||||
WorkerDataArray<double> _last_gc_worker_end_times_ms;
|
||||
WorkerDataArray<double> _last_gc_worker_times_ms;
|
||||
WorkerDataArray<double> _last_gc_worker_other_times_ms;
|
||||
|
||||
double _cur_collection_par_time_ms;
|
||||
|
||||
double _cur_collection_code_root_fixup_time_ms;
|
||||
|
||||
double _cur_clear_ct_time_ms;
|
||||
double _cur_ref_proc_time_ms;
|
||||
double _cur_ref_enq_time_ms;
|
||||
|
||||
// Helper methods for detailed logging
|
||||
void print_par_stats(int level, const char* str, double* data, bool showDecimals = true);
|
||||
void print_stats(int level, const char* str, double value);
|
||||
void print_stats(int level, const char* str, double value, int workers);
|
||||
void print_stats(int level, const char* str, int value);
|
||||
double avg_value(double* data);
|
||||
double max_value(double* data);
|
||||
double sum_of_values(double* data);
|
||||
double max_sum(double* data1, double* data2);
|
||||
double accounted_time_ms();
|
||||
|
||||
// Card Table Count Cache stats
|
||||
double _min_clear_cc_time_ms; // min
|
||||
double _max_clear_cc_time_ms; // max
|
||||
@ -81,19 +138,6 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
|
||||
double _cum_clear_cc_time_ms; // cummulative clearing time
|
||||
jlong _num_cc_clears; // number of times the card count cache has been cleared
|
||||
|
||||
// The following insance variables are directly accessed by G1CollectorPolicy
|
||||
// and TraceGen0TimeData. This is why those classes are declared friends.
|
||||
// An alternative is to add getters and setters for all of these fields.
|
||||
// It might also be possible to restructure the code to reduce these
|
||||
// dependencies.
|
||||
double _ext_root_scan_time;
|
||||
double _satb_filtering_time;
|
||||
double _update_rs_time;
|
||||
double _update_rs_processed_buffers;
|
||||
double _scan_rs_time;
|
||||
double _obj_copy_time;
|
||||
double _termination_time;
|
||||
|
||||
double _cur_collection_start_sec;
|
||||
double _root_region_scan_wait_time_ms;
|
||||
|
||||
@ -103,79 +147,58 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
|
||||
double _recorded_young_free_cset_time_ms;
|
||||
double _recorded_non_young_free_cset_time_ms;
|
||||
|
||||
void print(double pause_time_ms);
|
||||
double _cur_verify_before_time_ms;
|
||||
double _cur_verify_after_time_ms;
|
||||
|
||||
// Helper methods for detailed logging
|
||||
void print_stats(int level, const char* str, double value);
|
||||
void print_stats(int level, const char* str, double value, int workers);
|
||||
|
||||
public:
|
||||
G1GCPhaseTimes(uint max_gc_threads);
|
||||
void note_gc_start(double pause_start_time_sec, uint active_gc_threads,
|
||||
bool is_young_gc, bool is_initial_mark_gc, GCCause::Cause gc_cause);
|
||||
void note_gc_end(double pause_end_time_sec);
|
||||
void collapse_par_times();
|
||||
void note_gc_start(uint active_gc_threads);
|
||||
void note_gc_end();
|
||||
void print(double pause_time_sec);
|
||||
|
||||
void record_gc_worker_start_time(uint worker_i, double ms) {
|
||||
assert(worker_i >= 0, "worker index must be > 0");
|
||||
assert(worker_i < _active_gc_threads, "worker index out of bounds");
|
||||
_par_last_gc_worker_start_times_ms[worker_i] = ms;
|
||||
_last_gc_worker_start_times_ms.set(worker_i, ms);
|
||||
}
|
||||
|
||||
void record_ext_root_scan_time(uint worker_i, double ms) {
|
||||
assert(worker_i >= 0, "worker index must be > 0");
|
||||
assert(worker_i < _active_gc_threads, "worker index out of bounds");
|
||||
_par_last_ext_root_scan_times_ms[worker_i] = ms;
|
||||
_last_ext_root_scan_times_ms.set(worker_i, ms);
|
||||
}
|
||||
|
||||
void record_satb_filtering_time(uint worker_i, double ms) {
|
||||
assert(worker_i >= 0, "worker index must be > 0");
|
||||
assert(worker_i < _active_gc_threads, "worker index out of bounds");
|
||||
_par_last_satb_filtering_times_ms[worker_i] = ms;
|
||||
_last_satb_filtering_times_ms.set(worker_i, ms);
|
||||
}
|
||||
|
||||
void record_update_rs_time(uint worker_i, double ms) {
|
||||
assert(worker_i >= 0, "worker index must be > 0");
|
||||
assert(worker_i < _active_gc_threads, "worker index out of bounds");
|
||||
_par_last_update_rs_times_ms[worker_i] = ms;
|
||||
_last_update_rs_times_ms.set(worker_i, ms);
|
||||
}
|
||||
|
||||
void record_update_rs_processed_buffers (uint worker_i,
|
||||
double processed_buffers) {
|
||||
assert(worker_i >= 0, "worker index must be > 0");
|
||||
assert(worker_i < _active_gc_threads, "worker index out of bounds");
|
||||
_par_last_update_rs_processed_buffers[worker_i] = processed_buffers;
|
||||
void record_update_rs_processed_buffers(uint worker_i, int processed_buffers) {
|
||||
_last_update_rs_processed_buffers.set(worker_i, processed_buffers);
|
||||
}
|
||||
|
||||
void record_scan_rs_time(uint worker_i, double ms) {
|
||||
assert(worker_i >= 0, "worker index must be > 0");
|
||||
assert(worker_i < _active_gc_threads, "worker index out of bounds");
|
||||
_par_last_scan_rs_times_ms[worker_i] = ms;
|
||||
}
|
||||
|
||||
void reset_obj_copy_time(uint worker_i) {
|
||||
assert(worker_i >= 0, "worker index must be > 0");
|
||||
assert(worker_i < _active_gc_threads, "worker index out of bounds");
|
||||
_par_last_obj_copy_times_ms[worker_i] = 0.0;
|
||||
}
|
||||
|
||||
void reset_obj_copy_time() {
|
||||
reset_obj_copy_time(0);
|
||||
_last_scan_rs_times_ms.set(worker_i, ms);
|
||||
}
|
||||
|
||||
void record_obj_copy_time(uint worker_i, double ms) {
|
||||
assert(worker_i >= 0, "worker index must be > 0");
|
||||
assert(worker_i < _active_gc_threads, "worker index out of bounds");
|
||||
_par_last_obj_copy_times_ms[worker_i] += ms;
|
||||
_last_obj_copy_times_ms.set(worker_i, ms);
|
||||
}
|
||||
|
||||
void add_obj_copy_time(uint worker_i, double ms) {
|
||||
_last_obj_copy_times_ms.add(worker_i, ms);
|
||||
}
|
||||
|
||||
void record_termination(uint worker_i, double ms, size_t attempts) {
|
||||
assert(worker_i >= 0, "worker index must be > 0");
|
||||
assert(worker_i < _active_gc_threads, "worker index out of bounds");
|
||||
_par_last_termination_times_ms[worker_i] = ms;
|
||||
_par_last_termination_attempts[worker_i] = (double) attempts;
|
||||
_last_termination_times_ms.set(worker_i, ms);
|
||||
_last_termination_attempts.set(worker_i, attempts);
|
||||
}
|
||||
|
||||
void record_gc_worker_end_time(uint worker_i, double ms) {
|
||||
assert(worker_i >= 0, "worker index must be > 0");
|
||||
assert(worker_i < _active_gc_threads, "worker index out of bounds");
|
||||
_par_last_gc_worker_end_times_ms[worker_i] = ms;
|
||||
_last_gc_worker_end_times_ms.set(worker_i, ms);
|
||||
}
|
||||
|
||||
void record_clear_ct_time(double ms) {
|
||||
@ -211,6 +234,88 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
|
||||
void record_non_young_free_cset_time_ms(double time_ms) {
|
||||
_recorded_non_young_free_cset_time_ms = time_ms;
|
||||
}
|
||||
|
||||
void record_young_cset_choice_time_ms(double time_ms) {
|
||||
_recorded_young_cset_choice_time_ms = time_ms;
|
||||
}
|
||||
|
||||
void record_non_young_cset_choice_time_ms(double time_ms) {
|
||||
_recorded_non_young_cset_choice_time_ms = time_ms;
|
||||
}
|
||||
|
||||
void record_cur_collection_start_sec(double time_ms) {
|
||||
_cur_collection_start_sec = time_ms;
|
||||
}
|
||||
|
||||
void record_verify_before_time_ms(double time_ms) {
|
||||
_cur_verify_before_time_ms = time_ms;
|
||||
}
|
||||
|
||||
void record_verify_after_time_ms(double time_ms) {
|
||||
_cur_verify_after_time_ms = time_ms;
|
||||
}
|
||||
|
||||
double accounted_time_ms();
|
||||
|
||||
double cur_collection_start_sec() {
|
||||
return _cur_collection_start_sec;
|
||||
}
|
||||
|
||||
double cur_collection_par_time_ms() {
|
||||
return _cur_collection_par_time_ms;
|
||||
}
|
||||
|
||||
double cur_clear_ct_time_ms() {
|
||||
return _cur_clear_ct_time_ms;
|
||||
}
|
||||
|
||||
double root_region_scan_wait_time_ms() {
|
||||
return _root_region_scan_wait_time_ms;
|
||||
}
|
||||
|
||||
double young_cset_choice_time_ms() {
|
||||
return _recorded_young_cset_choice_time_ms;
|
||||
}
|
||||
|
||||
double young_free_cset_time_ms() {
|
||||
return _recorded_young_free_cset_time_ms;
|
||||
}
|
||||
|
||||
double non_young_cset_choice_time_ms() {
|
||||
return _recorded_non_young_cset_choice_time_ms;
|
||||
}
|
||||
|
||||
double non_young_free_cset_time_ms() {
|
||||
return _recorded_non_young_free_cset_time_ms;
|
||||
}
|
||||
|
||||
double average_last_update_rs_time() {
|
||||
return _last_update_rs_times_ms.average();
|
||||
}
|
||||
|
||||
int sum_last_update_rs_processed_buffers() {
|
||||
return _last_update_rs_processed_buffers.sum();
|
||||
}
|
||||
|
||||
double average_last_scan_rs_time(){
|
||||
return _last_scan_rs_times_ms.average();
|
||||
}
|
||||
|
||||
double average_last_obj_copy_time() {
|
||||
return _last_obj_copy_times_ms.average();
|
||||
}
|
||||
|
||||
double average_last_termination_time() {
|
||||
return _last_termination_times_ms.average();
|
||||
}
|
||||
|
||||
double average_last_ext_root_scan_time() {
|
||||
return _last_ext_root_scan_times_ms.average();
|
||||
}
|
||||
|
||||
double average_last_satb_filtering_times_ms() {
|
||||
return _last_satb_filtering_times_ms.average();
|
||||
}
|
||||
};
|
||||
|
||||
#endif // SHARE_VM_GC_IMPLEMENTATION_G1_G1GCPHASETIMESLOG_HPP
|
||||
|
||||
@ -324,7 +324,7 @@ void G1RemSet::oops_into_collection_set_do(OopsInHeapRegionClosure* oc,
|
||||
if (G1UseParallelRSetUpdating || (worker_i == 0)) {
|
||||
updateRS(&into_cset_dcq, worker_i);
|
||||
} else {
|
||||
_g1p->phase_times()->record_update_rs_processed_buffers(worker_i, 0.0);
|
||||
_g1p->phase_times()->record_update_rs_processed_buffers(worker_i, 0);
|
||||
_g1p->phase_times()->record_update_rs_time(worker_i, 0.0);
|
||||
}
|
||||
if (G1UseParallelRSetScanning || (worker_i == 0)) {
|
||||
|
||||
@ -1916,7 +1916,7 @@ bool Arguments::check_vm_args_consistency() {
|
||||
(ExplicitGCInvokesConcurrent ||
|
||||
ExplicitGCInvokesConcurrentAndUnloadsClasses)) {
|
||||
jio_fprintf(defaultStream::error_stream(),
|
||||
"error: +ExplictGCInvokesConcurrent[AndUnloadsClasses] conflicts"
|
||||
"error: +ExplicitGCInvokesConcurrent[AndUnloadsClasses] conflicts"
|
||||
" with -UseAsyncConcMarkSweepGC");
|
||||
status = false;
|
||||
}
|
||||
|
||||
Loading…
x
Reference in New Issue
Block a user