8249649: Shenandoah: provide per-cycle pacing stats

Reviewed-by: rkennke

src/hotspot/share/gc/shenandoah/shenandoahControlThread.cpp

@@ -252,6 +252,9 @@ void ShenandoahControlThread::run_service() {
 
       // Commit worker statistics to cycle data
       heap->phase_timings()->flush_par_workers_to_cycle();
+      if (ShenandoahPacing) {
+        heap->pacer()->flush_stats_to_cycle();
+      }
 
       // Print GC stats for current cycle
       {
@@ -260,6 +263,9 @@ void ShenandoahControlThread::run_service() {
           ResourceMark rm;
           LogStream ls(lt);
           heap->phase_timings()->print_cycle_on(&ls);
+          if (ShenandoahPacing) {
+            heap->pacer()->print_cycle_on(&ls);
+          }
         }
       }
 

src/hotspot/share/gc/shenandoah/shenandoahHeap.cpp

@@ -1231,13 +1231,6 @@ void ShenandoahHeap::print_tracing_info() const {
 
     ls.cr();
     ls.cr();
-
-    if (ShenandoahPacing) {
-      pacer()->print_on(&ls);
-    }
-
-    ls.cr();
-    ls.cr();
   }
 }
 

src/hotspot/share/gc/shenandoah/shenandoahNumberSeq.cpp

@@ -122,16 +122,20 @@ double HdrSeq::percentile(double level) const {
 
 BinaryMagnitudeSeq::BinaryMagnitudeSeq() {
   _mags = NEW_C_HEAP_ARRAY(size_t, BitsPerSize_t, mtInternal);
-  for (int c = 0; c < BitsPerSize_t; c++) {
-    _mags[c] = 0;
-  }
-  _sum = 0;
+  clear();
 }
 
 BinaryMagnitudeSeq::~BinaryMagnitudeSeq() {
   FREE_C_HEAP_ARRAY(size_t, _mags);
 }
 
+void BinaryMagnitudeSeq::clear() {
+  for (int c = 0; c < BitsPerSize_t; c++) {
+    _mags[c] = 0;
+  }
+  _sum = 0;
+}
+
 void BinaryMagnitudeSeq::add(size_t val) {
   Atomic::add(&_sum, val);
 

src/hotspot/share/gc/shenandoah/shenandoahNumberSeq.hpp

@@ -70,6 +70,7 @@ class BinaryMagnitudeSeq {
   size_t sum() const;
   int min_level() const;
   int max_level() const;
+  void clear();
 };
 
 #endif // SHARE_GC_SHENANDOAH_SHENANDOAHNUMBERSEQ_HPP

src/hotspot/share/gc/shenandoah/shenandoahPacer.cpp

@@ -27,6 +27,7 @@
 #include "gc/shenandoah/shenandoahFreeSet.hpp"
 #include "gc/shenandoah/shenandoahHeap.inline.hpp"
 #include "gc/shenandoah/shenandoahPacer.hpp"
+#include "gc/shenandoah/shenandoahPhaseTimings.hpp"
 #include "runtime/atomic.hpp"
 #include "runtime/mutexLocker.hpp"
 
@@ -272,7 +273,7 @@ void ShenandoahPacer::pace_for_alloc(size_t words) {
       //     Breaking out and allocating anyway, which may mean we outpace GC,
       //     and start Degenerated GC cycle.
       //  b) The budget had been replenished, which means our claim is satisfied.
-      _delays.add(total_ms);
+      ShenandoahThreadLocalData::add_paced_time(JavaThread::current(), end - start);
       break;
     }
   }
@@ -294,41 +295,48 @@ void ShenandoahPacer::notify_waiters() {
   }
 }
 
-void ShenandoahPacer::print_on(outputStream* out) const {
-  out->print_cr("ALLOCATION PACING:");
-  out->cr();
+void ShenandoahPacer::flush_stats_to_cycle() {
+  double sum = 0;
+  for (JavaThreadIteratorWithHandle jtiwh; JavaThread *t = jtiwh.next(); ) {
+    sum += ShenandoahThreadLocalData::paced_time(t);
+  }
+  ShenandoahHeap::heap()->phase_timings()->record_phase_time(ShenandoahPhaseTimings::pacing, sum);
+}
 
-  out->print_cr("Max pacing delay is set for " UINTX_FORMAT " ms.", ShenandoahPacingMaxDelay);
-  out->cr();
+void ShenandoahPacer::print_cycle_on(outputStream* out) {
+  MutexLocker lock(Threads_lock);
 
-  out->print_cr("Higher delay would prevent application outpacing the GC, but it will hide the GC latencies");
-  out->print_cr("from the STW pause times. Pacing affects the individual threads, and so it would also be");
-  out->print_cr("invisible to the usual profiling tools, but would add up to end-to-end application latency.");
-  out->print_cr("Raise max pacing delay with care.");
-  out->cr();
+  double now = os::elapsedTime();
+  double total = now - _last_time;
+  _last_time = now;
 
-  out->print_cr("Actual pacing delays histogram:");
   out->cr();
+  out->print_cr("Allocation pacing accrued:");
+
+  size_t threads_total = 0;
+  size_t threads_nz = 0;
+  double sum = 0;
+  for (JavaThreadIteratorWithHandle jtiwh; JavaThread *t = jtiwh.next(); ) {
+    double d = ShenandoahThreadLocalData::paced_time(t);
+    if (d > 0) {
+      threads_nz++;
+      sum += d;
+      out->print_cr("  %5.0f of %5.0f ms (%5.1f%%): %s",
+              d * 1000, total * 1000, d/total*100, t->name());
+    }
+    threads_total++;
+    ShenandoahThreadLocalData::reset_paced_time(t);
+  }
+  out->print_cr("  %5.0f of %5.0f ms (%5.1f%%): <total>",
+          sum * 1000, total * 1000, sum/total*100);
 
-  out->print_cr("%10s - %10s  %12s%12s", "From", "To", "Count", "Sum");
-
-  size_t total_count = 0;
-  size_t total_sum = 0;
-  for (int c = _delays.min_level(); c <= _delays.max_level(); c++) {
-    int l = (c == 0) ? 0 : 1 << (c - 1);
-    int r = 1 << c;
-    size_t count = _delays.level(c);
-    size_t sum   = count * (r - l) / 2;
-    total_count += count;
-    total_sum   += sum;
-
-    out->print_cr("%7d ms - %7d ms: " SIZE_FORMAT_W(12) SIZE_FORMAT_W(12) " ms", l, r, count, sum);
+  if (threads_total > 0) {
+    out->print_cr("  %5.0f of %5.0f ms (%5.1f%%): <average total>",
+            sum / threads_total * 1000, total * 1000, sum / threads_total / total * 100);
+  }
+  if (threads_nz > 0) {
+    out->print_cr("  %5.0f of %5.0f ms (%5.1f%%): <average non-zero>",
+            sum / threads_nz * 1000, total * 1000, sum / threads_nz / total * 100);
   }
-  out->print_cr("%23s: " SIZE_FORMAT_W(12) SIZE_FORMAT_W(12) " ms", "Total", total_count, total_sum);
-  out->cr();
-  out->print_cr("Pacing delays are measured from entering the pacing code till exiting it. Therefore,");
-  out->print_cr("observed pacing delays may be higher than the threshold when paced thread spent more");
-  out->print_cr("time in the pacing code. It usually happens when thread is de-scheduled while paced,");
-  out->print_cr("OS takes longer to unblock the thread, or JVM experiences an STW pause.");
   out->cr();
 }

src/hotspot/share/gc/shenandoah/shenandoahPacer.hpp

@@ -43,7 +43,7 @@ class ShenandoahHeap;
 class ShenandoahPacer : public CHeapObj<mtGC> {
 private:
   ShenandoahHeap* _heap;
-  BinaryMagnitudeSeq _delays;
+  double _last_time;
   TruncatedSeq* _progress_history;
   Monitor* _wait_monitor;
   ShenandoahSharedFlag _need_notify_waiters;
@@ -65,6 +65,7 @@ class ShenandoahPacer : public CHeapObj<mtGC> {
 public:
   ShenandoahPacer(ShenandoahHeap* heap) :
           _heap(heap),
+          _last_time(os::elapsedTime()),
           _progress_history(new TruncatedSeq(5)),
           _wait_monitor(new Monitor(Mutex::leaf, "_wait_monitor", true, Monitor::_safepoint_check_always)),
           _epoch(0),
@@ -94,7 +95,8 @@ class ShenandoahPacer : public CHeapObj<mtGC> {
 
   intptr_t epoch();
 
-  void print_on(outputStream* out) const;
+  void flush_stats_to_cycle();
+  void print_cycle_on(outputStream* out);
 
 private:
   inline void report_internal(size_t words);

src/hotspot/share/gc/shenandoah/shenandoahPhaseTimings.cpp

@@ -271,6 +271,17 @@ void ShenandoahPhaseTimings::print_global_on(outputStream* out) const {
   out->print_cr("  all workers. Dividing the <total> over the root stage time estimates parallelism.");
   out->cr();
 
+  out->print_cr("  Pacing delays are measured from entering the pacing code till exiting it. Therefore,");
+  out->print_cr("  observed pacing delays may be higher than the threshold when paced thread spent more");
+  out->print_cr("  time in the pacing code. It usually happens when thread is de-scheduled while paced,");
+  out->print_cr("  OS takes longer to unblock the thread, or JVM experiences an STW pause.");
+  out->cr();
+  out->print_cr("  Higher delay would prevent application outpacing the GC, but it will hide the GC latencies");
+  out->print_cr("  from the STW pause times. Pacing affects the individual threads, and so it would also be");
+  out->print_cr("  invisible to the usual profiling tools, but would add up to end-to-end application latency.");
+  out->print_cr("  Raise max pacing delay with care.");
+  out->cr();
+
   for (uint i = 0; i < _num_phases; i++) {
     if (_global_data[i].maximum() != 0) {
       out->print_cr(SHENANDOAH_PHASE_NAME_FORMAT " = " SHENANDOAH_S_TIME_FORMAT " s "

src/hotspot/share/gc/shenandoah/shenandoahPhaseTimings.hpp

@@ -163,6 +163,7 @@ class outputStream;
   f(full_gc_heapdump_post,                          "  Post Heap Dump")                \
                                                                                        \
   f(conc_uncommit,                                  "Concurrent Uncommit")             \
+  f(pacing,                                         "Pacing")                          \
                                                                                        \
   f(heap_iteration_roots,                           "Heap Iteration")                  \
   SHENANDOAH_PAR_PHASE_DO(heap_iteration_roots_,    "  HI: ", f)                       \

src/hotspot/share/gc/shenandoah/shenandoahThreadLocalData.hpp

@@ -49,6 +49,7 @@ class ShenandoahThreadLocalData {
   uint  _worker_id;
   bool _force_satb_flush;
   int  _disarmed_value;
+  double _paced_time;
 
   ShenandoahThreadLocalData() :
     _gc_state(0),
@@ -59,7 +60,8 @@ class ShenandoahThreadLocalData {
     _gclab_size(0),
     _worker_id(INVALID_WORKER_ID),
     _force_satb_flush(false),
-    _disarmed_value(0) {
+    _disarmed_value(0),
+    _paced_time(0) {
 
     // At least on x86_64, nmethod entry barrier encodes _disarmed_value offset
     // in instruction as disp8 immed
@@ -139,6 +141,18 @@ class ShenandoahThreadLocalData {
     data(thread)->_gclab_size = v;
   }
 
+  static void add_paced_time(Thread* thread, double v) {
+    data(thread)->_paced_time += v;
+  }
+
+  static double paced_time(Thread* thread) {
+    return data(thread)->_paced_time;
+  }
+
+  static void reset_paced_time(Thread* thread) {
+    data(thread)->_paced_time = 0;
+  }
+
   static void set_disarmed_value(Thread* thread, int value) {
     data(thread)->_disarmed_value = value;
   }