8068394: Trace event for concurrent GC phases

Add concurrent phase events for CMS and G1

Reviewed-by: brutisso, stefank

hotspot/src/share/vm/gc/cms/concurrentMarkSweepGeneration.cpp

@@ -2742,9 +2742,11 @@ CMSPhaseAccounting::CMSPhaseAccounting(CMSCollector *collector,
   _collector->resetYields();
   _collector->resetTimer();
   _collector->startTimer();
+  _collector->gc_timer_cm()->register_gc_concurrent_start(title);
 }
 
 CMSPhaseAccounting::~CMSPhaseAccounting() {
+  _collector->gc_timer_cm()->register_gc_concurrent_end();
   _collector->stopTimer();
   log_debug(gc)("Concurrent active time: %.3fms", TimeHelper::counter_to_seconds(_collector->timerTicks()));
   log_trace(gc)(" (CMS %s yielded %d times)", _title, _collector->yields());
@@ -5483,6 +5485,7 @@ void CMSCollector::reset_concurrent() {
     return;
   }
 
+  {
     // Clear the mark bitmap (no grey objects to start with)
     // for the next cycle.
     GCTraceCPUTime tcpu;
@@ -5523,6 +5526,7 @@ void CMSCollector::reset_concurrent() {
     // and count.
     size_policy()->reset_gc_overhead_limit_count();
     _collectorState = Idling;
+  }
 
   register_gc_end();
 }

hotspot/src/share/vm/gc/cms/concurrentMarkSweepGeneration.hpp

@@ -978,6 +978,8 @@ class CMSCollector: public CHeapObj<mtGC> {
   bool completed_initialization() { return _completed_initialization; }
 
   void print_eden_and_survivor_chunk_arrays();
+
+  ConcurrentGCTimer* gc_timer_cm() const { return _gc_timer_cm; }
 };
 
 class CMSExpansionCause : public AllStatic  {

hotspot/src/share/vm/gc/g1/concurrentMark.cpp

@@ -436,6 +436,7 @@ ConcurrentMark::ConcurrentMark(G1CollectedHeap* g1h, G1RegionToSpaceMapper* prev
   _has_aborted(false),
   _restart_for_overflow(false),
   _concurrent_marking_in_progress(false),
+  _concurrent_phase_started(false),
 
   // _verbose_level set below
 
@@ -1003,6 +1004,19 @@ void ConcurrentMark::scanRootRegions() {
   }
 }
 
+void ConcurrentMark::register_concurrent_phase_start(const char* title) {
+  assert(!_concurrent_phase_started, "Sanity");
+  _concurrent_phase_started = true;
+  _g1h->gc_timer_cm()->register_gc_concurrent_start(title);
+}
+
+void ConcurrentMark::register_concurrent_phase_end() {
+  if (_concurrent_phase_started) {
+    _concurrent_phase_started = false;
+    _g1h->gc_timer_cm()->register_gc_concurrent_end();
+  }
+}
+
 void ConcurrentMark::markFromRoots() {
   // we might be tempted to assert that:
   // assert(asynch == !SafepointSynchronize::is_at_safepoint(),
@@ -2609,6 +2623,10 @@ void ConcurrentMark::abort() {
                                  satb_mq_set.is_active() /* expected_active */);
 
   _g1h->trace_heap_after_concurrent_cycle();
+
+  // Close any open concurrent phase timing
+  register_concurrent_phase_end();
+
   _g1h->register_concurrent_cycle_end();
 }
 

hotspot/src/share/vm/gc/g1/concurrentMark.hpp

@@ -353,6 +353,9 @@ protected:
   // time of remark.
   volatile bool           _concurrent_marking_in_progress;
 
+  // Keep track of whether we have started concurrent phase or not.
+  bool                    _concurrent_phase_started;
+
   // All of these times are in ms
   NumberSeq _init_times;
   NumberSeq _remark_times;
@@ -516,6 +519,9 @@ public:
     _concurrent_marking_in_progress = false;
   }
 
+  void register_concurrent_phase_start(const char* title);
+  void register_concurrent_phase_end();
+
   void update_accum_task_vtime(int i, double vtime) {
     _accum_task_vtime[i] += vtime;
   }

hotspot/src/share/vm/gc/g1/concurrentMarkThread.cpp

@@ -90,6 +90,20 @@ void ConcurrentMarkThread::delay_to_keep_mmu(G1CollectorPolicy* g1_policy, bool
     os::sleep(this, sleep_time_ms, false);
   }
 }
+
+class GCConcPhaseTimer : StackObj {
+  ConcurrentMark* _cm;
+
+ public:
+  GCConcPhaseTimer(ConcurrentMark* cm, const char* title) : _cm(cm) {
+    _cm->register_concurrent_phase_start(title);
+  }
+
+  ~GCConcPhaseTimer() {
+    _cm->register_concurrent_phase_end();
+  }
+};
+
 void ConcurrentMarkThread::run() {
   initialize_in_thread();
   wait_for_universe_init();
@@ -127,6 +141,7 @@ void ConcurrentMarkThread::run_service() {
       // correctness issue.
 
       if (!cm()->has_aborted()) {
+        GCConcPhaseTimer(_cm, "Concurrent Root Region Scanning");
         _cm->scanRootRegions();
       }
 
@@ -140,6 +155,7 @@ void ConcurrentMarkThread::run_service() {
       do {
         iter++;
         if (!cm()->has_aborted()) {
+          GCConcPhaseTimer(_cm, "Concurrent Mark");
           _cm->markFromRoots();
         }
 
@@ -194,6 +210,7 @@ void ConcurrentMarkThread::run_service() {
         // reclaimed by cleanup.
 
         GCTraceConcTime(Info, gc) tt("Concurrent Cleanup");
+        GCConcPhaseTimer(_cm, "Concurrent Cleanup");
 
         // Now do the concurrent cleanup operation.
         _cm->completeCleanup();
@@ -250,6 +267,7 @@ void ConcurrentMarkThread::run_service() {
       // We may have aborted just before the remark. Do not bother clearing the
       // bitmap then, as it has been done during mark abort.
       if (!cm()->has_aborted()) {
+        GCConcPhaseTimer(_cm, "Concurrent Bitmap Clearing");
         _cm->clearNextBitmap();
       } else {
         assert(!G1VerifyBitmaps || _cm->nextMarkBitmapIsClear(), "Next mark bitmap must be clear");

hotspot/src/share/vm/gc/shared/gcTimer.cpp

@@ -69,13 +69,27 @@ void STWGCTimer::register_gc_end(const Ticks& time) {
 }
 
 void ConcurrentGCTimer::register_gc_pause_start(const char* name) {
+  assert(!_is_concurrent_phase_active, "A pause phase can't be started while a concurrent phase is active.");
   GCTimer::register_gc_pause_start(name);
 }
 
 void ConcurrentGCTimer::register_gc_pause_end() {
+  assert(!_is_concurrent_phase_active, "A pause phase can't be ended while a concurrent phase is active.");
   GCTimer::register_gc_pause_end();
 }
 
+void ConcurrentGCTimer::register_gc_concurrent_start(const char* name, const Ticks& time) {
+  assert(!_is_concurrent_phase_active, "A concurrent phase is already active.");
+  _time_partitions.report_gc_phase_start(name, time, GCPhase::ConcurrentPhaseType);
+  _is_concurrent_phase_active = true;
+}
+
+void ConcurrentGCTimer::register_gc_concurrent_end(const Ticks& time) {
+  assert(_is_concurrent_phase_active, "A concurrent phase is not active.");
+  _time_partitions.report_gc_phase_end(time, GCPhase::ConcurrentPhaseType);
+  _is_concurrent_phase_active = false;
+}
+
 void PhasesStack::clear() {
   _next_phase_level = 0;
 }
@@ -84,7 +98,6 @@ void PhasesStack::push(int phase_index) {
   assert(_next_phase_level < PHASE_LEVELS, "Overflow");
 
   _phase_indices[_next_phase_level] = phase_index;
-
   _next_phase_level++;
 }
 
@@ -92,7 +105,6 @@ int PhasesStack::pop() {
   assert(_next_phase_level > 0, "Underflow");
 
   _next_phase_level--;
-
   return _phase_indices[_next_phase_level];
 }
 
@@ -100,9 +112,8 @@ int PhasesStack::count() const {
   return _next_phase_level;
 }
 
-
 TimePartitions::TimePartitions() {
-  _phases = new (ResourceObj::C_HEAP, mtGC) GrowableArray<PausePhase>(INITIAL_CAPACITY, true, mtGC);
+  _phases = new (ResourceObj::C_HEAP, mtGC) GrowableArray<GCPhase>(INITIAL_CAPACITY, true, mtGC);
   clear();
 }
 
@@ -118,12 +129,13 @@ void TimePartitions::clear() {
   _longest_pause = Tickspan();
 }
 
-void TimePartitions::report_gc_phase_start(const char* name, const Ticks& time) {
+void TimePartitions::report_gc_phase_start(const char* name, const Ticks& time, GCPhase::PhaseType type) {
   assert(_phases->length() <= 1000, "Too many recored phases?");
 
   int level = _active_phases.count();
 
-  PausePhase phase;
+  GCPhase phase;
+  phase.set_type(type);
   phase.set_level(level);
   phase.set_name(name);
   phase.set_start(time);
@@ -134,15 +146,14 @@ void TimePartitions::report_gc_phase_start(const char* name, const Ticks& time)
 }
 
 void TimePartitions::update_statistics(GCPhase* phase) {
-  // FIXME: This should only be done for pause phases
+  if ((phase->type() == GCPhase::PausePhaseType) && (phase->level() == 0)) {
-  if (phase->level() == 0) {
     const Tickspan pause = phase->end() - phase->start();
     _sum_of_pauses += pause;
     _longest_pause = MAX2(pause, _longest_pause);
   }
 }
 
-void TimePartitions::report_gc_phase_end(const Ticks& time) {
+void TimePartitions::report_gc_phase_end(const Ticks& time, GCPhase::PhaseType type) {
   int phase_index = _active_phases.pop();
   GCPhase* phase = _phases->adr_at(phase_index);
   phase->set_end(time);
@@ -187,9 +198,10 @@ class TimePartitionPhasesIteratorTest {
     many_sub_pause_phases();
     many_sub_pause_phases2();
     max_nested_pause_phases();
+    one_concurrent();
   }
 
-  static void validate_pause_phase(GCPhase* phase, int level, const char* name, const Ticks& start, const Ticks& end) {
+  static void validate_gc_phase(GCPhase* phase, int level, const char* name, const Ticks& start, const Ticks& end) {
     assert(phase->level() == level, "Incorrect level");
     assert(strcmp(phase->name(), name) == 0, "Incorrect name");
     assert(phase->start() == start, "Incorrect start");
@@ -203,7 +215,7 @@ class TimePartitionPhasesIteratorTest {
 
     TimePartitionPhasesIterator iter(&time_partitions);
 
-    validate_pause_phase(iter.next(), 0, "PausePhase", 2, 8);
+    validate_gc_phase(iter.next(), 0, "PausePhase", 2, 8);
     assert(time_partitions.sum_of_pauses() == Ticks(8) - Ticks(2), "Incorrect");
     assert(time_partitions.longest_pause() == Ticks(8) - Ticks(2), "Incorrect");
 
@@ -219,8 +231,8 @@ class TimePartitionPhasesIteratorTest {
 
     TimePartitionPhasesIterator iter(&time_partitions);
 
-    validate_pause_phase(iter.next(), 0, "PausePhase1", 2, 3);
+    validate_gc_phase(iter.next(), 0, "PausePhase1", 2, 3);
-    validate_pause_phase(iter.next(), 0, "PausePhase2", 4, 6);
+    validate_gc_phase(iter.next(), 0, "PausePhase2", 4, 6);
 
     assert(time_partitions.sum_of_pauses() == Ticks(3) - Ticks(0), "Incorrect");
     assert(time_partitions.longest_pause() == Ticks(2) - Ticks(0), "Incorrect");
@@ -237,8 +249,8 @@ class TimePartitionPhasesIteratorTest {
 
     TimePartitionPhasesIterator iter(&time_partitions);
 
-    validate_pause_phase(iter.next(), 0, "PausePhase", 2, 5);
+    validate_gc_phase(iter.next(), 0, "PausePhase", 2, 5);
-    validate_pause_phase(iter.next(), 1, "SubPhase", 3, 4);
+    validate_gc_phase(iter.next(), 1, "SubPhase", 3, 4);
 
     assert(time_partitions.sum_of_pauses() == Ticks(3) - Ticks(0), "Incorrect");
     assert(time_partitions.longest_pause() == Ticks(3) - Ticks(0), "Incorrect");
@@ -259,10 +271,10 @@ class TimePartitionPhasesIteratorTest {
 
     TimePartitionPhasesIterator iter(&time_partitions);
 
-    validate_pause_phase(iter.next(), 0, "PausePhase", 2, 9);
+    validate_gc_phase(iter.next(), 0, "PausePhase", 2, 9);
-    validate_pause_phase(iter.next(), 1, "SubPhase1", 3, 8);
+    validate_gc_phase(iter.next(), 1, "SubPhase1", 3, 8);
-    validate_pause_phase(iter.next(), 2, "SubPhase2", 4, 7);
+    validate_gc_phase(iter.next(), 2, "SubPhase2", 4, 7);
-    validate_pause_phase(iter.next(), 3, "SubPhase3", 5, 6);
+    validate_gc_phase(iter.next(), 3, "SubPhase3", 5, 6);
 
     assert(time_partitions.sum_of_pauses() == Ticks(7) - Ticks(0), "Incorrect");
     assert(time_partitions.longest_pause() == Ticks(7) - Ticks(0), "Incorrect");
@@ -287,11 +299,11 @@ class TimePartitionPhasesIteratorTest {
 
     TimePartitionPhasesIterator iter(&time_partitions);
 
-    validate_pause_phase(iter.next(), 0, "PausePhase", 2, 11);
+    validate_gc_phase(iter.next(), 0, "PausePhase", 2, 11);
-    validate_pause_phase(iter.next(), 1, "SubPhase1", 3, 4);
+    validate_gc_phase(iter.next(), 1, "SubPhase1", 3, 4);
-    validate_pause_phase(iter.next(), 1, "SubPhase2", 5, 6);
+    validate_gc_phase(iter.next(), 1, "SubPhase2", 5, 6);
-    validate_pause_phase(iter.next(), 1, "SubPhase3", 7, 8);
+    validate_gc_phase(iter.next(), 1, "SubPhase3", 7, 8);
-    validate_pause_phase(iter.next(), 1, "SubPhase4", 9, 10);
+    validate_gc_phase(iter.next(), 1, "SubPhase4", 9, 10);
 
     assert(time_partitions.sum_of_pauses() == Ticks(9) - Ticks(0), "Incorrect");
     assert(time_partitions.longest_pause() == Ticks(9) - Ticks(0), "Incorrect");
@@ -322,20 +334,35 @@ class TimePartitionPhasesIteratorTest {
 
     TimePartitionPhasesIterator iter(&time_partitions);
 
-    validate_pause_phase(iter.next(), 0, "PausePhase", 2, 17);
+    validate_gc_phase(iter.next(), 0, "PausePhase", 2, 17);
-    validate_pause_phase(iter.next(), 1, "SubPhase1", 3, 8);
+    validate_gc_phase(iter.next(), 1, "SubPhase1", 3, 8);
-    validate_pause_phase(iter.next(), 2, "SubPhase11", 4, 5);
+    validate_gc_phase(iter.next(), 2, "SubPhase11", 4, 5);
-    validate_pause_phase(iter.next(), 2, "SubPhase12", 6, 7);
+    validate_gc_phase(iter.next(), 2, "SubPhase12", 6, 7);
-    validate_pause_phase(iter.next(), 1, "SubPhase2", 9, 14);
+    validate_gc_phase(iter.next(), 1, "SubPhase2", 9, 14);
-    validate_pause_phase(iter.next(), 2, "SubPhase21", 10, 11);
+    validate_gc_phase(iter.next(), 2, "SubPhase21", 10, 11);
-    validate_pause_phase(iter.next(), 2, "SubPhase22", 12, 13);
+    validate_gc_phase(iter.next(), 2, "SubPhase22", 12, 13);
-    validate_pause_phase(iter.next(), 1, "SubPhase3", 15, 16);
+    validate_gc_phase(iter.next(), 1, "SubPhase3", 15, 16);
 
     assert(time_partitions.sum_of_pauses() == Ticks(15) - Ticks(0), "Incorrect");
     assert(time_partitions.longest_pause() == Ticks(15) - Ticks(0), "Incorrect");
 
     assert(!iter.has_next(), "Too many elements");
   }
+
+  static void one_concurrent() {
+    TimePartitions time_partitions;
+    time_partitions.report_gc_phase_start("ConcurrentPhase", 2, GCPhase::ConcurrentPhaseType);
+    time_partitions.report_gc_phase_end(8, GCPhase::ConcurrentPhaseType);
+
+    TimePartitionPhasesIterator iter(&time_partitions);
+
+    validate_gc_phase(iter.next(), 0, "ConcurrentPhase", 2, 8);
+    // ConcurrentPhaseType should not affect to both 'sum_of_pauses()' and 'longest_pause()'.
+    assert(time_partitions.sum_of_pauses() == Tickspan(), "Incorrect");
+    assert(time_partitions.longest_pause() == Tickspan(), "Incorrect");
+
+    assert(!iter.has_next(), "Too many elements");
+  }
 };
 
 class GCTimerTest {

hotspot/src/share/vm/gc/shared/gcTimer.hpp

@@ -39,15 +39,21 @@ template <class E> class GrowableArray;
 class PhaseVisitor {
  public:
   virtual void visit(GCPhase* phase) = 0;
-  virtual void visit(PausePhase* phase) { visit((GCPhase*)phase); }
-  virtual void visit(ConcurrentPhase* phase) { visit((GCPhase*)phase); }
 };
 
 class GCPhase {
+ public:
+  enum PhaseType {
+    PausePhaseType      = 0,
+    ConcurrentPhaseType = 1
+  };
+
+ private:
   const char* _name;
   int _level;
   Ticks _start;
   Ticks _end;
+  PhaseType _type;
 
  public:
   void set_name(const char* name) { _name = name; }
@@ -62,17 +68,9 @@ class GCPhase {
   const Ticks end() const { return _end; }
   void set_end(const Ticks& time) { _end = time; }
 
-  virtual void accept(PhaseVisitor* visitor) = 0;
+  PhaseType type() const { return _type; }
-};
+  void set_type(PhaseType type) { _type = type; }
 
-class PausePhase : public GCPhase {
- public:
-  void accept(PhaseVisitor* visitor) {
-    visitor->visit(this);
-  }
-};
-
-class ConcurrentPhase : public GCPhase {
   void accept(PhaseVisitor* visitor) {
     visitor->visit(this);
   }
@@ -80,7 +78,7 @@ class ConcurrentPhase : public GCPhase {
 
 class PhasesStack {
  public:
-  // FIXME: Temporary set to 5 (used to be 4), since Reference processing needs it.
+  // Set to 5, since Reference processing needs it.
   static const int PHASE_LEVELS = 5;
 
  private:
@@ -99,8 +97,7 @@ class PhasesStack {
 class TimePartitions {
   static const int INITIAL_CAPACITY = 10;
 
-  // Currently we only support pause phases.
+  GrowableArray<GCPhase>* _phases;
-  GrowableArray<PausePhase>* _phases;
   PhasesStack _active_phases;
 
   Tickspan _sum_of_pauses;
@@ -111,8 +108,8 @@ class TimePartitions {
   ~TimePartitions();
   void clear();
 
-  void report_gc_phase_start(const char* name, const Ticks& time);
+  void report_gc_phase_start(const char* name, const Ticks& time, GCPhase::PhaseType type=GCPhase::PausePhaseType);
-  void report_gc_phase_end(const Ticks& time);
+  void report_gc_phase_end(const Ticks& time, GCPhase::PhaseType type=GCPhase::PausePhaseType);
 
   int num_phases() const;
   GCPhase* phase_at(int index) const;
@@ -121,6 +118,7 @@ class TimePartitions {
   const Tickspan longest_pause() const { return _longest_pause; }
 
   bool has_active_phases();
+
  private:
   void update_statistics(GCPhase* phase);
 };
@@ -162,9 +160,18 @@ class STWGCTimer : public GCTimer {
 };
 
 class ConcurrentGCTimer : public GCTimer {
+  // ConcurrentGCTimer can't be used if there is an overlap between a pause phase and a concurrent phase.
+  // _is_concurrent_phase_active is used to find above case.
+  bool _is_concurrent_phase_active;
+
  public:
+  ConcurrentGCTimer(): GCTimer(), _is_concurrent_phase_active(false) {};
+
   void register_gc_pause_start(const char* name);
   void register_gc_pause_end();
+
+  void register_gc_concurrent_start(const char* name, const Ticks& time = Ticks::now());
+  void register_gc_concurrent_end(const Ticks& time = Ticks::now());
 };
 
 class TimePartitionPhasesIterator {

hotspot/src/share/vm/gc/shared/gcTraceSend.cpp

@@ -418,30 +418,46 @@ void GCTracer::send_meta_space_summary_event(GCWhen::Type when, const MetaspaceS
 }
 
 class PhaseSender : public PhaseVisitor {
+  void visit_pause(GCPhase* phase) {
+    assert(phase->level() < PhasesStack::PHASE_LEVELS, "Need more event types for PausePhase");
+
+    switch (phase->level()) {
+      case 0: send_phase<EventGCPhasePause>(phase); break;
+      case 1: send_phase<EventGCPhasePauseLevel1>(phase); break;
+      case 2: send_phase<EventGCPhasePauseLevel2>(phase); break;
+      case 3: send_phase<EventGCPhasePauseLevel3>(phase); break;
+      default: /* Ignore sending this phase */ break;
+    }
+  }
+
+  void visit_concurrent(GCPhase* phase) {
+    assert(phase->level() < 1, "There is only one level for ConcurrentPhase");
+
+    switch (phase->level()) {
+      case 0: send_phase<EventGCPhaseConcurrent>(phase); break;
+      default: /* Ignore sending this phase */ break;
+    }
+  }
+
  public:
   template<typename T>
-  void send_phase(PausePhase* pause) {
+  void send_phase(GCPhase* phase) {
     T event(UNTIMED);
     if (event.should_commit()) {
       event.set_gcId(GCId::current());
-      event.set_name(pause->name());
+      event.set_name(phase->name());
-      event.set_starttime(pause->start());
+      event.set_starttime(phase->start());
-      event.set_endtime(pause->end());
+      event.set_endtime(phase->end());
       event.commit();
     }
   }
 
-  void visit(GCPhase* pause) { ShouldNotReachHere(); }
+  void visit(GCPhase* phase) {
-  void visit(ConcurrentPhase* pause) { Unimplemented(); }
+    if (phase->type() == GCPhase::PausePhaseType) {
-  void visit(PausePhase* pause) {
+      visit_pause(phase);
-    assert(PhasesStack::PHASE_LEVELS == 5, "Need more event types");
+    } else {
-
+      assert(phase->type() == GCPhase::ConcurrentPhaseType, "Should be ConcurrentPhaseType");
-    switch (pause->level()) {
+      visit_concurrent(phase);
-      case 0: send_phase<EventGCPhasePause>(pause); break;
-      case 1: send_phase<EventGCPhasePauseLevel1>(pause); break;
-      case 2: send_phase<EventGCPhasePauseLevel2>(pause); break;
-      case 3: send_phase<EventGCPhasePauseLevel3>(pause); break;
-      default: /* Ignore sending this phase */ break;
     }
   }
 };

hotspot/src/share/vm/trace/trace.xml

@@ -460,6 +460,11 @@ Declares a structure type that can be used in other events.
       <value type="UTF8" field="name" label="Name" />
     </event>
 
+    <event id="GCPhaseConcurrent" path="vm/gc/phases/concurrent" label="GC Phase Concurrent">
+      <value type="UINT" field="gcId" label="GC ID" relation="GC_ID"/>
+      <value type="UTF8" field="name" label="Name" />
+    </event>
+
     <!-- Compiler events -->
 
     <event id="Compilation" path="vm/compiler/compilation" label="Compilation"