mirror of
https://github.com/openjdk/jdk.git
synced 2025-09-21 03:24:38 +02:00
7172279: G1: Clean up TraceGen0Time and TraceGen1Time data gathering
Simplify code, remove unused code, remove ExitAfterGCNum Reviewed-by: huntch, johnc
This commit is contained in:
parent
057a1b7128
commit
212ab5c73a
7 changed files with 193 additions and 368 deletions
|
@ -3930,12 +3930,6 @@ G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
|
|||
|
||||
gc_epilogue(false);
|
||||
}
|
||||
|
||||
if (ExitAfterGCNum > 0 && total_collections() == ExitAfterGCNum) {
|
||||
gclog_or_tty->print_cr("Stopping after GC #%d", ExitAfterGCNum);
|
||||
print_tracing_info();
|
||||
vm_exit(-1);
|
||||
}
|
||||
}
|
||||
|
||||
// The closing of the inner scope, immediately above, will complete
|
||||
|
|
|
@ -133,12 +133,7 @@ G1CollectorPolicy::G1CollectorPolicy() :
|
|||
? ParallelGCThreads : 1),
|
||||
|
||||
_recent_gc_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
|
||||
_all_pause_times_ms(new NumberSeq()),
|
||||
_stop_world_start(0.0),
|
||||
_all_stop_world_times_ms(new NumberSeq()),
|
||||
_all_yield_times_ms(new NumberSeq()),
|
||||
|
||||
_summary(new Summary()),
|
||||
|
||||
_cur_clear_ct_time_ms(0.0),
|
||||
_root_region_scan_wait_time_ms(0.0),
|
||||
|
@ -154,12 +149,6 @@ G1CollectorPolicy::G1CollectorPolicy() :
|
|||
_num_cc_clears(0L),
|
||||
#endif
|
||||
|
||||
_aux_num(10),
|
||||
_all_aux_times_ms(new NumberSeq[_aux_num]),
|
||||
_cur_aux_start_times_ms(new double[_aux_num]),
|
||||
_cur_aux_times_ms(new double[_aux_num]),
|
||||
_cur_aux_times_set(new bool[_aux_num]),
|
||||
|
||||
_concurrent_mark_remark_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
|
||||
_concurrent_mark_cleanup_times_ms(new TruncatedSeq(NumPrevPausesForHeuristics)),
|
||||
|
||||
|
@ -185,8 +174,6 @@ G1CollectorPolicy::G1CollectorPolicy() :
|
|||
_pause_time_target_ms((double) MaxGCPauseMillis),
|
||||
|
||||
_gcs_are_young(true),
|
||||
_young_pause_num(0),
|
||||
_mixed_pause_num(0),
|
||||
|
||||
_during_marking(false),
|
||||
_in_marking_window(false),
|
||||
|
@ -197,8 +184,6 @@ G1CollectorPolicy::G1CollectorPolicy() :
|
|||
|
||||
_recent_avg_pause_time_ratio(0.0),
|
||||
|
||||
_all_full_gc_times_ms(new NumberSeq()),
|
||||
|
||||
_initiate_conc_mark_if_possible(false),
|
||||
_during_initial_mark_pause(false),
|
||||
_last_young_gc(false),
|
||||
|
@ -851,7 +836,7 @@ void G1CollectorPolicy::record_full_collection_end() {
|
|||
double full_gc_time_sec = end_sec - _cur_collection_start_sec;
|
||||
double full_gc_time_ms = full_gc_time_sec * 1000.0;
|
||||
|
||||
_all_full_gc_times_ms->add(full_gc_time_ms);
|
||||
_trace_gen1_time_data.record_full_collection(full_gc_time_ms);
|
||||
|
||||
update_recent_gc_times(end_sec, full_gc_time_ms);
|
||||
|
||||
|
@ -900,7 +885,7 @@ void G1CollectorPolicy::record_collection_pause_start(double start_time_sec,
|
|||
_g1->used(), _g1->recalculate_used()));
|
||||
|
||||
double s_w_t_ms = (start_time_sec - _stop_world_start) * 1000.0;
|
||||
_all_stop_world_times_ms->add(s_w_t_ms);
|
||||
_trace_gen0_time_data.record_start_collection(s_w_t_ms);
|
||||
_stop_world_start = 0.0;
|
||||
|
||||
_cur_collection_start_sec = start_time_sec;
|
||||
|
@ -937,11 +922,6 @@ void G1CollectorPolicy::record_collection_pause_start(double start_time_sec,
|
|||
}
|
||||
#endif
|
||||
|
||||
for (int i = 0; i < _aux_num; ++i) {
|
||||
_cur_aux_times_ms[i] = 0.0;
|
||||
_cur_aux_times_set[i] = false;
|
||||
}
|
||||
|
||||
// This is initialized to zero here and is set during the evacuation
|
||||
// pause if we actually waited for the root region scanning to finish.
|
||||
_root_region_scan_wait_time_ms = 0.0;
|
||||
|
@ -990,7 +970,7 @@ void G1CollectorPolicy::record_concurrent_mark_cleanup_completed() {
|
|||
void G1CollectorPolicy::record_concurrent_pause() {
|
||||
if (_stop_world_start > 0.0) {
|
||||
double yield_ms = (os::elapsedTime() - _stop_world_start) * 1000.0;
|
||||
_all_yield_times_ms->add(yield_ms);
|
||||
_trace_gen0_time_data.record_yield_time(yield_ms);
|
||||
}
|
||||
}
|
||||
|
||||
|
@ -1197,21 +1177,6 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) {
|
|||
_mmu_tracker->add_pause(end_time_sec - elapsed_ms/1000.0,
|
||||
end_time_sec, false);
|
||||
|
||||
// This assert is exempted when we're doing parallel collection pauses,
|
||||
// because the fragmentation caused by the parallel GC allocation buffers
|
||||
// can lead to more memory being used during collection than was used
|
||||
// before. Best leave this out until the fragmentation problem is fixed.
|
||||
// Pauses in which evacuation failed can also lead to negative
|
||||
// collections, since no space is reclaimed from a region containing an
|
||||
// object whose evacuation failed.
|
||||
// Further, we're now always doing parallel collection. But I'm still
|
||||
// leaving this here as a placeholder for a more precise assertion later.
|
||||
// (DLD, 10/05.)
|
||||
assert((true || parallel) // Always using GC LABs now.
|
||||
|| _g1->evacuation_failed()
|
||||
|| _cur_collection_pause_used_at_start_bytes >= cur_used_bytes,
|
||||
"Negative collection");
|
||||
|
||||
size_t freed_bytes =
|
||||
_cur_collection_pause_used_at_start_bytes - cur_used_bytes;
|
||||
size_t surviving_bytes = _collection_set_bytes_used_before - freed_bytes;
|
||||
|
@ -1259,44 +1224,15 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) {
|
|||
other_time_ms -= _cur_clear_ct_time_ms;
|
||||
|
||||
// TraceGen0Time and TraceGen1Time summary info updating.
|
||||
_all_pause_times_ms->add(elapsed_ms);
|
||||
|
||||
if (update_stats) {
|
||||
_summary->record_total_time_ms(elapsed_ms);
|
||||
_summary->record_other_time_ms(other_time_ms);
|
||||
|
||||
MainBodySummary* body_summary = _summary->main_body_summary();
|
||||
assert(body_summary != NULL, "should not be null!");
|
||||
|
||||
body_summary->record_root_region_scan_wait_time_ms(
|
||||
_root_region_scan_wait_time_ms);
|
||||
body_summary->record_ext_root_scan_time_ms(ext_root_scan_time);
|
||||
body_summary->record_satb_filtering_time_ms(satb_filtering_time);
|
||||
body_summary->record_update_rs_time_ms(update_rs_time);
|
||||
body_summary->record_scan_rs_time_ms(scan_rs_time);
|
||||
body_summary->record_obj_copy_time_ms(obj_copy_time);
|
||||
|
||||
if (parallel) {
|
||||
body_summary->record_parallel_time_ms(_cur_collection_par_time_ms);
|
||||
body_summary->record_termination_time_ms(termination_time);
|
||||
|
||||
double parallel_known_time = known_time + termination_time;
|
||||
double parallel_other_time = _cur_collection_par_time_ms - parallel_known_time;
|
||||
body_summary->record_parallel_other_time_ms(parallel_other_time);
|
||||
}
|
||||
|
||||
body_summary->record_clear_ct_time_ms(_cur_clear_ct_time_ms);
|
||||
|
||||
// We exempt parallel collection from this check because Alloc Buffer
|
||||
// fragmentation can produce negative collections. Same with evac
|
||||
// failure.
|
||||
// Further, we're now always doing parallel collection. But I'm still
|
||||
// leaving this here as a placeholder for a more precise assertion later.
|
||||
// (DLD, 10/05.
|
||||
assert((true || parallel)
|
||||
|| _g1->evacuation_failed()
|
||||
|| surviving_bytes <= _collection_set_bytes_used_before,
|
||||
"Or else negative collection!");
|
||||
_trace_gen0_time_data.record_end_collection(
|
||||
elapsed_ms, other_time_ms, _root_region_scan_wait_time_ms, _cur_collection_par_time_ms,
|
||||
ext_root_scan_time, satb_filtering_time, update_rs_time, scan_rs_time, obj_copy_time,
|
||||
termination_time, parallel_other_time, _cur_clear_ct_time_ms);
|
||||
|
||||
// this is where we update the allocation rate of the application
|
||||
double app_time_ms =
|
||||
|
@ -1349,12 +1285,6 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) {
|
|||
}
|
||||
}
|
||||
|
||||
for (int i = 0; i < _aux_num; ++i) {
|
||||
if (_cur_aux_times_set[i]) {
|
||||
_all_aux_times_ms[i].add(_cur_aux_times_ms[i]);
|
||||
}
|
||||
}
|
||||
|
||||
if (G1Log::finer()) {
|
||||
bool print_marking_info =
|
||||
_g1->mark_in_progress() && !last_pause_included_initial_mark;
|
||||
|
@ -1436,14 +1366,6 @@ void G1CollectorPolicy::record_collection_pause_end(int no_of_gc_threads) {
|
|||
print_stats(2, "Free CSet",
|
||||
(_recorded_young_free_cset_time_ms +
|
||||
_recorded_non_young_free_cset_time_ms));
|
||||
|
||||
for (int i = 0; i < _aux_num; ++i) {
|
||||
if (_cur_aux_times_set[i]) {
|
||||
char buffer[96];
|
||||
sprintf(buffer, "Aux%d", i);
|
||||
print_stats(1, buffer, _cur_aux_times_ms[i]);
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
bool new_in_marking_window = _in_marking_window;
|
||||
|
@ -1808,179 +1730,9 @@ void G1CollectorPolicy::count_CS_bytes_used() {
|
|||
_g1->collection_set_iterate(&cs_closure);
|
||||
}
|
||||
|
||||
void G1CollectorPolicy::print_summary(int level,
|
||||
const char* str,
|
||||
NumberSeq* seq) const {
|
||||
double sum = seq->sum();
|
||||
LineBuffer(level + 1).append_and_print_cr("%-24s = %8.2lf s (avg = %8.2lf ms)",
|
||||
str, sum / 1000.0, seq->avg());
|
||||
}
|
||||
|
||||
void G1CollectorPolicy::print_summary_sd(int level,
|
||||
const char* str,
|
||||
NumberSeq* seq) const {
|
||||
print_summary(level, str, seq);
|
||||
LineBuffer(level + 6).append_and_print_cr("(num = %5d, std dev = %8.2lf ms, max = %8.2lf ms)",
|
||||
seq->num(), seq->sd(), seq->maximum());
|
||||
}
|
||||
|
||||
void G1CollectorPolicy::check_other_times(int level,
|
||||
NumberSeq* other_times_ms,
|
||||
NumberSeq* calc_other_times_ms) const {
|
||||
bool should_print = false;
|
||||
LineBuffer buf(level + 2);
|
||||
|
||||
double max_sum = MAX2(fabs(other_times_ms->sum()),
|
||||
fabs(calc_other_times_ms->sum()));
|
||||
double min_sum = MIN2(fabs(other_times_ms->sum()),
|
||||
fabs(calc_other_times_ms->sum()));
|
||||
double sum_ratio = max_sum / min_sum;
|
||||
if (sum_ratio > 1.1) {
|
||||
should_print = true;
|
||||
buf.append_and_print_cr("## CALCULATED OTHER SUM DOESN'T MATCH RECORDED ###");
|
||||
}
|
||||
|
||||
double max_avg = MAX2(fabs(other_times_ms->avg()),
|
||||
fabs(calc_other_times_ms->avg()));
|
||||
double min_avg = MIN2(fabs(other_times_ms->avg()),
|
||||
fabs(calc_other_times_ms->avg()));
|
||||
double avg_ratio = max_avg / min_avg;
|
||||
if (avg_ratio > 1.1) {
|
||||
should_print = true;
|
||||
buf.append_and_print_cr("## CALCULATED OTHER AVG DOESN'T MATCH RECORDED ###");
|
||||
}
|
||||
|
||||
if (other_times_ms->sum() < -0.01) {
|
||||
buf.append_and_print_cr("## RECORDED OTHER SUM IS NEGATIVE ###");
|
||||
}
|
||||
|
||||
if (other_times_ms->avg() < -0.01) {
|
||||
buf.append_and_print_cr("## RECORDED OTHER AVG IS NEGATIVE ###");
|
||||
}
|
||||
|
||||
if (calc_other_times_ms->sum() < -0.01) {
|
||||
should_print = true;
|
||||
buf.append_and_print_cr("## CALCULATED OTHER SUM IS NEGATIVE ###");
|
||||
}
|
||||
|
||||
if (calc_other_times_ms->avg() < -0.01) {
|
||||
should_print = true;
|
||||
buf.append_and_print_cr("## CALCULATED OTHER AVG IS NEGATIVE ###");
|
||||
}
|
||||
|
||||
if (should_print)
|
||||
print_summary(level, "Other(Calc)", calc_other_times_ms);
|
||||
}
|
||||
|
||||
void G1CollectorPolicy::print_summary(PauseSummary* summary) const {
|
||||
bool parallel = G1CollectedHeap::use_parallel_gc_threads();
|
||||
MainBodySummary* body_summary = summary->main_body_summary();
|
||||
if (summary->get_total_seq()->num() > 0) {
|
||||
print_summary_sd(0, "Evacuation Pauses", summary->get_total_seq());
|
||||
if (body_summary != NULL) {
|
||||
print_summary(1, "Root Region Scan Wait", body_summary->get_root_region_scan_wait_seq());
|
||||
if (parallel) {
|
||||
print_summary(1, "Parallel Time", body_summary->get_parallel_seq());
|
||||
print_summary(2, "Ext Root Scanning", body_summary->get_ext_root_scan_seq());
|
||||
print_summary(2, "SATB Filtering", body_summary->get_satb_filtering_seq());
|
||||
print_summary(2, "Update RS", body_summary->get_update_rs_seq());
|
||||
print_summary(2, "Scan RS", body_summary->get_scan_rs_seq());
|
||||
print_summary(2, "Object Copy", body_summary->get_obj_copy_seq());
|
||||
print_summary(2, "Termination", body_summary->get_termination_seq());
|
||||
print_summary(2, "Parallel Other", body_summary->get_parallel_other_seq());
|
||||
{
|
||||
NumberSeq* other_parts[] = {
|
||||
body_summary->get_ext_root_scan_seq(),
|
||||
body_summary->get_satb_filtering_seq(),
|
||||
body_summary->get_update_rs_seq(),
|
||||
body_summary->get_scan_rs_seq(),
|
||||
body_summary->get_obj_copy_seq(),
|
||||
body_summary->get_termination_seq()
|
||||
};
|
||||
NumberSeq calc_other_times_ms(body_summary->get_parallel_seq(),
|
||||
6, other_parts);
|
||||
check_other_times(2, body_summary->get_parallel_other_seq(),
|
||||
&calc_other_times_ms);
|
||||
}
|
||||
} else {
|
||||
print_summary(1, "Ext Root Scanning", body_summary->get_ext_root_scan_seq());
|
||||
print_summary(1, "SATB Filtering", body_summary->get_satb_filtering_seq());
|
||||
print_summary(1, "Update RS", body_summary->get_update_rs_seq());
|
||||
print_summary(1, "Scan RS", body_summary->get_scan_rs_seq());
|
||||
print_summary(1, "Object Copy", body_summary->get_obj_copy_seq());
|
||||
}
|
||||
}
|
||||
print_summary(1, "Clear CT", body_summary->get_clear_ct_seq());
|
||||
print_summary(1, "Other", summary->get_other_seq());
|
||||
{
|
||||
if (body_summary != NULL) {
|
||||
NumberSeq calc_other_times_ms;
|
||||
if (parallel) {
|
||||
// parallel
|
||||
NumberSeq* other_parts[] = {
|
||||
body_summary->get_root_region_scan_wait_seq(),
|
||||
body_summary->get_parallel_seq(),
|
||||
body_summary->get_clear_ct_seq()
|
||||
};
|
||||
calc_other_times_ms = NumberSeq(summary->get_total_seq(),
|
||||
3, other_parts);
|
||||
} else {
|
||||
// serial
|
||||
NumberSeq* other_parts[] = {
|
||||
body_summary->get_root_region_scan_wait_seq(),
|
||||
body_summary->get_update_rs_seq(),
|
||||
body_summary->get_ext_root_scan_seq(),
|
||||
body_summary->get_satb_filtering_seq(),
|
||||
body_summary->get_scan_rs_seq(),
|
||||
body_summary->get_obj_copy_seq()
|
||||
};
|
||||
calc_other_times_ms = NumberSeq(summary->get_total_seq(),
|
||||
6, other_parts);
|
||||
}
|
||||
check_other_times(1, summary->get_other_seq(), &calc_other_times_ms);
|
||||
}
|
||||
}
|
||||
} else {
|
||||
LineBuffer(1).append_and_print_cr("none");
|
||||
}
|
||||
LineBuffer(0).append_and_print_cr("");
|
||||
}
|
||||
|
||||
void G1CollectorPolicy::print_tracing_info() const {
|
||||
if (TraceGen0Time) {
|
||||
gclog_or_tty->print_cr("ALL PAUSES");
|
||||
print_summary_sd(0, "Total", _all_pause_times_ms);
|
||||
gclog_or_tty->print_cr("");
|
||||
gclog_or_tty->print_cr("");
|
||||
gclog_or_tty->print_cr(" Young GC Pauses: %8d", _young_pause_num);
|
||||
gclog_or_tty->print_cr(" Mixed GC Pauses: %8d", _mixed_pause_num);
|
||||
gclog_or_tty->print_cr("");
|
||||
|
||||
gclog_or_tty->print_cr("EVACUATION PAUSES");
|
||||
print_summary(_summary);
|
||||
|
||||
gclog_or_tty->print_cr("MISC");
|
||||
print_summary_sd(0, "Stop World", _all_stop_world_times_ms);
|
||||
print_summary_sd(0, "Yields", _all_yield_times_ms);
|
||||
for (int i = 0; i < _aux_num; ++i) {
|
||||
if (_all_aux_times_ms[i].num() > 0) {
|
||||
char buffer[96];
|
||||
sprintf(buffer, "Aux%d", i);
|
||||
print_summary_sd(0, buffer, &_all_aux_times_ms[i]);
|
||||
}
|
||||
}
|
||||
}
|
||||
if (TraceGen1Time) {
|
||||
if (_all_full_gc_times_ms->num() > 0) {
|
||||
gclog_or_tty->print("\n%4d full_gcs: total time = %8.2f s",
|
||||
_all_full_gc_times_ms->num(),
|
||||
_all_full_gc_times_ms->sum() / 1000.0);
|
||||
gclog_or_tty->print_cr(" (avg = %8.2fms).", _all_full_gc_times_ms->avg());
|
||||
gclog_or_tty->print_cr(" [std. dev = %8.2f ms, max = %8.2f ms]",
|
||||
_all_full_gc_times_ms->sd(),
|
||||
_all_full_gc_times_ms->maximum());
|
||||
}
|
||||
}
|
||||
_trace_gen0_time_data.print();
|
||||
_trace_gen1_time_data.print();
|
||||
}
|
||||
|
||||
void G1CollectorPolicy::print_yg_surv_rate_info() const {
|
||||
|
@ -2531,9 +2283,9 @@ void G1CollectorPolicy::finalize_cset(double target_pause_time_ms) {
|
|||
_last_gc_was_young = gcs_are_young() ? true : false;
|
||||
|
||||
if (_last_gc_was_young) {
|
||||
++_young_pause_num;
|
||||
_trace_gen0_time_data.increment_young_collection_count();
|
||||
} else {
|
||||
++_mixed_pause_num;
|
||||
_trace_gen0_time_data.increment_mixed_collection_count();
|
||||
}
|
||||
|
||||
// The young list is laid with the survivor regions from the previous
|
||||
|
@ -2690,3 +2442,133 @@ void G1CollectorPolicy::finalize_cset(double target_pause_time_ms) {
|
|||
_recorded_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) {
|
||||
if(TraceGen0Time) {
|
||||
_all_stop_world_times_ms.add(time_to_stop_the_world_ms);
|
||||
}
|
||||
}
|
||||
|
||||
void TraceGen0TimeData::record_yield_time(double yield_time_ms) {
|
||||
if(TraceGen0Time) {
|
||||
_all_yield_times_ms.add(yield_time_ms);
|
||||
}
|
||||
}
|
||||
|
||||
void TraceGen0TimeData::record_end_collection(
|
||||
double total_ms,
|
||||
double other_ms,
|
||||
double root_region_scan_wait_ms,
|
||||
double parallel_ms,
|
||||
double ext_root_scan_ms,
|
||||
double satb_filtering_ms,
|
||||
double update_rs_ms,
|
||||
double scan_rs_ms,
|
||||
double obj_copy_ms,
|
||||
double termination_ms,
|
||||
double parallel_other_ms,
|
||||
double clear_ct_ms)
|
||||
{
|
||||
if(TraceGen0Time) {
|
||||
_total.add(total_ms);
|
||||
_other.add(other_ms);
|
||||
_root_region_scan_wait.add(root_region_scan_wait_ms);
|
||||
_parallel.add(parallel_ms);
|
||||
_ext_root_scan.add(ext_root_scan_ms);
|
||||
_satb_filtering.add(satb_filtering_ms);
|
||||
_update_rs.add(update_rs_ms);
|
||||
_scan_rs.add(scan_rs_ms);
|
||||
_obj_copy.add(obj_copy_ms);
|
||||
_termination.add(termination_ms);
|
||||
_parallel_other.add(parallel_other_ms);
|
||||
_clear_ct.add(clear_ct_ms);
|
||||
}
|
||||
}
|
||||
|
||||
void TraceGen0TimeData::increment_young_collection_count() {
|
||||
if(TraceGen0Time) {
|
||||
++_young_pause_num;
|
||||
}
|
||||
}
|
||||
|
||||
void TraceGen0TimeData::increment_mixed_collection_count() {
|
||||
if(TraceGen0Time) {
|
||||
++_mixed_pause_num;
|
||||
}
|
||||
}
|
||||
|
||||
void TraceGen0TimeData::print_summary(int level,
|
||||
const char* str,
|
||||
const NumberSeq* seq) const {
|
||||
double sum = seq->sum();
|
||||
LineBuffer(level + 1).append_and_print_cr("%-24s = %8.2lf s (avg = %8.2lf ms)",
|
||||
str, sum / 1000.0, seq->avg());
|
||||
}
|
||||
|
||||
void TraceGen0TimeData::print_summary_sd(int level,
|
||||
const char* str,
|
||||
const NumberSeq* seq) const {
|
||||
print_summary(level, str, seq);
|
||||
LineBuffer(level + 6).append_and_print_cr("(num = %5d, std dev = %8.2lf ms, max = %8.2lf ms)",
|
||||
seq->num(), seq->sd(), seq->maximum());
|
||||
}
|
||||
|
||||
void TraceGen0TimeData::print() const {
|
||||
if (!TraceGen0Time) {
|
||||
return;
|
||||
}
|
||||
|
||||
gclog_or_tty->print_cr("ALL PAUSES");
|
||||
print_summary_sd(0, "Total", &_total);
|
||||
gclog_or_tty->print_cr("");
|
||||
gclog_or_tty->print_cr("");
|
||||
gclog_or_tty->print_cr(" Young GC Pauses: %8d", _young_pause_num);
|
||||
gclog_or_tty->print_cr(" Mixed GC Pauses: %8d", _mixed_pause_num);
|
||||
gclog_or_tty->print_cr("");
|
||||
|
||||
gclog_or_tty->print_cr("EVACUATION PAUSES");
|
||||
|
||||
if (_young_pause_num == 0 && _mixed_pause_num == 0) {
|
||||
gclog_or_tty->print_cr("none");
|
||||
} else {
|
||||
print_summary_sd(0, "Evacuation Pauses", &_total);
|
||||
print_summary(1, "Root Region Scan Wait", &_root_region_scan_wait);
|
||||
print_summary(1, "Parallel Time", &_parallel);
|
||||
print_summary(2, "Ext Root Scanning", &_ext_root_scan);
|
||||
print_summary(2, "SATB Filtering", &_satb_filtering);
|
||||
print_summary(2, "Update RS", &_update_rs);
|
||||
print_summary(2, "Scan RS", &_scan_rs);
|
||||
print_summary(2, "Object Copy", &_obj_copy);
|
||||
print_summary(2, "Termination", &_termination);
|
||||
print_summary(2, "Parallel Other", &_parallel_other);
|
||||
print_summary(1, "Clear CT", &_clear_ct);
|
||||
print_summary(1, "Other", &_other);
|
||||
}
|
||||
gclog_or_tty->print_cr("");
|
||||
|
||||
gclog_or_tty->print_cr("MISC");
|
||||
print_summary_sd(0, "Stop World", &_all_stop_world_times_ms);
|
||||
print_summary_sd(0, "Yields", &_all_yield_times_ms);
|
||||
}
|
||||
|
||||
void TraceGen1TimeData::record_full_collection(double full_gc_time_ms) {
|
||||
if (TraceGen1Time) {
|
||||
_all_full_gc_times.add(full_gc_time_ms);
|
||||
}
|
||||
}
|
||||
|
||||
void TraceGen1TimeData::print() const {
|
||||
if (!TraceGen1Time) {
|
||||
return;
|
||||
}
|
||||
|
||||
if (_all_full_gc_times.num() > 0) {
|
||||
gclog_or_tty->print("\n%4d full_gcs: total time = %8.2f s",
|
||||
_all_full_gc_times.num(),
|
||||
_all_full_gc_times.sum() / 1000.0);
|
||||
gclog_or_tty->print_cr(" (avg = %8.2fms).", _all_full_gc_times.avg());
|
||||
gclog_or_tty->print_cr(" [std. dev = %8.2f ms, max = %8.2f ms]",
|
||||
_all_full_gc_times.sd(),
|
||||
_all_full_gc_times.maximum());
|
||||
}
|
||||
}
|
||||
|
|
|
@ -37,49 +37,62 @@
|
|||
class HeapRegion;
|
||||
class CollectionSetChooser;
|
||||
|
||||
// Yes, this is a bit unpleasant... but it saves replicating the same thing
|
||||
// over and over again and introducing subtle problems through small typos and
|
||||
// cutting and pasting mistakes. The macros below introduces a number
|
||||
// sequnce into the following two classes and the methods that access it.
|
||||
// TraceGen0Time collects data on _both_ young and mixed evacuation pauses
|
||||
// (the latter may contain non-young regions - i.e. regions that are
|
||||
// technically in Gen1) while TraceGen1Time collects data about full GCs.
|
||||
class TraceGen0TimeData : public CHeapObj {
|
||||
private:
|
||||
unsigned _young_pause_num;
|
||||
unsigned _mixed_pause_num;
|
||||
|
||||
#define define_num_seq(name) \
|
||||
private: \
|
||||
NumberSeq _all_##name##_times_ms; \
|
||||
public: \
|
||||
void record_##name##_time_ms(double ms) { \
|
||||
_all_##name##_times_ms.add(ms); \
|
||||
} \
|
||||
NumberSeq* get_##name##_seq() { \
|
||||
return &_all_##name##_times_ms; \
|
||||
}
|
||||
NumberSeq _all_stop_world_times_ms;
|
||||
NumberSeq _all_yield_times_ms;
|
||||
|
||||
class MainBodySummary;
|
||||
NumberSeq _total;
|
||||
NumberSeq _other;
|
||||
NumberSeq _root_region_scan_wait;
|
||||
NumberSeq _parallel;
|
||||
NumberSeq _ext_root_scan;
|
||||
NumberSeq _satb_filtering;
|
||||
NumberSeq _update_rs;
|
||||
NumberSeq _scan_rs;
|
||||
NumberSeq _obj_copy;
|
||||
NumberSeq _termination;
|
||||
NumberSeq _parallel_other;
|
||||
NumberSeq _clear_ct;
|
||||
|
||||
class PauseSummary: public CHeapObj {
|
||||
define_num_seq(total)
|
||||
define_num_seq(other)
|
||||
void print_summary (int level, const char* str, const NumberSeq* seq) const;
|
||||
void print_summary_sd (int level, const char* str, const NumberSeq* seq) const;
|
||||
|
||||
public:
|
||||
virtual MainBodySummary* main_body_summary() { return NULL; }
|
||||
TraceGen0TimeData() : _young_pause_num(0), _mixed_pause_num(0) {};
|
||||
void record_start_collection(double time_to_stop_the_world_ms);
|
||||
void record_yield_time(double yield_time_ms);
|
||||
void record_end_collection(
|
||||
double total_ms,
|
||||
double other_ms,
|
||||
double root_region_scan_wait_ms,
|
||||
double parallel_ms,
|
||||
double ext_root_scan_ms,
|
||||
double satb_filtering_ms,
|
||||
double update_rs_ms,
|
||||
double scan_rs_ms,
|
||||
double obj_copy_ms,
|
||||
double termination_ms,
|
||||
double parallel_other_ms,
|
||||
double clear_ct_ms);
|
||||
void increment_young_collection_count();
|
||||
void increment_mixed_collection_count();
|
||||
void print() const;
|
||||
};
|
||||
|
||||
class MainBodySummary: public CHeapObj {
|
||||
define_num_seq(root_region_scan_wait)
|
||||
define_num_seq(parallel) // parallel only
|
||||
define_num_seq(ext_root_scan)
|
||||
define_num_seq(satb_filtering)
|
||||
define_num_seq(update_rs)
|
||||
define_num_seq(scan_rs)
|
||||
define_num_seq(obj_copy)
|
||||
define_num_seq(termination) // parallel only
|
||||
define_num_seq(parallel_other) // parallel only
|
||||
define_num_seq(clear_ct)
|
||||
};
|
||||
class TraceGen1TimeData : public CHeapObj {
|
||||
private:
|
||||
NumberSeq _all_full_gc_times;
|
||||
|
||||
class Summary: public PauseSummary,
|
||||
public MainBodySummary {
|
||||
public:
|
||||
virtual MainBodySummary* main_body_summary() { return this; }
|
||||
public:
|
||||
void record_full_collection(double full_gc_time_ms);
|
||||
void print() const;
|
||||
};
|
||||
|
||||
// There are three command line options related to the young gen size:
|
||||
|
@ -199,19 +212,10 @@ private:
|
|||
TruncatedSeq* _concurrent_mark_remark_times_ms;
|
||||
TruncatedSeq* _concurrent_mark_cleanup_times_ms;
|
||||
|
||||
Summary* _summary;
|
||||
TraceGen0TimeData _trace_gen0_time_data;
|
||||
TraceGen1TimeData _trace_gen1_time_data;
|
||||
|
||||
NumberSeq* _all_pause_times_ms;
|
||||
NumberSeq* _all_full_gc_times_ms;
|
||||
double _stop_world_start;
|
||||
NumberSeq* _all_stop_world_times_ms;
|
||||
NumberSeq* _all_yield_times_ms;
|
||||
|
||||
int _aux_num;
|
||||
NumberSeq* _all_aux_times_ms;
|
||||
double* _cur_aux_start_times_ms;
|
||||
double* _cur_aux_times_ms;
|
||||
bool* _cur_aux_times_set;
|
||||
|
||||
double* _par_last_gc_worker_start_times_ms;
|
||||
double* _par_last_ext_root_scan_times_ms;
|
||||
|
@ -243,9 +247,6 @@ private:
|
|||
|
||||
bool _last_gc_was_young;
|
||||
|
||||
unsigned _young_pause_num;
|
||||
unsigned _mixed_pause_num;
|
||||
|
||||
bool _during_marking;
|
||||
bool _in_marking_window;
|
||||
bool _in_marking_window_im;
|
||||
|
@ -557,15 +558,6 @@ private:
|
|||
|
||||
void print_par_stats(int level, const char* str, double* data, bool showDecimals = true);
|
||||
|
||||
void check_other_times(int level,
|
||||
NumberSeq* other_times_ms,
|
||||
NumberSeq* calc_other_times_ms) const;
|
||||
|
||||
void print_summary (PauseSummary* stats) const;
|
||||
|
||||
void print_summary (int level, const char* str, NumberSeq* seq) const;
|
||||
void print_summary_sd (int level, const char* str, NumberSeq* seq) const;
|
||||
|
||||
double avg_value (double* data);
|
||||
double max_value (double* data);
|
||||
double sum_of_values (double* data);
|
||||
|
@ -745,10 +737,6 @@ public:
|
|||
return _bytes_in_collection_set_before_gc;
|
||||
}
|
||||
|
||||
unsigned calc_gc_alloc_time_stamp() {
|
||||
return _all_pause_times_ms->num() + 1;
|
||||
}
|
||||
|
||||
// This should be called after the heap is resized.
|
||||
void record_new_heap_size(uint new_number_of_regions);
|
||||
|
||||
|
@ -867,18 +855,6 @@ public:
|
|||
_cur_collection_code_root_fixup_time_ms = ms;
|
||||
}
|
||||
|
||||
void record_aux_start_time(int i) {
|
||||
guarantee(i < _aux_num, "should be within range");
|
||||
_cur_aux_start_times_ms[i] = os::elapsedTime() * 1000.0;
|
||||
}
|
||||
|
||||
void record_aux_end_time(int i) {
|
||||
guarantee(i < _aux_num, "should be within range");
|
||||
double ms = os::elapsedTime() * 1000.0 - _cur_aux_start_times_ms[i];
|
||||
_cur_aux_times_set[i] = true;
|
||||
_cur_aux_times_ms[i] += ms;
|
||||
}
|
||||
|
||||
void record_ref_proc_time(double ms) {
|
||||
_cur_ref_proc_time_ms = ms;
|
||||
}
|
||||
|
|
|
@ -677,11 +677,6 @@ void GenCollectedHeap::do_collection(bool full,
|
|||
#ifdef TRACESPINNING
|
||||
ParallelTaskTerminator::print_termination_counts();
|
||||
#endif
|
||||
|
||||
if (ExitAfterGCNum > 0 && total_collections() == ExitAfterGCNum) {
|
||||
tty->print_cr("Stopping after GC #%d", ExitAfterGCNum);
|
||||
vm_exit(-1);
|
||||
}
|
||||
}
|
||||
|
||||
HeapWord* GenCollectedHeap::satisfy_failed_allocation(size_t size, bool is_tlab) {
|
||||
|
|
|
@ -3285,9 +3285,6 @@ class CommandLineFlags {
|
|||
diagnostic(intx, VerifyGCLevel, 0, \
|
||||
"Generation level at which to start +VerifyBefore/AfterGC") \
|
||||
\
|
||||
develop(uintx, ExitAfterGCNum, 0, \
|
||||
"If non-zero, exit after this GC.") \
|
||||
\
|
||||
product(intx, MaxTenuringThreshold, 15, \
|
||||
"Maximum value for tenuring threshold") \
|
||||
\
|
||||
|
|
|
@ -115,24 +115,6 @@ bool NumberSeq::check_nums(NumberSeq *total, int n, NumberSeq **parts) {
|
|||
return true;
|
||||
}
|
||||
|
||||
NumberSeq::NumberSeq(NumberSeq *total, int n, NumberSeq **parts) {
|
||||
guarantee(check_nums(total, n, parts), "all seq lengths should match");
|
||||
double sum = total->sum();
|
||||
for (int i = 0; i < n; ++i) {
|
||||
if (parts[i] != NULL)
|
||||
sum -= parts[i]->sum();
|
||||
}
|
||||
|
||||
_num = total->num();
|
||||
_sum = sum;
|
||||
|
||||
// we do not calculate these...
|
||||
_sum_of_squares = -1.0;
|
||||
_maximum = -1.0;
|
||||
_davg = -1.0;
|
||||
_dvariance = -1.0;
|
||||
}
|
||||
|
||||
void NumberSeq::add(double val) {
|
||||
AbsSeq::add(val);
|
||||
|
||||
|
|
|
@ -93,7 +93,6 @@ protected:
|
|||
|
||||
public:
|
||||
NumberSeq(double alpha = DEFAULT_ALPHA_VALUE);
|
||||
NumberSeq(NumberSeq* total, int n_parts, NumberSeq** parts);
|
||||
|
||||
virtual void add(double val);
|
||||
virtual double maximum() const { return _maximum; }
|
||||
|
|
Loading…
Add table
Add a link
Reference in a new issue