src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp
Index
Unified diffs
Context diffs
Sdiffs
Patch
New
Old
Previous File
Next File
*** old/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Wed May 30 14:28:58 2012
--- new/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Wed May 30 14:28:57 2012
*** 131,146 ****
--- 131,141 ----
G1CollectorPolicy::G1CollectorPolicy() :
_parallel_gc_threads(G1CollectedHeap::use_parallel_gc_threads()
? 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),
_cur_ref_proc_time_ms(0.0),
*** 152,167 ****
--- 147,156 ----
_cur_clear_cc_time_ms(0.0),
_cum_clear_cc_time_ms(0.0),
_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)),
_alloc_rate_ms_seq(new TruncatedSeq(TruncatedSeqLength)),
_prev_collection_pause_end_ms(0.0),
*** 183,206 ****
--- 172,191 ----
_rs_lengths_seq(new TruncatedSeq(TruncatedSeqLength)),
_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),
_in_marking_window_im(false),
_recent_prev_end_times_for_all_gcs_sec(
new TruncatedSeq(NumPrevPausesForHeuristics)),
_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),
_last_gc_was_young(false),
*** 849,859 ****
--- 834,844 ----
// since last pause.
double end_sec = os::elapsedTime();
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);
_g1->clear_full_collection();
*** 898,908 ****
--- 883,893 ----
assert(_g1->used() == _g1->recalculate_used(),
err_msg("sanity, used: "SIZE_FORMAT" recalculate_used: "SIZE_FORMAT,
_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;
_cur_collection_pause_used_at_start_bytes = start_used;
_cur_collection_pause_used_regions_at_start = _g1->used_regions();
*** 935,949 ****
--- 920,929 ----
_par_last_gc_worker_times_ms[i] = -1234.0;
_par_last_gc_worker_other_times_ms[i] = -1234.0;
}
#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;
_last_gc_was_young = false;
*** 988,998 ****
--- 968,978 ----
}
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);
}
}
void G1CollectorPolicy::record_concurrent_pause_end() {
}
*** 1195,1219 ****
--- 1175,1184 ----
}
_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;
double survival_fraction =
*** 1257,1304 ****
--- 1222,1240 ----
// Subtract the time taken to clean the card table from the
// current value of "other time"
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 =
(_cur_collection_start_sec * 1000.0 - _prev_collection_pause_end_ms);
if (app_time_ms < MIN_TIMER_GRANULARITY) {
*** 1347,1362 ****
--- 1283,1292 ----
_recent_avg_pause_time_ratio = 1.0;
}
}
}
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;
gclog_or_tty->print_cr("%s, %1.8lf secs]",
*** 1434,1451 ****
--- 1364,1373 ----
print_stats(2, "Ref Proc", _cur_ref_proc_time_ms);
print_stats(2, "Ref Enq", _cur_ref_enq_time_ms);
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;
bool new_in_marking_window_im = false;
if (during_initial_mark_pause()) {
*** 1806,1988 ****
--- 1728,1740 ----
void G1CollectorPolicy::count_CS_bytes_used() {
CountCSClosure cs_closure(this);
_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 {
#ifndef PRODUCT
_short_lived_surv_rate_group->print_surv_rate_summary();
*** 2529,2541 ****
--- 2281,2293 ----
_collection_set_bytes_used_before = 0;
_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
// pause are appended to the RHS of the young list, i.e.
// [Newly Young Regions ++ Survivors from last pause].
*** 2688,2692 ****
--- 2440,2574 ----
double non_young_end_time_sec = os::elapsedTime();
_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());
+ }
+ }
src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp
Index
Unified diffs
Context diffs
Sdiffs
Patch
New
Old
Previous File
Next File