8336742: Shenandoah: Add more verbose logging/stats for mark termination attempts

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

@@ -205,9 +205,7 @@ void ShenandoahConcurrentMark::concurrent_mark() {
 
   ShenandoahSATBMarkQueueSet& qset = ShenandoahBarrierSet::satb_mark_queue_set();
   ShenandoahFlushSATBHandshakeClosure flush_satb(qset);
-  double handshake_total_time = 0;
-  uint flushes;
-  for (flushes = 0; flushes < ShenandoahMaxSATBBufferFlushes; flushes++) {
+  for (uint flushes = 0; flushes < ShenandoahMaxSATBBufferFlushes; flushes++) {
     TaskTerminator terminator(nworkers, task_queues());
     ShenandoahConcurrentMarkingTask<NON_GEN> task(this, &terminator);
     workers->run_task(&task);
@@ -218,20 +216,17 @@ void ShenandoahConcurrentMark::concurrent_mark() {
     }
 
     size_t before = qset.completed_buffers_num();
-    double handshake_start_time = os::elapsedTime();
-    Handshake::execute(&flush_satb);
-    handshake_total_time += os::elapsedTime() - handshake_start_time;
+    {
+      ShenandoahTimingsTracker t(ShenandoahPhaseTimings::conc_mark_satb_flush_rendezvous, true);
+      Handshake::execute(&flush_satb);
+    }
     size_t after = qset.completed_buffers_num();
 
     if (before == after) {
       // No more retries needed, break out.
       break;
     }
   }
-  ShenandoahPhaseTimings* const timings = heap->phase_timings();
-  timings->record_phase_time(ShenandoahPhaseTimings::conc_mark_satb_flush_rendezvous, handshake_total_time);
-
-  log_info(gc, phases) ("Total SATB flush attempts : %d", (flushes + 1));
   assert(task_queues()->is_empty() || heap->cancelled_gc(), "Should be empty when not cancelled");
 }
 

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

@@ -137,17 +137,21 @@ bool ShenandoahPhaseTimings::is_root_work_phase(Phase phase) {
   }
 }
 
-void ShenandoahPhaseTimings::set_cycle_data(Phase phase, double time) {
+void ShenandoahPhaseTimings::set_cycle_data(Phase phase, double time, bool should_aggregate_cycles) {
+  if (should_aggregate_cycles) {
+    _cycle_data[phase] = _cycle_data[phase] <= 0 ? time :  _cycle_data[phase] + time;
+  } else {
 #ifdef ASSERT
-  double d = _cycle_data[phase];
-  assert(d == uninitialized(), "Should not be set yet: %s, current value: %lf", phase_name(phase), d);
+    double d = _cycle_data[phase];
+    assert(d == uninitialized(), "Should not be set yet: %s, current value: %lf", phase_name(phase), d);
 #endif
-  _cycle_data[phase] = time;
+    _cycle_data[phase] = time;
+  }
 }
 
-void ShenandoahPhaseTimings::record_phase_time(Phase phase, double time) {
+void ShenandoahPhaseTimings::record_phase_time(Phase phase, double time, bool should_aggregate_cycles) {
   if (!_policy->is_at_shutdown()) {
-    set_cycle_data(phase, time);
+    set_cycle_data(phase, time, should_aggregate_cycles);
   }
 }
 

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

@@ -57,7 +57,7 @@ class outputStream;
   f(conc_mark_roots,                                "Concurrent Mark Roots ")          \
   SHENANDOAH_PAR_PHASE_DO(conc_mark_roots,          "  CMR: ", f)                      \
   f(conc_mark,                                      "Concurrent Marking")              \
-  f(conc_mark_satb_flush_rendezvous,                "  SATB Flush Rendezvous") \
+  f(conc_mark_satb_flush_rendezvous,                "  SATB Flush Rendezvous")         \
                                                                                        \
   f(final_mark_gross,                               "Pause Final Mark (G)")            \
   f(final_mark,                                     "Pause Final Mark (N)")            \
@@ -217,13 +217,13 @@ class ShenandoahPhaseTimings : public CHeapObj<mtGC> {
   ShenandoahWorkerData* worker_data(Phase phase, ParPhase par_phase);
   Phase worker_par_phase(Phase phase, ParPhase par_phase);
 
-  void set_cycle_data(Phase phase, double time);
+  void set_cycle_data(Phase phase, double time, bool should_aggregate_cycles=false);
   static double uninitialized() { return -1; }
 
 public:
   ShenandoahPhaseTimings(uint max_workers);
 
-  void record_phase_time(Phase phase, double time);
+  void record_phase_time(Phase phase, double time, bool should_aggregate_cycles=false);
 
   void record_workers_start(Phase phase);
   void record_workers_end(Phase phase);

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

@@ -111,17 +111,20 @@ ShenandoahConcurrentPhase::~ShenandoahConcurrentPhase() {
   _timer->register_gc_concurrent_end();
 }
 
-ShenandoahTimingsTracker::ShenandoahTimingsTracker(ShenandoahPhaseTimings::Phase phase) :
+ShenandoahTimingsTracker::ShenandoahTimingsTracker(ShenandoahPhaseTimings::Phase phase, bool should_aggregate_cycles) :
   _timings(ShenandoahHeap::heap()->phase_timings()), _phase(phase) {
   assert(Thread::current()->is_VM_thread() || Thread::current()->is_ConcurrentGC_thread(),
           "Must be set by these threads");
   _parent_phase = _current_phase;
   _current_phase = phase;
   _start = os::elapsedTime();
+  _should_aggregate_cycles = should_aggregate_cycles;
 }
 
 ShenandoahTimingsTracker::~ShenandoahTimingsTracker() {
-  _timings->record_phase_time(_phase, os::elapsedTime() - _start);
+  const double end_time = os::elapsedTime();
+  const double phase_elapsed_time = end_time - _start;
+  _timings->record_phase_time(_phase, phase_elapsed_time, _should_aggregate_cycles);
   _current_phase = _parent_phase;
 }
 

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

@@ -66,9 +66,10 @@ class ShenandoahTimingsTracker : public StackObj {
   const ShenandoahPhaseTimings::Phase   _phase;
   ShenandoahPhaseTimings::Phase         _parent_phase;
   double _start;
+  bool _should_aggregate_cycles;
 
 public:
-  ShenandoahTimingsTracker(ShenandoahPhaseTimings::Phase phase);
+  ShenandoahTimingsTracker(ShenandoahPhaseTimings::Phase phase, bool should_aggregate_cycles=false);
   ~ShenandoahTimingsTracker();
 
   static ShenandoahPhaseTimings::Phase current_phase() { return _current_phase; }