< prev index next >
src/share/vm/gc/g1/g1CollectorPolicy.cpp
Print this page
*** 27,39 ****
#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/g1IHOPControl.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"
--- 27,37 ----
*** 119,128 ****
--- 117,128 ----
_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),
+ _humongous_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),
*** 175,196 ****
// 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);
--- 175,184 ----
*** 788,812 ****
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;
}
}
--- 776,799 ----
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;
}
}
*** 981,1022 ****
size_t cur_used_bytes = _g1->non_young_capacity_bytes();
size_t alloc_byte_size = alloc_word_size * HeapWordSize;
size_t marking_request_bytes = cur_used_bytes + alloc_byte_size;
if (marking_request_bytes > 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) marking_initiating_used_threshold / _g1->capacity() * 100,
! 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;
}
// Anything below that is considered to be zero
#define MIN_TIMER_GRANULARITY 0.0000001
--- 968,986 ----
size_t cur_used_bytes = _g1->non_young_capacity_bytes();
size_t alloc_byte_size = alloc_word_size * HeapWordSize;
size_t marking_request_bytes = cur_used_bytes + alloc_byte_size;
+ bool result = false;
if (marking_request_bytes > marking_initiating_used_threshold) {
! result = collector_state()->gcs_are_young() && !collector_state()->last_young_gc();
! log_debug(gc, ihop, ergo)("%s occupancy: " SIZE_FORMAT "B allocation request: " SIZE_FORMAT "B threshold: " SIZE_FORMAT "B (%1.2f) source: %s",
! result ? "Request concurrent cycle initiation (occupancy higher than threshold)" : "Do not request concurrent cycle initiation (still doing mixed collections)",
! cur_used_bytes, alloc_byte_size, marking_initiating_used_threshold, (double) marking_initiating_used_threshold / _g1->capacity() * 100, source);
}
! return result;
}
// Anything below that is considered to be zero
#define MIN_TIMER_GRANULARITY 0.0000001
*** 1026,1042 ****
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
record_pause(young_gc_pause_kind(), end_time_sec - pause_time_ms / 1000.0, end_time_sec);
last_pause_included_initial_mark = collector_state()->during_initial_mark_pause();
if (last_pause_included_initial_mark) {
--- 990,1000 ----
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());
record_pause(young_gc_pause_kind(), end_time_sec - pause_time_ms / 1000.0, end_time_sec);
last_pause_included_initial_mark = collector_state()->during_initial_mark_pause();
if (last_pause_included_initial_mark) {
*** 1219,1235 ****
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;
}
--- 1177,1189 ----
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;
}
*** 1303,1371 ****
void G1CollectorPolicy::record_heap_size_info_at_start(bool full) {
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();
!
! _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);
}
--- 1257,1297 ----
void G1CollectorPolicy::record_heap_size_info_at_start(bool full) {
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();
+ _old_used_bytes_before_gc = _g1->old_regions_count() * HeapRegion::GrainBytes;
+ _humongous_used_bytes_before_gc = _g1->humongous_regions_count() * HeapRegion::GrainBytes;
_heap_used_bytes_before_gc = _g1->used();
! _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 heap_used_bytes_after_gc = _g1->used();
+ size_t old_used_bytes_after_gc = _g1->old_regions_count() * HeapRegion::GrainBytes;
+ size_t humongous_used_bytes_after_gc = _g1->humongous_regions_count() * HeapRegion::GrainBytes;
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)("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)("Humongous: " SIZE_FORMAT "K->" SIZE_FORMAT "K",
! _humongous_used_bytes_before_gc / K, humongous_used_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);
}
*** 1616,1636 ****
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;
}
--- 1542,1554 ----
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;
}
*** 1691,1713 ****
// 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() {
--- 1609,1623 ----
// 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() {
*** 1732,1744 ****
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
--- 1642,1652 ----
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
*** 1748,1760 ****
// 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 {
--- 1656,1666 ----
// 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 {
*** 2096,2137 ****
}
bool G1CollectorPolicy::next_gc_should_be_mixed(const char* true_action_str,
const char* false_action_str) const {
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
--- 2002,2026 ----
}
bool G1CollectorPolicy::next_gc_should_be_mixed(const char* true_action_str,
const char* false_action_str) const {
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
*** 2183,2198 ****
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()) {
--- 2072,2082 ----
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()) {
*** 2225,2243 ****
_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);
--- 2109,2120 ----
_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);
*** 2262,2276 ****
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;
}
--- 2139,2149 ----
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;
}
*** 2281,2301 ****
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) {
--- 2154,2166 ----
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) {
*** 2303,2321 ****
// 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.
--- 2168,2180 ----
// 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.
*** 2323,2337 ****
}
} 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;
}
}
--- 2182,2193 ----
}
} 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;
}
}
*** 2343,2386 ****
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);
}
--- 2199,2227 ----
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);
}
*** 2435,2472 ****
}
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);
--- 2276,2313 ----
}
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);
*** 2477,2489 ****
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) {
--- 2318,2330 ----
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) {
*** 2496,2509 ****
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());
}
}
--- 2337,2350 ----
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 >