8239786: Shenandoah: print per-cycle statistics

Reviewed-by: rkennke

Author: shipilev

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

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2013, 2019, Red Hat, Inc. All rights reserved.
+ * Copyright (c) 2013, 2020, Red Hat, Inc. All rights reserved.
  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
  *
  * This code is free software; you can redistribute it and/or modify it
@@ -242,6 +242,22 @@ void ShenandoahControlThread::run_service() {
         heuristics->clear_metaspace_oom();
       }
 
+      // Commit worker statistics to cycle data
+      heap->phase_timings()->flush_par_workers_to_cycle();
+
+      // Print GC stats for current cycle
+      {
+        LogTarget(Info, gc, stats) lt;
+        if (lt.is_enabled()) {
+          ResourceMark rm;
+          LogStream ls(lt);
+          heap->phase_timings()->print_cycle_on(&ls);
+        }
+      }
+
+      // Commit statistics to globals
+      heap->phase_timings()->flush_cycle_to_global();
+
       // Print Metaspace change following GC (if logging is enabled).
       MetaspaceUtils::print_metaspace_change(meta_sizes);
 
@@ -265,6 +281,7 @@ void ShenandoahControlThread::run_service() {
                              current :
                              current - (ShenandoahUncommitDelay / 1000.0);
       service_uncommit(shrink_before);
+      heap->phase_timings()->flush_cycle_to_global();
       last_shrink_time = current;
     }
 

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

@@ -1190,7 +1190,7 @@ void ShenandoahHeap::print_tracing_info() const {
     ResourceMark rm;
     LogStream ls(lt);
 
-    phase_timings()->print_on(&ls);
+    phase_timings()->print_global_on(&ls);
 
     ls.cr();
     ls.cr();

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

@@ -30,8 +30,14 @@
 #include "gc/shenandoah/shenandoahHeap.hpp"
 #include "gc/shenandoah/shenandoahHeuristics.hpp"
 #include "gc/shenandoah/shenandoahUtils.hpp"
+#include "runtime/orderAccess.hpp"
 #include "utilities/ostream.hpp"
 
+#define SHENANDOAH_PHASE_NAME_FORMAT "%-28s"
+#define SHENANDOAH_S_TIME_FORMAT "%8.3lf"
+#define SHENANDOAH_US_TIME_FORMAT "%8.0lf"
+#define SHENANDOAH_US_WORKER_TIME_FORMAT "%3.0lf"
+
 #define GC_PHASE_DECLARE_NAME(type, title) \
   title,
 
@@ -42,62 +48,155 @@ const char* ShenandoahPhaseTimings::_phase_names[] = {
 #undef GC_PHASE_DECLARE_NAME
 
 ShenandoahPhaseTimings::ShenandoahPhaseTimings() {
-  uint max_workers = MAX2(ConcGCThreads, ParallelGCThreads);
-  assert(max_workers > 0, "Must have some GC threads");
+  _max_workers = MAX2(ConcGCThreads, ParallelGCThreads);
+  assert(_max_workers > 0, "Must have some GC threads");
 
-#define GC_PAR_PHASE_DECLARE_WORKER_DATA(type, title) \
-  _gc_par_phases[ShenandoahPhaseTimings::type] = new WorkerDataArray<double>(title, max_workers);
-  // Root scanning phases
-  SHENANDOAH_GC_PAR_PHASE_DO(,, GC_PAR_PHASE_DECLARE_WORKER_DATA)
-#undef GC_PAR_PHASE_DECLARE_WORKER_DATA
+  // Initialize everything to sane defaults
+  for (uint i = 0; i < _num_phases; i++) {
+#define SHENANDOAH_WORKER_DATA_NULL(type, title) \
+    _worker_data[i] = NULL;
+    SHENANDOAH_GC_PAR_PHASE_DO(,, SHENANDOAH_WORKER_DATA_NULL)
+#undef SHENANDOAH_WORKER_DATA_NULL
+    _cycle_data[i] = 0;
+  }
+
+  // Then punch in the worker-related data.
+  // Every worker phase get a bunch of internal objects, except
+  // the very first slot, which is "<total>" and is not populated.
+  for (uint i = 0; i < _num_phases; i++) {
+    if (is_worker_phase(Phase(i))) {
+      int c = 0;
+#define SHENANDOAH_WORKER_DATA_INIT(type, title) \
+      if (c++ != 0) _worker_data[i + c] = new ShenandoahWorkerData(title, _max_workers);
+      SHENANDOAH_GC_PAR_PHASE_DO(,, SHENANDOAH_WORKER_DATA_INIT)
+#undef SHENANDOAH_WORKER_DATA_INIT
+    }
+  }
 
   _policy = ShenandoahHeap::heap()->shenandoah_policy();
   assert(_policy != NULL, "Can not be NULL");
+
+  _current_worker_phase = _invalid_phase;
+}
+
+ShenandoahPhaseTimings::Phase ShenandoahPhaseTimings::worker_par_phase(Phase phase, GCParPhases par_phase) {
+  assert(is_worker_phase(phase), "Phase should accept worker phase times: %s", phase_name(phase));
+  Phase p = Phase(phase + 1 + par_phase);
+  assert(p >= 0 && p < _num_phases, "Out of bound for: %s", phase_name(phase));
+  return p;
+}
+
+ShenandoahWorkerData* ShenandoahPhaseTimings::worker_data(Phase phase, GCParPhases par_phase) {
+  Phase p = worker_par_phase(phase, par_phase);
+  ShenandoahWorkerData* wd = _worker_data[p];
+  assert(wd != NULL, "Counter initialized: %s", phase_name(p));
+  return wd;
+}
+
+bool ShenandoahPhaseTimings::is_worker_phase(Phase phase) {
+  assert(phase >= 0 && phase < _num_phases, "Out of bounds");
+  switch (phase) {
+    case init_evac:
+    case scan_roots:
+    case update_roots:
+    case final_update_refs_roots:
+    case full_gc_scan_roots:
+    case full_gc_update_roots:
+    case full_gc_adjust_roots:
+    case degen_gc_update_roots:
+    case full_gc_purge_class_unload:
+    case full_gc_purge_weak_par:
+    case purge_class_unload:
+    case purge_weak_par:
+    case heap_iteration_roots:
+      return true;
+    default:
+      return false;
+  }
+}
+
+void ShenandoahPhaseTimings::set_cycle_data(Phase phase, double time) {
+#ifdef ASSERT
+  double d = _cycle_data[phase];
+  assert(d == 0, "Should not be set yet: %s, current value: %lf", phase_name(phase), d);
+#endif
+  _cycle_data[phase] = time;
 }
 
 void ShenandoahPhaseTimings::record_phase_time(Phase phase, double time) {
   if (!_policy->is_at_shutdown()) {
-    _timing_data[phase].add(time);
+    set_cycle_data(phase, time);
   }
 }
 
 void ShenandoahPhaseTimings::record_workers_start(Phase phase) {
-  for (uint i = 0; i < GCParPhasesSentinel; i++) {
-    _gc_par_phases[i]->reset();
+  assert(is_worker_phase(phase), "Phase should accept worker phase times: %s", phase_name(phase));
+
+  assert(_current_worker_phase == _invalid_phase, "Should not be set yet: requested %s, existing %s",
+         phase_name(phase), phase_name(_current_worker_phase));
+  _current_worker_phase = phase;
+
+  for (uint i = 1; i < GCParPhasesSentinel; i++) {
+    worker_data(phase, GCParPhases(i))->reset();
   }
 }
 
 void ShenandoahPhaseTimings::record_workers_end(Phase phase) {
-  if (_policy->is_at_shutdown()) {
-    // Do not record the past-shutdown events
-    return;
+  assert(is_worker_phase(phase), "Phase should accept worker phase times: %s", phase_name(phase));
+  _current_worker_phase = _invalid_phase;
+}
+
+void ShenandoahPhaseTimings::flush_par_workers_to_cycle() {
+  for (uint pi = 0; pi < _num_phases; pi++) {
+    Phase phase = Phase(pi);
+    if (is_worker_phase(phase)) {
+      double s = 0;
+      for (uint i = 1; i < GCParPhasesSentinel; i++) {
+        double t = worker_data(phase, GCParPhases(i))->sum();
+        // add to each line in phase
+        set_cycle_data(Phase(phase + i + 1), t);
+        s += t;
+      }
+      // add to total for phase
+      set_cycle_data(Phase(phase + 1), s);
+    }
   }
+}
 
-  assert(phase == init_evac ||
-         phase == scan_roots ||
-         phase == update_roots ||
-         phase == final_update_refs_roots ||
-         phase == full_gc_scan_roots ||
-         phase == full_gc_update_roots ||
-         phase == full_gc_adjust_roots ||
-         phase == degen_gc_update_roots ||
-         phase == full_gc_purge_class_unload ||
-         phase == full_gc_purge_weak_par ||
-         phase == purge_class_unload ||
-         phase == purge_weak_par ||
-         phase == heap_iteration_roots,
-         "Phase should accept accept per-thread phase times: %s", phase_name(phase));
-
-  double s = 0;
-  for (uint i = 1; i < GCParPhasesSentinel; i++) {
-    double t = _gc_par_phases[i]->sum();
-    _timing_data[phase + i + 1].add(t); // add to each line in phase
-    s += t;
+void ShenandoahPhaseTimings::flush_cycle_to_global() {
+  for (uint i = 0; i < _num_phases; i++) {
+    _global_data[i].add(_cycle_data[i]);
+    _cycle_data[i] = 0;
   }
-  _timing_data[phase + 1].add(s); // add to total for phase
+  OrderAccess::fence();
 }
 
-void ShenandoahPhaseTimings::print_on(outputStream* out) const {
+void ShenandoahPhaseTimings::print_cycle_on(outputStream* out) const {
+  out->cr();
+  out->print_cr("All times are wall-clock times, except per-root-class counters, that are sum over");
+  out->print_cr("all workers. Dividing the <total> over the root stage time estimates parallelism.");
+  out->cr();
+  for (uint i = 0; i < _num_phases; i++) {
+    double v = _cycle_data[i] * 1000000.0;
+    if (v > 0) {
+      out->print(SHENANDOAH_PHASE_NAME_FORMAT " " SHENANDOAH_US_TIME_FORMAT " us", _phase_names[i], v);
+      if (_worker_data[i] != NULL) {
+        out->print(", workers (us): ");
+        for (size_t c = 0; c < _max_workers; c++) {
+          double tv = _worker_data[i]->get(c);
+          if (tv != ShenandoahWorkerData::uninitialized()) {
+            out->print(SHENANDOAH_US_WORKER_TIME_FORMAT ", ", tv * 1000000.0);
+          } else {
+            out->print("%3s, ", "---");
+          }
+        }
+      }
+      out->cr();
+    }
+  }
+}
+
+void ShenandoahPhaseTimings::print_global_on(outputStream* out) const {
   out->cr();
   out->print_cr("GC STATISTICS:");
   out->print_cr("  \"(G)\" (gross) pauses include VM time: time to notify and block threads, do the pre-");
@@ -111,37 +210,43 @@ void ShenandoahPhaseTimings::print_on(outputStream* out) const {
   out->cr();
 
   for (uint i = 0; i < _num_phases; i++) {
-    if (_timing_data[i].maximum() != 0) {
-      out->print_cr("%-27s = %8.2lf s (a = %8.0lf us) (n = " INT32_FORMAT_W(5) ") (lvls, us = %8.0lf, %8.0lf, %8.0lf, %8.0lf, %8.0lf)",
+    if (_global_data[i].maximum() != 0) {
+      out->print_cr(SHENANDOAH_PHASE_NAME_FORMAT " = " SHENANDOAH_S_TIME_FORMAT " s "
+                    "(a = " SHENANDOAH_US_TIME_FORMAT " us) "
+                    "(n = " INT32_FORMAT_W(5) ") (lvls, us = "
+                    SHENANDOAH_US_TIME_FORMAT ", "
+                    SHENANDOAH_US_TIME_FORMAT ", "
+                    SHENANDOAH_US_TIME_FORMAT ", "
+                    SHENANDOAH_US_TIME_FORMAT ", "
+                    SHENANDOAH_US_TIME_FORMAT ")",
                     _phase_names[i],
-                    _timing_data[i].sum(),
-                    _timing_data[i].avg() * 1000000.0,
-                    _timing_data[i].num(),
-                    _timing_data[i].percentile(0) * 1000000.0,
-                    _timing_data[i].percentile(25) * 1000000.0,
-                    _timing_data[i].percentile(50) * 1000000.0,
-                    _timing_data[i].percentile(75) * 1000000.0,
-                    _timing_data[i].maximum() * 1000000.0
+                    _global_data[i].sum(),
+                    _global_data[i].avg() * 1000000.0,
+                    _global_data[i].num(),
+                    _global_data[i].percentile(0) * 1000000.0,
+                    _global_data[i].percentile(25) * 1000000.0,
+                    _global_data[i].percentile(50) * 1000000.0,
+                    _global_data[i].percentile(75) * 1000000.0,
+                    _global_data[i].maximum() * 1000000.0
       );
     }
   }
 }
 
-void ShenandoahPhaseTimings::record_worker_time(ShenandoahPhaseTimings::GCParPhases phase, uint worker_id, double secs) {
-  _gc_par_phases[phase]->set(worker_id, secs);
-}
-
-ShenandoahWorkerTimingsTracker::ShenandoahWorkerTimingsTracker(ShenandoahPhaseTimings::GCParPhases phase, uint worker_id) :
-        _phase(phase), _timings(ShenandoahHeap::heap()->phase_timings()), _worker_id(worker_id) {
+ShenandoahWorkerTimingsTracker::ShenandoahWorkerTimingsTracker(ShenandoahPhaseTimings::GCParPhases par_phase, uint worker_id) :
+        _timings(ShenandoahHeap::heap()->phase_timings()), _phase(_timings->current_worker_phase()),
+        _par_phase(par_phase), _worker_id(worker_id) {
+  assert(_timings->worker_data(_phase, _par_phase)->get(_worker_id) == ShenandoahWorkerData::uninitialized(),
+         "Should not be set yet: %s", ShenandoahPhaseTimings::phase_name(_timings->worker_par_phase(_phase, _par_phase)));
   _start_time = os::elapsedTime();
 }
 
 ShenandoahWorkerTimingsTracker::~ShenandoahWorkerTimingsTracker() {
-  _timings->record_worker_time(_phase, _worker_id, os::elapsedTime() - _start_time);
+  _timings->worker_data(_phase, _par_phase)->set(_worker_id, os::elapsedTime() - _start_time);
 
   if (ShenandoahGCPhase::is_root_work_phase()) {
     ShenandoahPhaseTimings::Phase root_phase = ShenandoahGCPhase::current_phase();
-    ShenandoahPhaseTimings::Phase cur_phase = (ShenandoahPhaseTimings::Phase)((int)root_phase + (int)_phase + 1);
+    ShenandoahPhaseTimings::Phase cur_phase = _timings->worker_par_phase(root_phase, _par_phase);
     _event.commit(GCId::current(), _worker_id, ShenandoahPhaseTimings::phase_name(cur_phase));
   }
 }

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

@@ -1,5 +1,5 @@
 /*
- * Copyright (c) 2017, 2019, Red Hat, Inc. All rights reserved.
+ * Copyright (c) 2017, 2020, Red Hat, Inc. All rights reserved.
  * DO NOT ALTER OR REMOVE COPYRIGHT NOTICES OR THIS FILE HEADER.
  *
  * This code is free software; you can redistribute it and/or modify it
@@ -156,7 +156,11 @@ class outputStream;
   SHENANDOAH_GC_PAR_PHASE_DO(heap_iteration_roots_, "  HI: ", f)                       \
   // end
 
+typedef WorkerDataArray<double> ShenandoahWorkerData;
+
 class ShenandoahPhaseTimings : public CHeapObj<mtGC> {
+  friend class ShenandoahGCPhase;
+  friend class ShenandoahWorkerTimingsTracker;
 public:
 #define GC_PHASE_DECLARE_ENUM(type, title)   type,
 
@@ -174,39 +178,54 @@ class ShenandoahPhaseTimings : public CHeapObj<mtGC> {
 #undef GC_PHASE_DECLARE_ENUM
 
 private:
-  HdrSeq              _timing_data[_num_phases];
+  size_t              _max_workers;
+  double              _cycle_data[_num_phases];
+  HdrSeq              _global_data[_num_phases];
   static const char*  _phase_names[_num_phases];
 
-  WorkerDataArray<double>*   _gc_par_phases[ShenandoahPhaseTimings::GCParPhasesSentinel];
+  Phase                 _current_worker_phase;
+  ShenandoahWorkerData* _worker_data[_num_phases];
   ShenandoahCollectorPolicy* _policy;
 
+  static bool is_worker_phase(Phase phase);
+  Phase current_worker_phase() { return _current_worker_phase; }
+
+  ShenandoahWorkerData* worker_data(Phase phase, GCParPhases par_phase);
+  Phase worker_par_phase(Phase phase, GCParPhases par_phase);
+
+  void set_cycle_data(Phase phase, double time);
+
 public:
   ShenandoahPhaseTimings();
 
   void record_phase_time(Phase phase, double time);
-  void record_worker_time(GCParPhases phase, uint worker_id, double time);
 
   void record_workers_start(Phase phase);
   void record_workers_end(Phase phase);
 
+  void flush_par_workers_to_cycle();
+  void flush_cycle_to_global();
+
   static const char* phase_name(Phase phase) {
     assert(phase >= 0 && phase < _num_phases, "Out of bound");
     return _phase_names[phase];
   }
 
-  void print_on(outputStream* out) const;
+  void print_cycle_on(outputStream* out) const;
+  void print_global_on(outputStream* out) const;
 };
 
 class ShenandoahWorkerTimingsTracker : public StackObj {
 private:
-  ShenandoahPhaseTimings::GCParPhases const _phase;
-  ShenandoahPhaseTimings* const _timings;
+  ShenandoahPhaseTimings*             const _timings;
+  ShenandoahPhaseTimings::Phase       const _phase;
+  ShenandoahPhaseTimings::GCParPhases const _par_phase;
   uint const _worker_id;
 
   double _start_time;
   EventGCPhaseParallel _event;
 public:
-  ShenandoahWorkerTimingsTracker(ShenandoahPhaseTimings::GCParPhases phase, uint worker_id);
+  ShenandoahWorkerTimingsTracker(ShenandoahPhaseTimings::GCParPhases par_phase, uint worker_id);
   ~ShenandoahWorkerTimingsTracker();
 };