graal-compiler: src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp comparison

comparison src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp @ 4023:c6a6e936dc68

7096030: G1: PrintGCDetails enhancements 7102445: G1: Unnecessary Resource allocations during RSet scanning Summary: Add a new per-worker thread line in the PrintGCDetails output. GC Worker Other is the difference between the elapsed time for the parallel phase of the evacuation pause and the sum of the times of the sub-phases (external root scanning, mark stack scanning, RSet updating, RSet scanning, object copying, and termination) for that worker. During RSet scanning, stack allocate DirtyCardToOopClosure objects; allocating these in a resource area was causing abnormally high GC Worker Other times while the worker thread freed ResourceArea chunks. Reviewed-by: tonyp, jwilhelm, brutisso

author	johnc
date	Sun, 23 Oct 2011 23:06:06 -0700
parents	074f0252cc13
children	dbfcbecbb2dc

comparison

equal deleted inserted replaced

-:db89aa49298f
+:c6a6e936dc68
 _par_last_termination_times_ms = new double[_parallel_gc_threads];
 _par_last_termination_attempts = new double[_parallel_gc_threads];
 _par_last_gc_worker_end_times_ms = new double[_parallel_gc_threads];
 _par_last_gc_worker_times_ms = new double[_parallel_gc_threads];
+_par_last_gc_worker_other_times_ms = new double[_parallel_gc_threads];
 // start conservatively
 _expensive_region_limit_ms = 0.5 * (double) MaxGCPauseMillis;
 // <NEW PREDICTION>
 _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
 for (int i = 0; i < _aux_num; ++i) {
 _cur_aux_times_ms[i] = 0.0;
 _cur_aux_times_set[i] = false;
 }
-_satb_drain_time_set = false;
+// These are initialized to zero here and they are set during
-_last_satb_drain_processed_buffers = -1;
+// the evacuation pause if marking is in progress.
+_cur_satb_drain_time_ms = 0.0;
+_last_satb_drain_processed_buffers = 0;
 _last_young_gc_full = false;
 // do that for any other surv rate groups
 _short_lived_surv_rate_group->stop_adding_regions();
 double avg = total / (double) ParallelGCThreads;
 buf.append_and_print_cr(" Sum: %d, Avg: %d, Min: %d, Max: %d, Diff: %d]",
 (int)total, (int)avg, (int)min, (int)max, (int)max - (int)min);
 }
-void G1CollectorPolicy::print_stats (int level,
+void G1CollectorPolicy::print_stats(int level,
 const char* str,
 double value) {
 LineBuffer(level).append_and_print_cr("[%s: %5.1lf ms]", str, value);
 }
-void G1CollectorPolicy::print_stats (int level,
+void G1CollectorPolicy::print_stats(int level,
 const char* str,
 int value) {
 LineBuffer(level).append_and_print_cr("[%s: %d]", str, value);
 }
-double G1CollectorPolicy::avg_value (double* data) {
+double G1CollectorPolicy::avg_value(double* data) {
 if (G1CollectedHeap::use_parallel_gc_threads()) {
 double ret = 0.0;
-for (uint i = 0; i < ParallelGCThreads; ++i)
+for (uint i = 0; i < ParallelGCThreads; ++i) {
 ret += data[i];
+}
 return ret / (double) ParallelGCThreads;
 } else {
 return data[0];
 }
 }
-double G1CollectorPolicy::max_value (double* data) {
+double G1CollectorPolicy::max_value(double* data) {
 if (G1CollectedHeap::use_parallel_gc_threads()) {
 double ret = data[0];
-for (uint i = 1; i < ParallelGCThreads; ++i)
+for (uint i = 1; i < ParallelGCThreads; ++i) {
-if (data[i] > ret)
+if (data[i] > ret) {
 ret = data[i];
+}
+}
 return ret;
 } else {
 return data[0];
 }
 }
-double G1CollectorPolicy::sum_of_values (double* data) {
+double G1CollectorPolicy::sum_of_values(double* data) {
 if (G1CollectedHeap::use_parallel_gc_threads()) {
 double sum = 0.0;
-for (uint i = 0; i < ParallelGCThreads; i++)
+for (uint i = 0; i < ParallelGCThreads; i++) {
 sum += data[i];
+}
 return sum;
 } else {
 return data[0];
 }
 }
-double G1CollectorPolicy::max_sum (double* data1,
+double G1CollectorPolicy::max_sum(double* data1, double* data2) {
-double* data2) {
 double ret = data1[0] + data2[0];
 if (G1CollectedHeap::use_parallel_gc_threads()) {
 for (uint i = 1; i < ParallelGCThreads; ++i) {
 double data = data1[i] + data2[i];
-if (data > ret)
+if (data > ret) {
 ret = data;
+}
 }
 }
 return ret;
 }
 (double)surviving_bytes/
 (double)_collection_set_bytes_used_before;
 _n_pauses++;
+// These values are used to update the summary information that is
+// displayed when TraceGen0Time is enabled, and are output as part
+// of the PrintGCDetails output, in the non-parallel case.
 double ext_root_scan_time = avg_value(_par_last_ext_root_scan_times_ms);
 double mark_stack_scan_time = avg_value(_par_last_mark_stack_scan_times_ms);
 double update_rs_time = avg_value(_par_last_update_rs_times_ms);
 double update_rs_processed_buffers =
 sum_of_values(_par_last_update_rs_processed_buffers);
 double scan_rs_time = avg_value(_par_last_scan_rs_times_ms);
 double obj_copy_time = avg_value(_par_last_obj_copy_times_ms);
 double termination_time = avg_value(_par_last_termination_times_ms);
-double parallel_known_time = update_rs_time +
+double known_time = ext_root_scan_time +
-ext_root_scan_time +
+mark_stack_scan_time +
-mark_stack_scan_time +
+update_rs_time +
 scan_rs_time +
-obj_copy_time +
+obj_copy_time;
-termination_time;
+double other_time_ms = elapsed_ms;
-double parallel_other_time = _cur_collection_par_time_ms - parallel_known_time;
+// Subtract the SATB drain time. It's initialized to zero at the
-PauseSummary* summary = _summary;
+// start of the pause and is updated during the pause if marking
+// is in progress.
+other_time_ms -= _cur_satb_drain_time_ms;
+if (parallel) {
+other_time_ms -= _cur_collection_par_time_ms;
+} else {
+other_time_ms -= known_time;
+}
+// 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) {
 _recent_rs_scan_times_ms->add(scan_rs_time);
 _recent_pause_times_ms->add(elapsed_ms);
 _recent_rs_sizes->add(rs_size);
-MainBodySummary* body_summary = summary->main_body_summary();
+_summary->record_total_time_ms(elapsed_ms);
-guarantee(body_summary != NULL, "should not be null!");
+_summary->record_other_time_ms(other_time_ms);
-if (_satb_drain_time_set)
+MainBodySummary* body_summary = _summary->main_body_summary();
-body_summary->record_satb_drain_time_ms(_cur_satb_drain_time_ms);
+assert(body_summary != NULL, "should not be null!");
-else
-body_summary->record_satb_drain_time_ms(0.0);
+// This will be non-zero iff marking is currently in progress (i.e.
+// _g1->mark_in_progress() == true) and the currrent pause was not
+// an initial mark pause. Since the body_summary items are NumberSeqs,
+// however, they have to be consistent and updated in lock-step with
+// each other. Therefore we unconditionally record the SATB drain
+// time - even if it's zero.
+body_summary->record_satb_drain_time_ms(_cur_satb_drain_time_ms);
 body_summary->record_ext_root_scan_time_ms(ext_root_scan_time);
 body_summary->record_mark_stack_scan_time_ms(mark_stack_scan_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_clear_ct_time_ms(_cur_clear_ct_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_mark_closure_time_ms(_mark_closure_time_ms);
+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
 // (DLD, 10/05.
 assert((true || parallel)
 || _g1->evacuation_failed()
 || surviving_bytes <= _collection_set_bytes_used_before,
 "Or else negative collection!");
 _recent_CS_bytes_used_before->add(_collection_set_bytes_used_before);
 _recent_CS_bytes_surviving->add(surviving_bytes);
 // this is where we update the allocation rate of the application
 double app_time_ms =
 _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 (G1PolicyVerbose > 1) {
 gclog_or_tty->print_cr("   Recording collection pause(%d)", _n_pauses);
 }
 if (G1PolicyVerbose > 1) {
 recent_avg_survival_fraction()*100.0);
 gclog_or_tty->print_cr("       Recent %% gc pause time: %6.2f",
 recent_avg_pause_time_ratio() * 100.0);
 }
-double other_time_ms = elapsed_ms;
+// PrintGCDetails output
-if (_satb_drain_time_set) {
-other_time_ms -= _cur_satb_drain_time_ms;
-}
-if (parallel) {
-other_time_ms -= _cur_collection_par_time_ms + _cur_clear_ct_time_ms;
-} else {
-other_time_ms -=
-update_rs_time +
-ext_root_scan_time + mark_stack_scan_time +
-scan_rs_time + obj_copy_time;
-}
 if (PrintGCDetails) {
+bool print_marking_info =
+_g1->mark_in_progress() && !last_pause_included_initial_mark;
 gclog_or_tty->print_cr("%s, %1.8lf secs]",
 (last_pause_included_initial_mark) ? " (initial-mark)" : "",
 elapsed_ms / 1000.0);
-if (_satb_drain_time_set) {
+if (print_marking_info) {
 print_stats(1, "SATB Drain Time", _cur_satb_drain_time_ms);
-}
-if (_last_satb_drain_processed_buffers >= 0) {
 print_stats(2, "Processed Buffers", _last_satb_drain_processed_buffers);
 }
 if (parallel) {
 print_stats(1, "Parallel Time", _cur_collection_par_time_ms);
-print_par_stats(2, "GC Worker Start Time", _par_last_gc_worker_start_times_ms);
+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 (print_marking_info) {
+print_par_stats(2, "Mark Stack Scanning", _par_last_mark_stack_scan_times_ms);
+}
 print_par_stats(2, "Update RS", _par_last_update_rs_times_ms);
 print_par_sizes(3, "Processed Buffers", _par_last_update_rs_processed_buffers);
-print_par_stats(2, "Ext Root Scanning", _par_last_ext_root_scan_times_ms);
-print_par_stats(2, "Mark Stack Scanning", _par_last_mark_stack_scan_times_ms);
 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);
 print_par_sizes(3, "Termination Attempts", _par_last_termination_attempts);
-print_par_stats(2, "GC Worker End Time", _par_last_gc_worker_end_times_ms);
+print_par_stats(2, "GC Worker End", _par_last_gc_worker_end_times_ms);
 for (int i = 0; i < _parallel_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_mark_stack_scan_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] = _cur_collection_par_time_ms - worker_known_time;
 }
-print_par_stats(2, "GC Worker Times", _par_last_gc_worker_times_ms);
+print_par_stats(2, "GC Worker", _par_last_gc_worker_times_ms);
+print_par_stats(2, "GC Worker Other", _par_last_gc_worker_other_times_ms);
-print_stats(2, "Parallel Other", parallel_other_time);
-print_stats(1, "Clear CT", _cur_clear_ct_time_ms);
 } else {
+print_stats(1, "Ext Root Scanning", ext_root_scan_time);
+if (print_marking_info) {
+print_stats(1, "Mark Stack Scanning", mark_stack_scan_time);
+}
 print_stats(1, "Update RS", update_rs_time);
-print_stats(2, "Processed Buffers",
+print_stats(2, "Processed Buffers", (int)update_rs_processed_buffers);
-(int)update_rs_processed_buffers);
-print_stats(1, "Ext Root Scanning", ext_root_scan_time);
-print_stats(1, "Mark Stack Scanning", mark_stack_scan_time);
 print_stats(1, "Scan RS", scan_rs_time);
 print_stats(1, "Object Copying", obj_copy_time);
 }
+print_stats(1, "Clear CT", _cur_clear_ct_time_ms);
 #ifndef PRODUCT
 print_stats(1, "Cur Clear CC", _cur_clear_cc_time_ms);
 print_stats(1, "Cum Clear CC", _cum_clear_cc_time_ms);
 print_stats(1, "Min Clear CC", _min_clear_cc_time_ms);
 print_stats(1, "Max Clear CC", _max_clear_cc_time_ms);
 sprintf(buffer, "Aux%d", i);
 print_stats(1, buffer, _cur_aux_times_ms[i]);
 }
 }
 }
-_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);
-}
-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]);
-}
 // Update the efficiency-since-mark vars.
 double proc_ms = elapsed_ms * (double) _parallel_gc_threads;
 if (elapsed_ms < MIN_TIMER_GRANULARITY) {
 // This usually happens due to the timer not having the required
 void G1CollectorPolicy::count_CS_bytes_used() {
 CountCSClosure cs_closure(this);
 _g1->collection_set_iterate(&cs_closure);
 }
-void G1CollectorPolicy::print_summary (int level,
+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,
+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());
 }
 print_summary_sd(0, "Evacuation Pauses", summary->get_total_seq());
 if (body_summary != NULL) {
 print_summary(1, "SATB Drain", body_summary->get_satb_drain_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, "Mark Stack Scanning", body_summary->get_mark_stack_scan_seq());
 print_summary(2, "Update RS", body_summary->get_update_rs_seq());
-print_summary(2, "Ext Root Scanning",
-body_summary->get_ext_root_scan_seq());
-print_summary(2, "Mark Stack Scanning",
-body_summary->get_mark_stack_scan_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, "Other", body_summary->get_parallel_other_seq());
+print_summary(2, "Parallel Other", body_summary->get_parallel_other_seq());
 {
 NumberSeq* other_parts[] = {
-body_summary->get_update_rs_seq(),
 body_summary->get_ext_root_scan_seq(),
 body_summary->get_mark_stack_scan_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);
 }
-print_summary(1, "Mark Closure", body_summary->get_mark_closure_seq());
-print_summary(1, "Clear CT", body_summary->get_clear_ct_seq());
 } else {
+print_summary(1, "Ext Root Scanning", body_summary->get_ext_root_scan_seq());
+print_summary(1, "Mark Stack Scanning", body_summary->get_mark_stack_scan_seq());
 print_summary(1, "Update RS", body_summary->get_update_rs_seq());
-print_summary(1, "Ext Root Scanning",
-body_summary->get_ext_root_scan_seq());
-print_summary(1, "Mark Stack Scanning",
-body_summary->get_mark_stack_scan_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, "Mark Closure", body_summary->get_mark_closure_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) {

Mercurial > hg > graal-compiler

comparison src/share/vm/gc_implementation/g1/g1CollectorPolicy.cpp @ 4023:c6a6e936dc68