jdk-sandbox: comparison hotspot/src/share/vm/gc/g1/g1CollectorPolicy.cpp

equal deleted inserted replaced

-:382d0689141c
+:be6025ebffea
 #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"
 _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),
 // the region size on the heap size, but the heap size should be
 // 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;
 clear_ratio_check_data();
 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);
+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) {
-gclog_or_tty->print_cr("## %s: encountered negative age", name);
+log_info(gc, verify)("## %s: encountered negative age", name);
 ret = false;
 }
 if (age <= prev_age) {
-gclog_or_tty->print_cr("## %s: region ages are not strictly increasing "
+log_info(gc, verify)("## %s: region ages are not strictly increasing (%d, %d)", name, age, prev_age);
-"(%d, %d)", name, age, prev_age);
 ret = false;
 }
 prev_age = age;
 }
 }
 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) {
-if (collector_state()->gcs_are_young() && !collector_state()->last_young_gc()) {
+result = collector_state()->gcs_are_young() && !collector_state()->last_young_gc();
-ergo_verbose5(ErgoConcCycles,
+log_debug(gc, ergo, ihop)("%s occupancy: " SIZE_FORMAT "B allocation request: " SIZE_FORMAT "B threshold: " SIZE_FORMAT "B (%1.2f) source: %s",
-"request concurrent cycle initiation",
+result ? "Request concurrent cycle initiation (occupancy higher than threshold)" : "Do not request concurrent cycle initiation (still doing mixed collections)",
-ergo_format_reason("occupancy higher than threshold")
+cur_used_bytes, alloc_byte_size, marking_initiating_used_threshold, (double) marking_initiating_used_threshold / _g1->capacity() * 100, source);
-ergo_format_byte("occupancy")
+}
-ergo_format_byte("allocation request")
-ergo_format_byte_perc("threshold")
+return result;
-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
 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
+NOT_PRODUCT(_short_lived_surv_rate_group->print());
-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) {
 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,
+log_debug(gc, ergo, refine)("Adjust concurrent refinement thresholds (scanning the HCC expected to take longer than Update RS time goal)."
-"adjust concurrent refinement thresholds",
+"Update RS time goal: %1.2fms Scan HCC time: %1.2fms",
-ergo_format_reason("Scanning the HCC expected to take longer than Update RS time goal")
+update_rs_time_goal_ms, scan_hcc_time_ms);
-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;
 }
 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;
-_eden_capacity_bytes_before_gc =
+_metaspace_used_bytes_before_gc = MetaspaceAux::used_bytes();
-(_young_list_target_length * HeapRegion::GrainBytes) - _survivor_used_bytes_before_gc;
+}
-if (full) {
+void G1CollectorPolicy::print_detailed_heap_transition() const {
-_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 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;
-gclog_or_tty->print(
-"   [Eden: " EXT_SIZE_FORMAT "(" EXT_SIZE_FORMAT ")->" EXT_SIZE_FORMAT "(" EXT_SIZE_FORMAT ") "
+log_info(gc, heap)("Eden: " SIZE_FORMAT "K->" SIZE_FORMAT "K("  SIZE_FORMAT "K)",
-"Survivors: " EXT_SIZE_FORMAT "->" EXT_SIZE_FORMAT " "
+_eden_used_bytes_before_gc / K, eden_used_bytes_after_gc /K, eden_capacity_bytes_after_gc /K);
-"Heap: " EXT_SIZE_FORMAT "(" EXT_SIZE_FORMAT ")->"
+log_info(gc, heap)("Survivor: " SIZE_FORMAT "K->" SIZE_FORMAT "K("  SIZE_FORMAT "K)",
-EXT_SIZE_FORMAT "(" EXT_SIZE_FORMAT ")]",
+_survivor_used_bytes_before_gc / K, survivor_used_bytes_after_gc /K, survivor_capacity_bytes_after_gc /K);
-EXT_SIZE_PARAMS(_eden_used_bytes_before_gc),
+log_info(gc, heap)("Old: " SIZE_FORMAT "K->" SIZE_FORMAT "K",
-EXT_SIZE_PARAMS(_eden_capacity_bytes_before_gc),
+_old_used_bytes_before_gc / K, old_used_bytes_after_gc /K);
-EXT_SIZE_PARAMS(eden_used_bytes_after_gc),
+log_info(gc, heap)("Humongous: " SIZE_FORMAT "K->" SIZE_FORMAT "K",
-EXT_SIZE_PARAMS(eden_capacity_bytes_after_gc),
+_humongous_used_bytes_before_gc / K, humongous_used_bytes_after_gc /K);
-EXT_SIZE_PARAMS(_survivor_used_bytes_before_gc),
-EXT_SIZE_PARAMS(survivor_used_bytes_after_gc),
+MetaspaceAux::print_metaspace_change(_metaspace_used_bytes_before_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);
 }
 scale_factor = 1 + ((ratio_delta - StartScaleUpAt) / ScaleUpRange);
 scale_factor = MIN2(scale_factor, MaxScaleUpFactor);
 }
 }
-ergo_verbose5(ErgoHeapSizing,
+log_debug(gc, ergo, heap)("Attempt heap expansion (recent GC overhead higher than threshold after GC) "
-"attempt heap expansion",
+"recent GC overhead: %1.2f %% threshold: %1.2f %% uncommitted: " SIZE_FORMAT "B base expansion amount and scale: " SIZE_FORMAT "B (%1.2f%%)",
-ergo_format_reason("recent GC overhead higher than "
+recent_gc_overhead, threshold, uncommitted_bytes, expand_bytes, scale_factor * 100);
-"threshold after GC")
-ergo_format_perc("recent GC overhead")
-ergo_format_perc("current threshold")
-ergo_format_byte("uncommitted")
-ergo_format_byte_perc("base expansion amount and scale"),
-recent_gc_overhead, threshold,
-uncommitted_bytes,
-expand_bytes, scale_factor * 100);
 expand_bytes = static_cast<size_t>(expand_bytes * scale_factor);
 // Ensure the expansion size is at least the minimum growth amount
 // and at most the remaining uncommitted byte size.
 // 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,
+log_debug(gc, ergo)("Request concurrent cycle initiation (requested by GC cause). GC cause: %s", GCCause::to_string(gc_cause));
-"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,
+log_debug(gc, ergo)("Do not request concurrent cycle initiation (concurrent cycle already in progress). GC cause: %s", GCCause::to_string(gc_cause));
-"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::initiate_conc_mark() {
 // concurrent marking cycle. So we might initiate one.
 if (!about_to_start_mixed_phase() && collector_state()->gcs_are_young()) {
 // Initiate a new initial mark if there is no marking or reclamation going on.
 initiate_conc_mark();
-ergo_verbose0(ErgoConcCycles,
+log_debug(gc, ergo)("Initiate concurrent cycle (concurrent cycle initiation requested)");
-"initiate concurrent cycle",
-ergo_format_reason("concurrent cycle initiation requested"));
 } else if (_g1->is_user_requested_concurrent_full_gc(_g1->gc_cause())) {
 // Initiate a user requested initial mark. An initial mark must be young only
 // GC, so the collector state must be updated to reflect this.
 collector_state()->set_gcs_are_young(true);
 collector_state()->set_last_young_gc(false);
 abort_time_to_mixed_tracking();
 initiate_conc_mark();
-ergo_verbose0(ErgoConcCycles,
+log_debug(gc, ergo)("Initiate concurrent cycle (user requested concurrent cycle)");
-"initiate concurrent cycle",
-ergo_format_reason("user requested concurrent cycle"));
 } 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
 // 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,
+log_debug(gc, ergo)("Do not initiate concurrent cycle (concurrent cycle already in progress)");
-"do not initiate concurrent cycle",
-ergo_format_reason("concurrent cycle already in progress"));
 }
 }
 }
 class ParKnownGarbageHRClosure: public HeapRegionClosure {
 }
 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,
+log_debug(gc, ergo)("%s (candidate old regions not available)", false_action_str);
-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,
+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,
+false_action_str, cset_chooser()->remaining_regions(), reclaimable_bytes, reclaimable_perc, G1HeapWastePercent);
-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;
 }
+log_debug(gc, ergo)("%s (candidate old regions available). candidate old regions: %u reclaimable: " SIZE_FORMAT " (%1.2f) threshold: " UINTX_FORMAT,
-ergo_verbose4(ErgoMixedGCs,
+true_action_str, cset_chooser()->remaining_regions(), reclaimable_bytes, reclaimable_perc, G1HeapWastePercent);
-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
 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,
+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",
-"start choosing CSet",
+_pending_cards, base_time_ms, time_remaining_ms, target_pause_time_ms);
-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()) {
 _trace_young_gen_time_data.increment_young_collection_count();
 _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,
+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",
-"add young regions to CSet",
+eden_region_length, survivor_region_length, _inc_cset_predicted_elapsed_time_ms, target_pause_time_ms);
-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);
 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,
+log_debug(gc, ergo, cset)("Finish adding old regions to CSet (old CSet region num reached max). old %u regions, max %u regions",
-"finish adding old regions to CSet",
+old_cset_region_length(), max_old_cset_length);
-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;
 }
 // Stop adding regions if the remaining reclaimable space is
 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,
+log_debug(gc, ergo, cset)("Finish adding old regions to CSet (reclaimable percentage not over threshold). "
-"finish adding old regions to CSet",
+"old %u regions, max %u regions, reclaimable: " SIZE_FORMAT "B (%1.2f%%) threshold: " UINTX_FORMAT "%%",
-ergo_format_reason("reclaimable percentage not over threshold")
+old_cset_region_length(), max_old_cset_length, reclaimable_bytes, reclaimable_perc, G1HeapWastePercent);
-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) {
 // 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,
+log_debug(gc, ergo, cset)("Finish adding old regions to CSet (predicted time is too high). "
-"finish adding old regions to CSet",
+"predicted time: %1.2fms, remaining time: %1.2fms old %u regions, min %u regions",
-ergo_format_reason("predicted time is too high")
+predicted_time_ms, time_remaining_ms, old_cset_region_length(), min_old_cset_length);
-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.
 }
 } 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",
+log_debug(gc, ergo, cset)("Finish adding old regions to CSet (old CSet region num reached min). old %u regions, min %u regions",
-ergo_format_reason("old CSet region num reached min")
+old_cset_region_length(), min_old_cset_length);
-ergo_format_region("old")
-ergo_format_region("min"),
-old_cset_region_length(), min_old_cset_length);
 break;
 }
 }
 // We will add this region to the CSet.
 add_old_region_to_cset(hr);
 hr = cset_chooser()->peek();
 }
 if (hr == NULL) {
-ergo_verbose0(ErgoCSetConstruction,
+log_debug(gc, ergo, cset)("Finish adding old regions to CSet (candidate old regions not available)");
-"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,
+log_debug(gc, ergo, cset)("Added expensive regions to CSet (old CSet region num not reached min)."
-"added expensive regions to CSet",
+"old %u regions, expensive: %u regions, min %u regions, remaining time: %1.2fms",
-ergo_format_reason("old CSet region num not reached min")
+old_cset_region_length(), expensive_region_num, min_old_cset_length, time_remaining_ms);
-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,
+log_debug(gc, ergo, cset)("Finish choosing CSet. old %u regions, predicted old region time: %1.2fms, time remaining: %1.2f",
-"finish choosing CSet",
+old_cset_region_length(), predicted_old_time_ms, time_remaining_ms);
-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);
 }
 }
 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)",
+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)",
+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");
+tty->print_cr("ALL PAUSES");
 print_summary_sd("   Total", &_total);
-gclog_or_tty->cr();
+tty->cr();
-gclog_or_tty->cr();
+tty->cr();
-gclog_or_tty->print_cr("   Young GC Pauses: %8d", _young_pause_num);
+tty->print_cr("   Young GC Pauses: %8d", _young_pause_num);
-gclog_or_tty->print_cr("   Mixed GC Pauses: %8d", _mixed_pause_num);
+tty->print_cr("   Mixed GC Pauses: %8d", _mixed_pause_num);
-gclog_or_tty->cr();
+tty->cr();
-gclog_or_tty->print_cr("EVACUATION PAUSES");
+tty->print_cr("EVACUATION PAUSES");
 if (_young_pause_num == 0 && _mixed_pause_num == 0) {
-gclog_or_tty->print_cr("none");
+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);
 print_summary("         Termination", &_termination);
 print_summary("         Parallel Other", &_parallel_other);
 print_summary("      Clear CT", &_clear_ct);
 print_summary("      Other", &_other);
 }
-gclog_or_tty->cr();
+tty->cr();
-gclog_or_tty->print_cr("MISC");
+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) {
 if (!TraceOldGenTime) {
 return;
 }
 if (_all_full_gc_times.num() > 0) {
-gclog_or_tty->print("\n%4d full_gcs: total time = %8.2f s",
+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());
+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]",
+tty->print_cr("                     [std. dev = %8.2f ms, max = %8.2f ms]",
 _all_full_gc_times.sd(),
 _all_full_gc_times.maximum());
 }
 }

changeset 35061	be6025ebffea
parent 35059	1805414a18bc
child 35163	448e610805bb