--- a/hotspot/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Wed May 30 10:26:24 2012 -0700
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp Thu May 31 21:10:33 2012 +0200
@@ -133,12 +133,7 @@
? 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 @@
_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 @@
_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 @@
_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 @@
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 @@
_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 @@
}
#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_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 @@
_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 @@
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;
- 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 @@
}
}
- 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 @@
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 @@
_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 @@
_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 @@
_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());
+ }
+}