8359348: G1: Improve cpu usage measurements for heap sizing

Reviewed-by: tschatzl, ayang, manc

Author: Ivan Walulya

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

@@ -28,6 +28,7 @@
 #include "gc/shared/gc_globals.hpp"
 #include "runtime/globals.hpp"
 #include "runtime/os.hpp"
+#include "services/cpuTimeUsage.hpp"
 #include "utilities/debug.hpp"
 #include "utilities/globalDefinitions.hpp"
 #include "utilities/numberSeq.hpp"
@@ -73,6 +74,8 @@ G1Analytics::G1Analytics(const G1Predictions* predictor) :
     _concurrent_mark_cleanup_times_ms(NumPrevPausesForHeuristics),
     _alloc_rate_ms_seq(TruncatedSeqLength),
     _prev_collection_pause_end_ms(0.0),
+    _gc_cpu_time_at_pause_end_ms(),
+    _concurrent_gc_cpu_time_ms(),
     _concurrent_refine_rate_ms_seq(TruncatedSeqLength),
     _dirtied_cards_rate_ms_seq(TruncatedSeqLength),
     _dirtied_cards_in_thread_buffers_seq(TruncatedSeqLength),
@@ -88,8 +91,8 @@ G1Analytics::G1Analytics(const G1Predictions* predictor) :
     _young_other_cost_per_region_ms_seq(TruncatedSeqLength),
     _non_young_other_cost_per_region_ms_seq(TruncatedSeqLength),
     _recent_prev_end_times_for_all_gcs_sec(NumPrevPausesForHeuristics),
-    _long_term_pause_time_ratio(0.0),
-    _short_term_pause_time_ratio(0.0) {
+    _long_term_gc_time_ratio(0.0),
+    _short_term_gc_time_ratio(0.0) {
 
   // Seed sequences with initial values.
   _recent_prev_end_times_for_all_gcs_sec.add(os::elapsedTime());
@@ -149,6 +152,10 @@ int G1Analytics::num_alloc_rate_ms() const {
   return _alloc_rate_ms_seq.num();
 }
 
+double G1Analytics::gc_cpu_time_ms() const {
+  return (double)CPUTimeUsage::GC::gc_threads() / NANOSECS_PER_MILLISEC;
+}
+
 void G1Analytics::report_concurrent_mark_remark_times_ms(double ms) {
   _concurrent_mark_remark_times_ms.add(ms);
 }
@@ -157,15 +164,27 @@ void G1Analytics::report_alloc_rate_ms(double alloc_rate) {
   _alloc_rate_ms_seq.add(alloc_rate);
 }
 
-void G1Analytics::compute_pause_time_ratios(double end_time_sec, double pause_time_ms) {
+void G1Analytics::update_gc_time_ratios(double end_time_sec, double pause_time_ms) {
+  // This estimates the wall-clock time "lost" by application mutator threads due to concurrent GC
+  // activity. We do not account for contention on other shared resources such as memory bandwidth and
+  // caches, therefore underestimate the impact of the concurrent GC activity on mutator threads.
+  uint num_cpus = (uint)os::active_processor_count();
+  double concurrent_gc_impact_time = _concurrent_gc_cpu_time_ms / num_cpus;
+
+  double gc_time_ms = pause_time_ms + concurrent_gc_impact_time;
+
   double long_interval_ms = (end_time_sec - oldest_known_gc_end_time_sec()) * 1000.0;
-  double gc_pause_time_ms = _recent_gc_times_ms.sum() - _recent_gc_times_ms.oldest() + pause_time_ms;
-  _long_term_pause_time_ratio = gc_pause_time_ms / long_interval_ms;
-  _long_term_pause_time_ratio = clamp(_long_term_pause_time_ratio, 0.0, 1.0);
+  double long_term_gc_time_ms = _recent_gc_times_ms.sum() - _recent_gc_times_ms.oldest() + gc_time_ms;
+
+  _long_term_gc_time_ratio = long_term_gc_time_ms / long_interval_ms;
+  _long_term_gc_time_ratio = clamp(_long_term_gc_time_ratio, 0.0, 1.0);
 
   double short_interval_ms = (end_time_sec - most_recent_gc_end_time_sec()) * 1000.0;
-  _short_term_pause_time_ratio = pause_time_ms / short_interval_ms;
-  _short_term_pause_time_ratio = clamp(_short_term_pause_time_ratio, 0.0, 1.0);
+
+  _short_term_gc_time_ratio = gc_time_ms / short_interval_ms;
+  _short_term_gc_time_ratio = clamp(_short_term_gc_time_ratio, 0.0, 1.0);
+
+  update_recent_gc_times(end_time_sec, gc_time_ms);
 }
 
 void G1Analytics::report_concurrent_refine_rate_ms(double cards_per_ms) {
@@ -305,8 +324,8 @@ double G1Analytics::most_recent_gc_end_time_sec() const {
 }
 
 void G1Analytics::update_recent_gc_times(double end_time_sec,
-                                         double pause_time_ms) {
-  _recent_gc_times_ms.add(pause_time_ms);
+                                         double gc_time_ms) {
+  _recent_gc_times_ms.add(gc_time_ms);
   _recent_prev_end_times_for_all_gcs_sec.add(end_time_sec);
 }
 

src/hotspot/share/gc/g1/g1Analytics.hpp

@@ -44,7 +44,15 @@ class G1Analytics: public CHeapObj<mtGC> {
   TruncatedSeq _concurrent_mark_cleanup_times_ms;
 
   TruncatedSeq _alloc_rate_ms_seq;
-  double        _prev_collection_pause_end_ms;
+  double       _prev_collection_pause_end_ms;
+
+  // Records the total GC CPU time (in ms) at the end of the last GC pause.
+  // Used as a baseline to calculate CPU time spent in GC threads between pauses.
+  double _gc_cpu_time_at_pause_end_ms;
+
+  // CPU time (ms) spent by GC threads between the end of the last pause
+  // and the start of the current pause; calculated at start of a GC pause.
+  double _concurrent_gc_cpu_time_ms;
 
   TruncatedSeq _concurrent_refine_rate_ms_seq;
   TruncatedSeq _dirtied_cards_rate_ms_seq;
@@ -75,10 +83,10 @@ class G1Analytics: public CHeapObj<mtGC> {
   // Statistics kept per GC stoppage, pause or full.
   TruncatedSeq _recent_prev_end_times_for_all_gcs_sec;
 
-  // Cached values for long and short term pause time ratios. See
-  // compute_pause_time_ratios() for how they are computed.
-  double _long_term_pause_time_ratio;
-  double _short_term_pause_time_ratio;
+  // Cached values for long and short term gc time ratios. See
+  // update_gc_time_ratios() for how they are computed.
+  double _long_term_gc_time_ratio;
+  double _short_term_gc_time_ratio;
 
   double predict_in_unit_interval(TruncatedSeq const* seq) const;
   size_t predict_size(TruncatedSeq const* seq) const;
@@ -102,12 +110,12 @@ class G1Analytics: public CHeapObj<mtGC> {
     return _prev_collection_pause_end_ms;
   }
 
-  double long_term_pause_time_ratio() const {
-    return _long_term_pause_time_ratio;
+  double long_term_gc_time_ratio() const {
+    return _long_term_gc_time_ratio;
   }
 
-  double short_term_pause_time_ratio() const {
-    return _short_term_pause_time_ratio;
+  double short_term_gc_time_ratio() const {
+    return _short_term_gc_time_ratio;
   }
 
   static constexpr uint max_num_of_recorded_pause_times() {
@@ -122,6 +130,20 @@ class G1Analytics: public CHeapObj<mtGC> {
     _prev_collection_pause_end_ms = ms;
   }
 
+  void set_gc_cpu_time_at_pause_end_ms(double ms) {
+    _gc_cpu_time_at_pause_end_ms = ms;
+  }
+
+  double gc_cpu_time_at_pause_end_ms() const {
+    return _gc_cpu_time_at_pause_end_ms;
+  }
+
+  void set_concurrent_gc_cpu_time_ms(double ms) {
+    _concurrent_gc_cpu_time_ms = ms;
+  }
+
+  double gc_cpu_time_ms() const;
+
   void report_concurrent_mark_remark_times_ms(double ms);
   void report_concurrent_mark_cleanup_times_ms(double ms);
   void report_alloc_rate_ms(double alloc_rate);
@@ -173,8 +195,8 @@ class G1Analytics: public CHeapObj<mtGC> {
   size_t predict_pending_cards(bool for_young_only_phase) const;
 
   // Add a new GC of the given duration and end time to the record.
-  void update_recent_gc_times(double end_time_sec, double elapsed_ms);
-  void compute_pause_time_ratios(double end_time_sec, double pause_time_ms);
+  void update_recent_gc_times(double end_time_sec, double gc_time_ms);
+  void update_gc_time_ratios(double end_time_sec, double pause_time_ms);
 };
 
 #endif // SHARE_GC_G1_G1ANALYTICS_HPP

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

@@ -217,8 +217,8 @@ size_t G1HeapSizingPolicy::young_collection_resize_amount(bool& expand, size_t a
   assert(GCTimeRatio > 0, "must be");
   expand = false;
 
-  const double long_term_gc_cpu_usage = _analytics->long_term_pause_time_ratio();
-  const double short_term_gc_cpu_usage = _analytics->short_term_pause_time_ratio();
+  const double long_term_gc_cpu_usage = _analytics->long_term_gc_time_ratio();
+  const double short_term_gc_cpu_usage = _analytics->short_term_gc_time_ratio();
 
   double gc_cpu_usage_target = 1.0 / (1.0 + GCTimeRatio);
   gc_cpu_usage_target = scale_with_heap(gc_cpu_usage_target);

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

@@ -664,6 +664,12 @@ bool G1Policy::should_retain_evac_failed_region(uint index) const {
 void G1Policy::record_pause_start_time() {
   Ticks now = Ticks::now();
   _cur_pause_start_sec = now.seconds();
+
+  double prev_gc_cpu_pause_end_ms = _analytics->gc_cpu_time_at_pause_end_ms();
+  double cur_gc_cpu_time_ms = _analytics->gc_cpu_time_ms();
+
+  double concurrent_gc_cpu_time_ms = cur_gc_cpu_time_ms - prev_gc_cpu_pause_end_ms;
+  _analytics->set_concurrent_gc_cpu_time_ms(concurrent_gc_cpu_time_ms);
 }
 
 void G1Policy::record_young_collection_start() {
@@ -1346,8 +1352,7 @@ void G1Policy::update_gc_pause_time_ratios(G1GCPauseType gc_type, double start_t
   double pause_time_sec = end_time_sec - start_time_sec;
   double pause_time_ms = pause_time_sec * 1000.0;
 
-  _analytics->compute_pause_time_ratios(end_time_sec, pause_time_ms);
-  _analytics->update_recent_gc_times(end_time_sec, pause_time_ms);
+  _analytics->update_gc_time_ratios(end_time_sec, pause_time_ms);
 
   if (gc_type == G1GCPauseType::Cleanup || gc_type == G1GCPauseType::Remark) {
     _analytics->append_prev_collection_pause_end_ms(pause_time_ms);
@@ -1370,6 +1375,9 @@ void G1Policy::record_pause(G1GCPauseType gc_type,
   }
 
   update_time_to_mixed_tracking(gc_type, start, end);
+
+  double elapsed_gc_cpu_time = _analytics->gc_cpu_time_ms();
+  _analytics->set_gc_cpu_time_at_pause_end_ms(elapsed_gc_cpu_time);
 }
 
 void G1Policy::update_time_to_mixed_tracking(G1GCPauseType gc_type,

test/hotspot/gtest/gc/g1/test_g1Analytics.cpp

@@ -29,6 +29,6 @@
 TEST_VM(G1Analytics, is_initialized) {
   G1Predictions p(0.888888); // the actual sigma value doesn't matter
   G1Analytics a(&p);
-  ASSERT_EQ(a.long_term_pause_time_ratio(), 0.0);
-  ASSERT_EQ(a.short_term_pause_time_ratio(), 0.0);
+  ASSERT_EQ(a.long_term_gc_time_ratio(), 0.0);
+  ASSERT_EQ(a.short_term_gc_time_ratio(), 0.0);
 }