src/hotspot/share/gc/g1/g1HeapSizingPolicy.cpp

rev 59304 : [mq]: 8245088-provide-log-information-about-heap-expansion

@@ -48,12 +48,12 @@
   _ratio_over_threshold_count = 0;
   _ratio_over_threshold_sum = 0.0;
   _pauses_since_start = 0;
 }
 
-double G1HeapSizingPolicy::scale_with_heap(double pause_time_ratio) {
-  double threshold = pause_time_ratio;
+double G1HeapSizingPolicy::scale_with_heap(double upper_threshold) {
+  double threshold = upper_threshold;
   // If the heap is at less than half its maximum size, scale the threshold down,
   // to a limit of 1%. Thus the smaller the heap is, the more likely it is to expand,
   // though the scaling code will likely keep the increase small.
   if (_g1h->capacity() <= _g1h->max_capacity() / 2) {
     threshold *= (double)_g1h->capacity() / (double)(_g1h->max_capacity() / 2);

@@ -61,37 +61,63 @@
   }
 
   return threshold;
 }
 
+static void log(const char* prefix,
+                double short_term_pause_time_ratio,
+                double long_term_pause_time_ratio,
+                double threshold,
+                double pause_time_ratio,
+                bool fully_expanded,
+                size_t resize_bytes) {
+
+  log_debug(gc, ergo, heap)("%s "
+                            "short term pause time ratio %1.2f%% long term pause time ratio %1.2f%% "
+                            "threshold %1.2f%% pause time ratio %1.2f%% fully expanded %d "
+                            "resize by " SIZE_FORMAT "B",
+                            prefix,
+                            short_term_pause_time_ratio * 100.0,
+                            long_term_pause_time_ratio * 100.0,
+                            threshold * 100.0,
+                            pause_time_ratio * 100.0,
+                            fully_expanded,
+                            resize_bytes);
+}
+
 size_t G1HeapSizingPolicy::expansion_amount() {
   assert(GCTimeRatio > 0, "must be");
 
   double long_term_pause_time_ratio = _analytics->long_term_pause_time_ratio();
   double short_term_pause_time_ratio = _analytics->short_term_pause_time_ratio();
+  const double pause_time_ratio = 1.0 / (1.0 + GCTimeRatio);
+  double threshold = scale_with_heap(pause_time_ratio);
+
   size_t expand_bytes = 0;
 
   if (_g1h->capacity() == _g1h->max_capacity()) {
-    log_trace(gc, ergo, heap)("Can not expand (heap already fully expanded) "
-                              "long term GC overhead: %1.2f%%  committed: " SIZE_FORMAT "B",
-                              long_term_pause_time_ratio * 100.0, _g1h->capacity());
-
+    log("Heap expansion: Can not expand (heap already fully expanded)",
+        short_term_pause_time_ratio, long_term_pause_time_ratio, threshold, pause_time_ratio, true, 0);
     clear_ratio_check_data();
     return expand_bytes;
   }
 
-  const double pause_time_ratio = 1.0 / (1.0 + GCTimeRatio);
-
-  double threshold = scale_with_heap(pause_time_ratio);
-
   // If the last GC time ratio is over the threshold, increment the count of
   // times it has been exceeded, and add this ratio to the sum of exceeded
   // ratios.
   if (short_term_pause_time_ratio > threshold) {
     _ratio_over_threshold_count++;
     _ratio_over_threshold_sum += short_term_pause_time_ratio;
   }
+
+  log_trace(gc, ergo, heap)("Heap expansion triggers: pauses since start: %u "
+                            "num prev pauses for heuristics: %u "
+                            "ratio over threshold count: %u",
+                            _pauses_since_start,
+                            _num_prev_pauses_for_heuristics,
+                            _ratio_over_threshold_count);
+
   // Check if we've had enough GC time ratio checks that were over the
   // threshold to trigger an expansion. We'll also expand if we've
   // reached the end of the history buffer and the average of all entries
   // is still over the threshold. This indicates a smaller number of GCs were
   // long enough to make the average exceed the threshold.

@@ -144,22 +170,15 @@
         scale_factor = 1 + ((ratio_delta - StartScaleUpAt) / ScaleUpRange);
         scale_factor = MIN2(scale_factor, MaxScaleUpFactor);
       }
     }
 
-    log_debug(gc, ergo, heap)("Attempt heap expansion (recent GC overhead higher than threshold after GC) "
-                              "long term GC overhead: %1.2f%% threshold: %1.2f%% uncommitted: " SIZE_FORMAT "B "
-                              "base expansion amount and scale: " SIZE_FORMAT "B (%1.2f%%)",
-                              long_term_pause_time_ratio * 100.0, threshold * 100.0,
-                              uncommitted_bytes, expand_bytes, scale_factor * 100.0);
-
     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.
-    expand_bytes = MAX2(expand_bytes, min_expand_bytes);
-    expand_bytes = MIN2(expand_bytes, uncommitted_bytes);
+    expand_bytes = clamp(min_expand_bytes, expand_bytes, uncommitted_bytes);
 
     clear_ratio_check_data();
   } else {
     // An expansion was not triggered. If we've started counting, increment
     // the number of checks we've made in the current window.  If we've

@@ -171,7 +190,10 @@
         clear_ratio_check_data();
       }
     }
   }
 
+  log("Heap expansion:", short_term_pause_time_ratio, long_term_pause_time_ratio,
+      threshold, pause_time_ratio, false, expand_bytes);
+
   return expand_bytes;
 }