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