< prev index next >

src/share/vm/gc/g1/g1CollectorPolicy.cpp

Print this page

        

*** 26,41 **** #include "gc/g1/concurrentG1Refine.hpp" #include "gc/g1/concurrentMark.hpp" #include "gc/g1/concurrentMarkThread.inline.hpp" #include "gc/g1/g1CollectedHeap.inline.hpp" #include "gc/g1/g1CollectorPolicy.hpp" - #include "gc/g1/g1ErgoVerbose.hpp" #include "gc/g1/g1GCPhaseTimes.hpp" - #include "gc/g1/g1Log.hpp" #include "gc/g1/heapRegion.inline.hpp" #include "gc/g1/heapRegionRemSet.hpp" #include "gc/shared/gcPolicyCounters.hpp" #include "runtime/arguments.hpp" #include "runtime/java.hpp" #include "runtime/mutexLocker.hpp" #include "utilities/debug.hpp" --- 26,40 ---- #include "gc/g1/concurrentG1Refine.hpp" #include "gc/g1/concurrentMark.hpp" #include "gc/g1/concurrentMarkThread.inline.hpp" #include "gc/g1/g1CollectedHeap.inline.hpp" #include "gc/g1/g1CollectorPolicy.hpp" #include "gc/g1/g1GCPhaseTimes.hpp" #include "gc/g1/heapRegion.inline.hpp" #include "gc/g1/heapRegionRemSet.hpp" #include "gc/shared/gcPolicyCounters.hpp" + #include "logging/log.hpp" #include "runtime/arguments.hpp" #include "runtime/java.hpp" #include "runtime/mutexLocker.hpp" #include "utilities/debug.hpp"
*** 117,126 **** --- 116,126 ---- _rs_lengths_prediction(0), _max_survivor_regions(0), _eden_used_bytes_before_gc(0), _survivor_used_bytes_before_gc(0), + _old_used_bytes_before_gc(0), _heap_used_bytes_before_gc(0), _metaspace_used_bytes_before_gc(0), _eden_capacity_bytes_before_gc(0), _heap_capacity_bytes_before_gc(0),
*** 169,190 **** // aligned with the region size. To get around this we use the // unaligned values for the heap. HeapRegion::setup_heap_region_size(InitialHeapSize, MaxHeapSize); HeapRegionRemSet::setup_remset_size(); - G1ErgoVerbose::initialize(); - if (PrintAdaptiveSizePolicy) { - // Currently, we only use a single switch for all the heuristics. - G1ErgoVerbose::set_enabled(true); - // Given that we don't currently have a verboseness level - // parameter, we'll hardcode this to high. This can be easily - // changed in the future. - G1ErgoVerbose::set_level(ErgoHigh); - } else { - G1ErgoVerbose::set_enabled(false); - } - _recent_prev_end_times_for_all_gcs_sec->add(os::elapsedTime()); _prev_collection_pause_end_ms = os::elapsedTime() * 1000.0; _phase_times = new G1GCPhaseTimes(_parallel_gc_threads); --- 169,178 ----
*** 771,795 **** for (HeapRegion* curr = head; curr != NULL; curr = curr->get_next_young_region()) { SurvRateGroup* group = curr->surv_rate_group(); if (group == NULL && !curr->is_survivor()) { ! gclog_or_tty->print_cr("## %s: encountered NULL surv_rate_group", name); ret = false; } if (surv_rate_group == group) { int age = curr->age_in_surv_rate_group(); if (age < 0) { ! gclog_or_tty->print_cr("## %s: encountered negative age", name); ret = false; } if (age <= prev_age) { ! gclog_or_tty->print_cr("## %s: region ages are not strictly increasing " ! "(%d, %d)", name, age, prev_age); ret = false; } prev_age = age; } } --- 759,782 ---- for (HeapRegion* curr = head; curr != NULL; curr = curr->get_next_young_region()) { SurvRateGroup* group = curr->surv_rate_group(); if (group == NULL && !curr->is_survivor()) { ! log_info(gc, verify)("## %s: encountered NULL surv_rate_group", name); ret = false; } if (surv_rate_group == group) { int age = curr->age_in_surv_rate_group(); if (age < 0) { ! log_info(gc, verify)("## %s: encountered negative age", name); ret = false; } if (age <= prev_age) { ! log_info(gc, verify)("## %s: region ages are not strictly increasing (%d, %d)", name, age, prev_age); ret = false; } prev_age = age; } }
*** 957,993 **** size_t cur_used_bytes = _g1->non_young_capacity_bytes(); size_t alloc_byte_size = alloc_word_size * HeapWordSize; if ((cur_used_bytes + alloc_byte_size) > marking_initiating_used_threshold) { if (collector_state()->gcs_are_young() && !collector_state()->last_young_gc()) { ! ergo_verbose5(ErgoConcCycles, ! "request concurrent cycle initiation", ! ergo_format_reason("occupancy higher than threshold") ! ergo_format_byte("occupancy") ! ergo_format_byte("allocation request") ! ergo_format_byte_perc("threshold") ! ergo_format_str("source"), ! cur_used_bytes, ! alloc_byte_size, ! marking_initiating_used_threshold, ! (double) InitiatingHeapOccupancyPercent, ! source); return true; } else { ! ergo_verbose5(ErgoConcCycles, ! "do not request concurrent cycle initiation", ! ergo_format_reason("still doing mixed collections") ! ergo_format_byte("occupancy") ! ergo_format_byte("allocation request") ! ergo_format_byte_perc("threshold") ! ergo_format_str("source"), ! cur_used_bytes, ! alloc_byte_size, ! marking_initiating_used_threshold, ! (double) InitiatingHeapOccupancyPercent, ! source); ! } } return false; } --- 944,961 ---- size_t cur_used_bytes = _g1->non_young_capacity_bytes(); size_t alloc_byte_size = alloc_word_size * HeapWordSize; if ((cur_used_bytes + alloc_byte_size) > marking_initiating_used_threshold) { if (collector_state()->gcs_are_young() && !collector_state()->last_young_gc()) { ! log_debug(gc, ergo)("Request concurrent cycle initiation (occupancy higher than threshold)" ! "occupancy: " SIZE_FORMAT "B allocation request: " SIZE_FORMAT "B threshold: " SIZE_FORMAT "B (" UINTX_FORMAT "%%) source: %s", ! cur_used_bytes, alloc_byte_size, marking_initiating_used_threshold, InitiatingHeapOccupancyPercent, source); return true; } else { ! log_debug(gc, ergo)("Do not request concurrent cycle initiation (still doing mixed collections)" ! "occupancy: " SIZE_FORMAT "B allocation request: " SIZE_FORMAT "B threshold: " SIZE_FORMAT "B (" UINTX_FORMAT "%%) source: %s", ! cur_used_bytes, alloc_byte_size, marking_initiating_used_threshold, InitiatingHeapOccupancyPercent, source); } } return false; }
*** 1003,1019 **** size_t cur_used_bytes = _g1->used(); assert(cur_used_bytes == _g1->recalculate_used(), "It should!"); bool last_pause_included_initial_mark = false; bool update_stats = !_g1->evacuation_failed(); ! #ifndef PRODUCT ! if (G1YoungSurvRateVerbose) { ! gclog_or_tty->cr(); ! _short_lived_surv_rate_group->print(); ! // do that for any other surv rate groups too ! } ! #endif // PRODUCT last_pause_included_initial_mark = collector_state()->during_initial_mark_pause(); if (last_pause_included_initial_mark) { record_concurrent_mark_init_end(0.0); } else { --- 971,981 ---- size_t cur_used_bytes = _g1->used(); assert(cur_used_bytes == _g1->recalculate_used(), "It should!"); bool last_pause_included_initial_mark = false; bool update_stats = !_g1->evacuation_failed(); ! NOT_PRODUCT(_short_lived_surv_rate_group->print()); last_pause_included_initial_mark = collector_state()->during_initial_mark_pause(); if (last_pause_included_initial_mark) { record_concurrent_mark_init_end(0.0); } else {
*** 1184,1200 **** double update_rs_time_goal_ms = _mmu_tracker->max_gc_time() * MILLIUNITS * G1RSetUpdatingPauseTimePercent / 100.0; double scan_hcc_time_ms = average_time_ms(G1GCPhaseTimes::ScanHCC); if (update_rs_time_goal_ms < scan_hcc_time_ms) { ! ergo_verbose2(ErgoTiming, ! "adjust concurrent refinement thresholds", ! ergo_format_reason("Scanning the HCC expected to take longer than Update RS time goal") ! ergo_format_ms("Update RS time goal") ! ergo_format_ms("Scan HCC time"), ! update_rs_time_goal_ms, ! scan_hcc_time_ms); update_rs_time_goal_ms = 0; } else { update_rs_time_goal_ms -= scan_hcc_time_ms; } --- 1146,1158 ---- double update_rs_time_goal_ms = _mmu_tracker->max_gc_time() * MILLIUNITS * G1RSetUpdatingPauseTimePercent / 100.0; double scan_hcc_time_ms = average_time_ms(G1GCPhaseTimes::ScanHCC); if (update_rs_time_goal_ms < scan_hcc_time_ms) { ! log_debug(gc, ergo, refine)("Adjust concurrent refinement thresholds (scanning the HCC expected to take longer than Update RS time goal)." ! "Update RS time goal: %1.2fms Scan HCC time: %1.2fms", ! update_rs_time_goal_ms, scan_hcc_time_ms); update_rs_time_goal_ms = 0; } else { update_rs_time_goal_ms -= scan_hcc_time_ms; }
*** 1214,1282 **** YoungList* young_list = _g1->young_list(); _eden_used_bytes_before_gc = young_list->eden_used_bytes(); _survivor_used_bytes_before_gc = young_list->survivor_used_bytes(); _heap_capacity_bytes_before_gc = _g1->capacity(); _heap_used_bytes_before_gc = _g1->used(); _cur_collection_pause_used_regions_at_start = _g1->num_used_regions(); _eden_capacity_bytes_before_gc = (_young_list_target_length * HeapRegion::GrainBytes) - _survivor_used_bytes_before_gc; - if (full) { _metaspace_used_bytes_before_gc = MetaspaceAux::used_bytes(); - } } ! void G1CollectorPolicy::print_heap_transition(size_t bytes_before) const { ! size_t bytes_after = _g1->used(); ! size_t capacity = _g1->capacity(); ! ! gclog_or_tty->print(" " SIZE_FORMAT "%s->" SIZE_FORMAT "%s(" SIZE_FORMAT "%s)", ! byte_size_in_proper_unit(bytes_before), ! proper_unit_for_byte_size(bytes_before), ! byte_size_in_proper_unit(bytes_after), ! proper_unit_for_byte_size(bytes_after), ! byte_size_in_proper_unit(capacity), ! proper_unit_for_byte_size(capacity)); ! } ! ! void G1CollectorPolicy::print_heap_transition() const { ! print_heap_transition(_heap_used_bytes_before_gc); ! } ! ! void G1CollectorPolicy::print_detailed_heap_transition(bool full) const { YoungList* young_list = _g1->young_list(); size_t eden_used_bytes_after_gc = young_list->eden_used_bytes(); size_t survivor_used_bytes_after_gc = young_list->survivor_used_bytes(); ! size_t heap_used_bytes_after_gc = _g1->used(); size_t heap_capacity_bytes_after_gc = _g1->capacity(); size_t eden_capacity_bytes_after_gc = (_young_list_target_length * HeapRegion::GrainBytes) - survivor_used_bytes_after_gc; ! gclog_or_tty->print( ! " [Eden: " EXT_SIZE_FORMAT "(" EXT_SIZE_FORMAT ")->" EXT_SIZE_FORMAT "(" EXT_SIZE_FORMAT ") " ! "Survivors: " EXT_SIZE_FORMAT "->" EXT_SIZE_FORMAT " " ! "Heap: " EXT_SIZE_FORMAT "(" EXT_SIZE_FORMAT ")->" ! EXT_SIZE_FORMAT "(" EXT_SIZE_FORMAT ")]", ! EXT_SIZE_PARAMS(_eden_used_bytes_before_gc), ! EXT_SIZE_PARAMS(_eden_capacity_bytes_before_gc), ! EXT_SIZE_PARAMS(eden_used_bytes_after_gc), ! EXT_SIZE_PARAMS(eden_capacity_bytes_after_gc), ! EXT_SIZE_PARAMS(_survivor_used_bytes_before_gc), ! EXT_SIZE_PARAMS(survivor_used_bytes_after_gc), ! EXT_SIZE_PARAMS(_heap_used_bytes_before_gc), ! EXT_SIZE_PARAMS(_heap_capacity_bytes_before_gc), ! EXT_SIZE_PARAMS(heap_used_bytes_after_gc), ! EXT_SIZE_PARAMS(heap_capacity_bytes_after_gc)); ! if (full) { ! MetaspaceAux::print_metaspace_change(_metaspace_used_bytes_before_gc); ! } ! gclog_or_tty->cr(); } void G1CollectorPolicy::print_phases(double pause_time_sec) { phase_times()->print(pause_time_sec); } --- 1172,1212 ---- YoungList* young_list = _g1->young_list(); _eden_used_bytes_before_gc = young_list->eden_used_bytes(); _survivor_used_bytes_before_gc = young_list->survivor_used_bytes(); _heap_capacity_bytes_before_gc = _g1->capacity(); _heap_used_bytes_before_gc = _g1->used(); + _old_used_bytes_before_gc = _heap_used_bytes_before_gc - _survivor_used_bytes_before_gc - _eden_used_bytes_before_gc; _cur_collection_pause_used_regions_at_start = _g1->num_used_regions(); _eden_capacity_bytes_before_gc = (_young_list_target_length * HeapRegion::GrainBytes) - _survivor_used_bytes_before_gc; _metaspace_used_bytes_before_gc = MetaspaceAux::used_bytes(); } ! void G1CollectorPolicy::print_detailed_heap_transition() const { YoungList* young_list = _g1->young_list(); size_t eden_used_bytes_after_gc = young_list->eden_used_bytes(); size_t survivor_used_bytes_after_gc = young_list->survivor_used_bytes(); ! size_t old_used_bytes_after_gc = _g1->used() - eden_used_bytes_after_gc - survivor_used_bytes_after_gc; size_t heap_capacity_bytes_after_gc = _g1->capacity(); size_t eden_capacity_bytes_after_gc = (_young_list_target_length * HeapRegion::GrainBytes) - survivor_used_bytes_after_gc; + size_t survivor_capacity_bytes_after_gc = _max_survivor_regions * HeapRegion::GrainBytes; ! log_info(gc, heap)("Eden: " SIZE_FORMAT "K->" SIZE_FORMAT "K(" SIZE_FORMAT "K)", ! _eden_used_bytes_before_gc / K, eden_used_bytes_after_gc /K, eden_capacity_bytes_after_gc /K); ! log_info(gc, heap)("Survivor: " SIZE_FORMAT "K->" SIZE_FORMAT "K(" SIZE_FORMAT "K)", ! _survivor_used_bytes_before_gc / K, survivor_used_bytes_after_gc /K, survivor_capacity_bytes_after_gc /K); ! log_info(gc, heap)("Old: " SIZE_FORMAT "K->" SIZE_FORMAT "K(" SIZE_FORMAT "K)", ! _old_used_bytes_before_gc / K, old_used_bytes_after_gc /K, heap_capacity_bytes_after_gc /K); ! ! MetaspaceAux::print_metaspace_change(_metaspace_used_bytes_before_gc); } void G1CollectorPolicy::print_phases(double pause_time_sec) { phase_times()->print(pause_time_sec); }
*** 1527,1547 **** uncommitted_bytes * G1ExpandByPercentOfAvailable / 100; expand_bytes = MIN2(expand_bytes_via_pct, committed_bytes); expand_bytes = MAX2(expand_bytes, min_expand_bytes); expand_bytes = MIN2(expand_bytes, uncommitted_bytes); ! ergo_verbose5(ErgoHeapSizing, ! "attempt heap expansion", ! ergo_format_reason("recent GC overhead higher than " ! "threshold after GC") ! ergo_format_perc("recent GC overhead") ! ergo_format_perc("threshold") ! ergo_format_byte("uncommitted") ! ergo_format_byte_perc("calculated expansion amount"), ! recent_gc_overhead, threshold, ! uncommitted_bytes, ! expand_bytes_via_pct, (double) G1ExpandByPercentOfAvailable); return expand_bytes; } else { return 0; } --- 1457,1469 ---- uncommitted_bytes * G1ExpandByPercentOfAvailable / 100; expand_bytes = MIN2(expand_bytes_via_pct, committed_bytes); expand_bytes = MAX2(expand_bytes, min_expand_bytes); expand_bytes = MIN2(expand_bytes, uncommitted_bytes); ! log_debug(gc, ergo, heap)("Attempt heap expansion (recent GC overhead higher than threshold after GC) " ! "recent GC overhead: %1.2f %% threshold: %1.2f %% uncommitted: " SIZE_FORMAT "B calculated expansion amount: " SIZE_FORMAT "B (" INTX_FORMAT "%%)", ! recent_gc_overhead, threshold, uncommitted_bytes, expand_bytes_via_pct, G1ExpandByPercentOfAvailable); return expand_bytes; } else { return 0; }
*** 1602,1624 **** // We actually check whether we are marking here and not if we are in a // reclamation phase. This means that we will schedule a concurrent mark // even while we are still in the process of reclaiming memory. bool during_cycle = _g1->concurrent_mark()->cmThread()->during_cycle(); if (!during_cycle) { ! ergo_verbose1(ErgoConcCycles, ! "request concurrent cycle initiation", ! ergo_format_reason("requested by GC cause") ! ergo_format_str("GC cause"), ! GCCause::to_string(gc_cause)); collector_state()->set_initiate_conc_mark_if_possible(true); return true; } else { ! ergo_verbose1(ErgoConcCycles, ! "do not request concurrent cycle initiation", ! ergo_format_reason("concurrent cycle already in progress") ! ergo_format_str("GC cause"), ! GCCause::to_string(gc_cause)); return false; } } void G1CollectorPolicy::decide_on_conc_mark_initiation() { --- 1524,1538 ---- // We actually check whether we are marking here and not if we are in a // reclamation phase. This means that we will schedule a concurrent mark // even while we are still in the process of reclaiming memory. bool during_cycle = _g1->concurrent_mark()->cmThread()->during_cycle(); if (!during_cycle) { ! log_debug(gc, ergo)("Request concurrent cycle initiation (requested by GC cause). GC cause: %s", GCCause::to_string(gc_cause)); collector_state()->set_initiate_conc_mark_if_possible(true); return true; } else { ! log_debug(gc, ergo)("Do not request concurrent cycle initiation (concurrent cycle already in progress). GC cause: %s", GCCause::to_string(gc_cause)); return false; } } void G1CollectorPolicy::decide_on_conc_mark_initiation() {
*** 1643,1655 **** collector_state()->set_during_initial_mark_pause(true); // And we can now clear initiate_conc_mark_if_possible() as // we've already acted on it. collector_state()->set_initiate_conc_mark_if_possible(false); ! ergo_verbose0(ErgoConcCycles, ! "initiate concurrent cycle", ! ergo_format_reason("concurrent cycle initiation requested")); } else { // The concurrent marking thread is still finishing up the // previous cycle. If we start one right now the two cycles // overlap. In particular, the concurrent marking thread might // be in the process of clearing the next marking bitmap (which --- 1557,1567 ---- collector_state()->set_during_initial_mark_pause(true); // And we can now clear initiate_conc_mark_if_possible() as // we've already acted on it. collector_state()->set_initiate_conc_mark_if_possible(false); ! log_debug(gc, ergo)("Initiate concurrent cycle (concurrent cycle initiation requested)"); } else { // The concurrent marking thread is still finishing up the // previous cycle. If we start one right now the two cycles // overlap. In particular, the concurrent marking thread might // be in the process of clearing the next marking bitmap (which
*** 1659,1671 **** // cannot wait for the marking thread to finish the cycle as it // periodically yields while clearing the next marking bitmap // and, if it's in a yield point, it's waiting for us to // finish. So, at this point we will not start a cycle and we'll // let the concurrent marking thread complete the last one. ! ergo_verbose0(ErgoConcCycles, ! "do not initiate concurrent cycle", ! ergo_format_reason("concurrent cycle already in progress")); } } } class ParKnownGarbageHRClosure: public HeapRegionClosure { --- 1571,1581 ---- // cannot wait for the marking thread to finish the cycle as it // periodically yields while clearing the next marking bitmap // and, if it's in a yield point, it's waiting for us to // finish. So, at this point we will not start a cycle and we'll // let the concurrent marking thread complete the last one. ! log_debug(gc, ergo)("Do not initiate concurrent cycle (concurrent cycle already in progress)"); } } } class ParKnownGarbageHRClosure: public HeapRegionClosure {
*** 1955,1996 **** bool G1CollectorPolicy::next_gc_should_be_mixed(const char* true_action_str, const char* false_action_str) const { CollectionSetChooser* cset_chooser = _collectionSetChooser; if (cset_chooser->is_empty()) { ! ergo_verbose0(ErgoMixedGCs, ! false_action_str, ! ergo_format_reason("candidate old regions not available")); return false; } // Is the amount of uncollected reclaimable space above G1HeapWastePercent? size_t reclaimable_bytes = cset_chooser->remaining_reclaimable_bytes(); double reclaimable_perc = reclaimable_bytes_perc(reclaimable_bytes); double threshold = (double) G1HeapWastePercent; if (reclaimable_perc <= threshold) { ! ergo_verbose4(ErgoMixedGCs, ! false_action_str, ! ergo_format_reason("reclaimable percentage not over threshold") ! ergo_format_region("candidate old regions") ! ergo_format_byte_perc("reclaimable") ! ergo_format_perc("threshold"), ! cset_chooser->remaining_regions(), ! reclaimable_bytes, ! reclaimable_perc, threshold); return false; } ! ergo_verbose4(ErgoMixedGCs, ! true_action_str, ! ergo_format_reason("candidate old regions available") ! ergo_format_region("candidate old regions") ! ergo_format_byte_perc("reclaimable") ! ergo_format_perc("threshold"), ! cset_chooser->remaining_regions(), ! reclaimable_bytes, ! reclaimable_perc, threshold); return true; } uint G1CollectorPolicy::calc_min_old_cset_length() const { // The min old CSet region bound is based on the maximum desired --- 1865,1890 ---- bool G1CollectorPolicy::next_gc_should_be_mixed(const char* true_action_str, const char* false_action_str) const { CollectionSetChooser* cset_chooser = _collectionSetChooser; if (cset_chooser->is_empty()) { ! log_debug(gc, ergo)("%s (candidate old regions not available)", false_action_str); return false; } // Is the amount of uncollected reclaimable space above G1HeapWastePercent? size_t reclaimable_bytes = cset_chooser->remaining_reclaimable_bytes(); double reclaimable_perc = reclaimable_bytes_perc(reclaimable_bytes); double threshold = (double) G1HeapWastePercent; if (reclaimable_perc <= threshold) { ! log_debug(gc, ergo)("%s (reclaimable percentage not over threshold). candidate old regions: %u reclaimable: " SIZE_FORMAT " (%1.2f) threshold: " UINTX_FORMAT, ! false_action_str, cset_chooser->remaining_regions(), reclaimable_bytes, reclaimable_perc, G1HeapWastePercent); return false; } ! log_debug(gc, ergo)("%s (candidate old regions available). candidate old regions: %u reclaimable: " SIZE_FORMAT " (%1.2f) threshold: " UINTX_FORMAT, ! true_action_str, cset_chooser->remaining_regions(), reclaimable_bytes, reclaimable_perc, G1HeapWastePercent); return true; } uint G1CollectorPolicy::calc_min_old_cset_length() const { // The min old CSet region bound is based on the maximum desired
*** 2042,2057 **** guarantee(_collection_set == NULL, "Precondition"); double base_time_ms = predict_base_elapsed_time_ms(_pending_cards); double time_remaining_ms = MAX2(target_pause_time_ms - base_time_ms, 0.0); ! ergo_verbose4(ErgoCSetConstruction | ErgoHigh, ! "start choosing CSet", ! ergo_format_size("_pending_cards") ! ergo_format_ms("predicted base time") ! ergo_format_ms("remaining time") ! ergo_format_ms("target pause time"), _pending_cards, base_time_ms, time_remaining_ms, target_pause_time_ms); collector_state()->set_last_gc_was_young(collector_state()->gcs_are_young()); if (collector_state()->last_gc_was_young()) { --- 1936,1946 ---- guarantee(_collection_set == NULL, "Precondition"); double base_time_ms = predict_base_elapsed_time_ms(_pending_cards); double time_remaining_ms = MAX2(target_pause_time_ms - base_time_ms, 0.0); ! log_trace(gc, ergo, cset)("Start choosing CSet. pending cards: " SIZE_FORMAT " predicted base time: %1.2fms remaining time: %1.2fms target pause time: %1.2fms", _pending_cards, base_time_ms, time_remaining_ms, target_pause_time_ms); collector_state()->set_last_gc_was_young(collector_state()->gcs_are_young()); if (collector_state()->last_gc_was_young()) {
*** 2084,2102 **** _collection_set = _inc_cset_head; _collection_set_bytes_used_before = _inc_cset_bytes_used_before; time_remaining_ms = MAX2(time_remaining_ms - _inc_cset_predicted_elapsed_time_ms, 0.0); ! ergo_verbose4(ErgoCSetConstruction | ErgoHigh, ! "add young regions to CSet", ! ergo_format_region("eden") ! ergo_format_region("survivors") ! ergo_format_ms("predicted young region time") ! ergo_format_ms("target pause time"), ! eden_region_length, survivor_region_length, ! _inc_cset_predicted_elapsed_time_ms, ! target_pause_time_ms); // The number of recorded young regions is the incremental // collection set's current size set_recorded_rs_lengths(_inc_cset_recorded_rs_lengths); --- 1973,1984 ---- _collection_set = _inc_cset_head; _collection_set_bytes_used_before = _inc_cset_bytes_used_before; time_remaining_ms = MAX2(time_remaining_ms - _inc_cset_predicted_elapsed_time_ms, 0.0); ! log_trace(gc, ergo, cset)("Add young regions to CSet. eden: %u regions, survivors: %u regions, predicted young region time: %1.2fms, target pause time: %1.2fms", ! eden_region_length, survivor_region_length, _inc_cset_predicted_elapsed_time_ms, target_pause_time_ms); // The number of recorded young regions is the incremental // collection set's current size set_recorded_rs_lengths(_inc_cset_recorded_rs_lengths);
*** 2122,2136 **** HeapRegion* hr = cset_chooser->peek(); while (hr != NULL) { if (old_cset_region_length() >= max_old_cset_length) { // Added maximum number of old regions to the CSet. ! ergo_verbose2(ErgoCSetConstruction, ! "finish adding old regions to CSet", ! ergo_format_reason("old CSet region num reached max") ! ergo_format_region("old") ! ergo_format_region("max"), old_cset_region_length(), max_old_cset_length); break; } --- 2004,2014 ---- HeapRegion* hr = cset_chooser->peek(); while (hr != NULL) { if (old_cset_region_length() >= max_old_cset_length) { // Added maximum number of old regions to the CSet. ! log_debug(gc, ergo, cset)("Finish adding old regions to CSet (old CSet region num reached max). old %u regions, max %u regions", old_cset_region_length(), max_old_cset_length); break; }
*** 2141,2161 **** double threshold = (double) G1HeapWastePercent; if (reclaimable_perc <= threshold) { // We've added enough old regions that the amount of uncollected // reclaimable space is at or below the waste threshold. Stop // adding old regions to the CSet. ! ergo_verbose5(ErgoCSetConstruction, ! "finish adding old regions to CSet", ! ergo_format_reason("reclaimable percentage not over threshold") ! ergo_format_region("old") ! ergo_format_region("max") ! ergo_format_byte_perc("reclaimable") ! ergo_format_perc("threshold"), ! old_cset_region_length(), ! max_old_cset_length, ! reclaimable_bytes, ! reclaimable_perc, threshold); break; } double predicted_time_ms = predict_region_elapsed_time_ms(hr, collector_state()->gcs_are_young()); if (check_time_remaining) { --- 2019,2031 ---- double threshold = (double) G1HeapWastePercent; if (reclaimable_perc <= threshold) { // We've added enough old regions that the amount of uncollected // reclaimable space is at or below the waste threshold. Stop // adding old regions to the CSet. ! log_debug(gc, ergo, cset)("Finish adding old regions to CSet (reclaimable percentage not over threshold). " ! "old %u regions, max %u regions, reclaimable: " SIZE_FORMAT "B (%1.2f%%) threshold: " UINTX_FORMAT "%%", ! old_cset_region_length(), max_old_cset_length, reclaimable_bytes, reclaimable_perc, G1HeapWastePercent); break; } double predicted_time_ms = predict_region_elapsed_time_ms(hr, collector_state()->gcs_are_young()); if (check_time_remaining) {
*** 2163,2181 **** // Too expensive for the current CSet. if (old_cset_region_length() >= min_old_cset_length) { // We have added the minimum number of old regions to the CSet, // we are done with this CSet. ! ergo_verbose4(ErgoCSetConstruction, ! "finish adding old regions to CSet", ! ergo_format_reason("predicted time is too high") ! ergo_format_ms("predicted time") ! ergo_format_ms("remaining time") ! ergo_format_region("old") ! ergo_format_region("min"), ! predicted_time_ms, time_remaining_ms, ! old_cset_region_length(), min_old_cset_length); break; } // We'll add it anyway given that we haven't reached the // minimum number of old regions. --- 2033,2045 ---- // Too expensive for the current CSet. if (old_cset_region_length() >= min_old_cset_length) { // We have added the minimum number of old regions to the CSet, // we are done with this CSet. ! log_debug(gc, ergo, cset)("Finish adding old regions to CSet (predicted time is too high). " ! "predicted time: %1.2fms, remaining time: %1.2fms old %u regions, min %u regions", ! predicted_time_ms, time_remaining_ms, old_cset_region_length(), min_old_cset_length); break; } // We'll add it anyway given that we haven't reached the // minimum number of old regions.
*** 2183,2197 **** } } else { if (old_cset_region_length() >= min_old_cset_length) { // In the non-auto-tuning case, we'll finish adding regions // to the CSet if we reach the minimum. ! ergo_verbose2(ErgoCSetConstruction, ! "finish adding old regions to CSet", ! ergo_format_reason("old CSet region num reached min") ! ergo_format_region("old") ! ergo_format_region("min"), old_cset_region_length(), min_old_cset_length); break; } } --- 2047,2058 ---- } } else { if (old_cset_region_length() >= min_old_cset_length) { // In the non-auto-tuning case, we'll finish adding regions // to the CSet if we reach the minimum. ! ! log_debug(gc, ergo, cset)("Finish adding old regions to CSet (old CSet region num reached min). old %u regions, min %u regions", old_cset_region_length(), min_old_cset_length); break; } }
*** 2203,2246 **** add_old_region_to_cset(hr); hr = cset_chooser->peek(); } if (hr == NULL) { ! ergo_verbose0(ErgoCSetConstruction, ! "finish adding old regions to CSet", ! ergo_format_reason("candidate old regions not available")); } if (expensive_region_num > 0) { // We print the information once here at the end, predicated on // whether we added any apparently expensive regions or not, to // avoid generating output per region. ! ergo_verbose4(ErgoCSetConstruction, ! "added expensive regions to CSet", ! ergo_format_reason("old CSet region num not reached min") ! ergo_format_region("old") ! ergo_format_region("expensive") ! ergo_format_region("min") ! ergo_format_ms("remaining time"), ! old_cset_region_length(), ! expensive_region_num, ! min_old_cset_length, ! time_remaining_ms); } cset_chooser->verify(); } stop_incremental_cset_building(); ! ergo_verbose3(ErgoCSetConstruction, ! "finish choosing CSet", ! ergo_format_region("old") ! ergo_format_ms("predicted old region time") ! ergo_format_ms("time remaining"), ! old_cset_region_length(), ! predicted_old_time_ms, time_remaining_ms); double non_young_end_time_sec = os::elapsedTime(); phase_times()->record_non_young_cset_choice_time_ms((non_young_end_time_sec - non_young_start_time_sec) * 1000.0); } --- 2064,2092 ---- add_old_region_to_cset(hr); hr = cset_chooser->peek(); } if (hr == NULL) { ! log_debug(gc, ergo, cset)("Finish adding old regions to CSet (candidate old regions not available)"); } if (expensive_region_num > 0) { // We print the information once here at the end, predicated on // whether we added any apparently expensive regions or not, to // avoid generating output per region. ! log_debug(gc, ergo, cset)("Added expensive regions to CSet (old CSet region num not reached min)." ! "old %u regions, expensive: %u regions, min %u regions, remaining time: %1.2fms", ! old_cset_region_length(), expensive_region_num, min_old_cset_length, time_remaining_ms); } cset_chooser->verify(); } stop_incremental_cset_building(); ! log_debug(gc, ergo, cset)("Finish choosing CSet. old %u regions, predicted old region time: %1.2fms, time remaining: %1.2f", ! old_cset_region_length(), predicted_old_time_ms, time_remaining_ms); double non_young_end_time_sec = os::elapsedTime(); phase_times()->record_non_young_cset_choice_time_ms((non_young_end_time_sec - non_young_start_time_sec) * 1000.0); }
*** 2295,2332 **** } void TraceYoungGenTimeData::print_summary(const char* str, const NumberSeq* seq) const { double sum = seq->sum(); ! gclog_or_tty->print_cr("%-27s = %8.2lf s (avg = %8.2lf ms)", str, sum / 1000.0, seq->avg()); } void TraceYoungGenTimeData::print_summary_sd(const char* str, const NumberSeq* seq) const { print_summary(str, seq); ! gclog_or_tty->print_cr("%45s = %5d, std dev = %8.2lf ms, max = %8.2lf ms)", "(num", seq->num(), seq->sd(), seq->maximum()); } void TraceYoungGenTimeData::print() const { if (!TraceYoungGenTime) { return; } ! gclog_or_tty->print_cr("ALL PAUSES"); print_summary_sd(" Total", &_total); ! gclog_or_tty->cr(); ! gclog_or_tty->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->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(" Evacuation Pauses", &_total); print_summary(" Root Region Scan Wait", &_root_region_scan_wait); print_summary(" Parallel Time", &_parallel); print_summary(" Ext Root Scanning", &_ext_root_scan); --- 2141,2178 ---- } void TraceYoungGenTimeData::print_summary(const char* str, const NumberSeq* seq) const { double sum = seq->sum(); ! tty->print_cr("%-27s = %8.2lf s (avg = %8.2lf ms)", str, sum / 1000.0, seq->avg()); } void TraceYoungGenTimeData::print_summary_sd(const char* str, const NumberSeq* seq) const { print_summary(str, seq); ! tty->print_cr("%45s = %5d, std dev = %8.2lf ms, max = %8.2lf ms)", "(num", seq->num(), seq->sd(), seq->maximum()); } void TraceYoungGenTimeData::print() const { if (!TraceYoungGenTime) { return; } ! tty->print_cr("ALL PAUSES"); print_summary_sd(" Total", &_total); ! tty->cr(); ! tty->cr(); ! tty->print_cr(" Young GC Pauses: %8d", _young_pause_num); ! tty->print_cr(" Mixed GC Pauses: %8d", _mixed_pause_num); ! tty->cr(); ! tty->print_cr("EVACUATION PAUSES"); if (_young_pause_num == 0 && _mixed_pause_num == 0) { ! tty->print_cr("none"); } else { print_summary_sd(" Evacuation Pauses", &_total); print_summary(" Root Region Scan Wait", &_root_region_scan_wait); print_summary(" Parallel Time", &_parallel); print_summary(" Ext Root Scanning", &_ext_root_scan);
*** 2337,2349 **** print_summary(" Termination", &_termination); print_summary(" Parallel Other", &_parallel_other); print_summary(" Clear CT", &_clear_ct); print_summary(" Other", &_other); } ! gclog_or_tty->cr(); ! gclog_or_tty->print_cr("MISC"); print_summary_sd(" Stop World", &_all_stop_world_times_ms); print_summary_sd(" Yields", &_all_yield_times_ms); } void TraceOldGenTimeData::record_full_collection(double full_gc_time_ms) { --- 2183,2195 ---- print_summary(" Termination", &_termination); print_summary(" Parallel Other", &_parallel_other); print_summary(" Clear CT", &_clear_ct); print_summary(" Other", &_other); } ! tty->cr(); ! tty->print_cr("MISC"); print_summary_sd(" Stop World", &_all_stop_world_times_ms); print_summary_sd(" Yields", &_all_yield_times_ms); } void TraceOldGenTimeData::record_full_collection(double full_gc_time_ms) {
*** 2356,2369 **** if (!TraceOldGenTime) { 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()); } } --- 2202,2215 ---- if (!TraceOldGenTime) { return; } if (_all_full_gc_times.num() > 0) { ! tty->print("\n%4d full_gcs: total time = %8.2f s", _all_full_gc_times.num(), _all_full_gc_times.sum() / 1000.0); ! tty->print_cr(" (avg = %8.2fms).", _all_full_gc_times.avg()); ! tty->print_cr(" [std. dev = %8.2f ms, max = %8.2f ms]", _all_full_gc_times.sd(), _all_full_gc_times.maximum()); } }
< prev index next >