< prev index next >

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

Print this page

        

@@ -26,16 +26,15 @@
 #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 "logging/log.hpp"
 #include "runtime/arguments.hpp"
 #include "runtime/java.hpp"
 #include "runtime/mutexLocker.hpp"
 #include "utilities/debug.hpp"
 

@@ -117,10 +116,11 @@
   _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,22 +169,10 @@
   // 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);
 

@@ -760,25 +748,24 @@
   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 "
-                               "(%d, %d)", name, 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;
     }
   }

@@ -940,37 +927,18 @@
   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);
+      log_debug(gc, ergo, conc)("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 {
-      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);
-    }
+      log_debug(gc, ergo, conc)("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;
 }
 

@@ -986,17 +954,11 @@
   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
+  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 if (need_to_start_conc_mark("end of GC")) {

@@ -1063,13 +1025,11 @@
       if (next_gc_should_be_mixed("start mixed GCs",
                                   "do not start mixed GCs")) {
         collector_state()->set_gcs_are_young(false);
       }
     } else {
-      ergo_verbose0(ErgoMixedGCs,
-                    "do not start mixed GCs",
-                    ergo_format_reason("concurrent cycle is about to start"));
+      log_debug(gc, ergo)("Do not start mixed GCs (concurrent cycle is about to start)");
     }
     collector_state()->set_last_young_gc(false);
   }
 
   if (!collector_state()->last_gc_was_young()) {

@@ -1172,17 +1132,13 @@
   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);
+    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;
   }

@@ -1202,69 +1158,41 @@
   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;
 
-  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 {
+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->used() - eden_used_bytes_after_gc - eden_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;
 
-  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));
+  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);
 
-  if (full) {
-    MetaspaceAux::print_metaspace_change(_metaspace_used_bytes_before_gc);
-  }
+  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);
 
-  gclog_or_tty->cr();
+  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);
 }

@@ -1515,21 +1443,13 @@
       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);
+    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;
   }

@@ -1588,23 +1508,15 @@
 
 bool G1CollectorPolicy::force_initial_mark_if_outside_cycle(
                                                      GCCause::Cause gc_cause) {
   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));
+    log_debug(gc, ergo, conc)("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 {
-    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));
+    log_debug(gc, ergo, conc)("Do not request concurrent cycle initiation (concurrent cycle already in progress). GC cause: %s", GCCause::to_string(gc_cause));
     return false;
   }
 }
 
 void

@@ -1631,22 +1543,17 @@
 
       collector_state()->set_during_initial_mark_pause(true);
       // We do not allow mixed GCs during marking.
       if (!collector_state()->gcs_are_young()) {
         collector_state()->set_gcs_are_young(true);
-        ergo_verbose0(ErgoMixedGCs,
-                      "end mixed GCs",
-                      ergo_format_reason("concurrent cycle is about to start"));
+        log_debug(gc, ergo)("End mixed GCs (concurrent cycle is about to start");
       }
 
       // 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"));
+      log_debug(gc, ergo, conc)("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

@@ -1656,13 +1563,11 @@
       // 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"));
+      log_debug(gc, ergo, conc)("Do not initiate concurrent cycle (concurrent cycle already in progress)");
     }
   }
 }
 
 class ParKnownGarbageHRClosure: public HeapRegionClosure {

@@ -1943,42 +1848,26 @@
 
 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"));
+    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) {
-    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);
+    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;
   }
 
-  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);
+  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

@@ -2030,16 +1919,11 @@
   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"),
+  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()) {

@@ -2072,19 +1956,12 @@
 
   _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);
+  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);
 

@@ -2110,15 +1987,11 @@
 
     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"),
+        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;
       }
 
 

@@ -2129,21 +2002,13 @@
       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);
+        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) {

@@ -2151,19 +2016,13 @@
           // 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);
+            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.

@@ -2171,15 +2030,12 @@
         }
       } 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"),
+
+          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;
         }
       }
 

@@ -2191,44 +2047,29 @@
       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"));
+      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.
-      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);
+      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();
 
-  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);
+  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);
 }
 

@@ -2283,38 +2124,38 @@
 }
 
 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();
-  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();
+  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();
 
-  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);

@@ -2325,13 +2166,13 @@
     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) {

@@ -2344,14 +2185,14 @@
   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());
-    gclog_or_tty->print_cr("                     [std. dev = %8.2f ms, max = %8.2f ms]",
+    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 >