8270014: Add scoped objects for g1 young gc verification and young gc internal timing

Reviewed-by: ayang, iwalulya, kbarrett

Author: Thomas Schatzl

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

@@ -2922,6 +2922,36 @@ class G1YoungGCTraceTime {
   }
 };
 
+class G1YoungGCVerifierMark : public StackObj {
+  G1HeapVerifier::G1VerifyType _type;
+
+  static G1HeapVerifier::G1VerifyType young_collection_verify_type() {
+    G1CollectorState* state = G1CollectedHeap::heap()->collector_state();
+    if (state->in_concurrent_start_gc()) {
+      return G1HeapVerifier::G1VerifyConcurrentStart;
+    } else if (state->in_young_only_phase()) {
+      return G1HeapVerifier::G1VerifyYoungNormal;
+    } else {
+      return G1HeapVerifier::G1VerifyMixed;
+    }
+  }
+
+public:
+  G1YoungGCVerifierMark() : _type(young_collection_verify_type()) {
+    G1CollectedHeap::heap()->verify_before_young_collection(_type);
+  }
+
+  ~G1YoungGCVerifierMark() {
+    G1CollectedHeap::heap()->verify_after_young_collection(_type);
+  }
+};
+
+class G1YoungGCNotifyPauseMark : public StackObj {
+public:
+  G1YoungGCNotifyPauseMark() { G1CollectedHeap::heap()->policy()->record_young_gc_pause_start(); }
+  ~G1YoungGCNotifyPauseMark() { G1CollectedHeap::heap()->policy()->record_young_gc_pause_end(); }
+};
+
 G1HeapPrinterMark::G1HeapPrinterMark(G1CollectedHeap* g1h) : _g1h(g1h), _heap_transition(g1h) {
   // This summary needs to be printed before incrementing total collections.
   _g1h->rem_set()->print_periodic_summary_info("Before GC RS summary", _g1h->total_collections());
@@ -3053,8 +3083,8 @@ void G1CollectedHeap::do_collection_pause_at_safepoint_helper(double target_paus
     // determining collector state.
     G1YoungGCTraceTime tm(gc_cause());
 
-    // Young GC internal timing
-    policy()->note_gc_start();
+    // Young GC internal pause timing
+    G1YoungGCNotifyPauseMark npm;
     // JFR
     G1YoungGCJFRTracerMark jtm(_gc_timer_stw, _gc_tracer_stw, gc_cause());
     // JStat/MXBeans
@@ -3069,15 +3099,14 @@ void G1CollectedHeap::do_collection_pause_at_safepoint_helper(double target_paus
     // just to do that).
     wait_for_root_region_scanning();
 
-    G1HeapVerifier::G1VerifyType verify_type = young_collection_verify_type();
-    verify_before_young_collection(verify_type);
+    G1YoungGCVerifierMark vm;
     {
       // Actual collection work starts and is executed (only) in this scope.
 
-      // The elapsed time induced by the start time below deliberately elides
-      // the possible verification above.
-      double sample_start_time_sec = os::elapsedTime();
-      policy()->record_collection_pause_start(sample_start_time_sec);
+      // Young GC internal collection timing. The elapsed time recorded in the
+      // policy for the collection deliberately elides verification (and some
+      // other trivial setup above).
+      policy()->record_young_collection_start();
 
       calculate_collection_set(jtm.evacuation_info(), target_pause_time_ms);
 
@@ -3106,14 +3135,8 @@ void G1CollectedHeap::do_collection_pause_at_safepoint_helper(double target_paus
       // modifies it to the next state.
       jtm.report_pause_type(collector_state()->young_gc_pause_type(concurrent_operation_is_full_mark));
 
-      double sample_end_time_sec = os::elapsedTime();
-      double pause_time_ms = (sample_end_time_sec - sample_start_time_sec) * MILLIUNITS;
-      policy()->record_collection_pause_end(pause_time_ms, concurrent_operation_is_full_mark);
+      policy()->record_young_collection_end(concurrent_operation_is_full_mark);
     }
-    verify_after_young_collection(verify_type);
-
-    policy()->print_phases();
-
     TASKQUEUE_STATS_ONLY(print_taskqueue_stats());
     TASKQUEUE_STATS_ONLY(reset_taskqueue_stats());
   }
@@ -3780,11 +3803,11 @@ void G1CollectedHeap::evacuate_next_optional_regions(G1ParScanThreadStateSet* pe
 }
 
 void G1CollectedHeap::evacuate_optional_collection_set(G1ParScanThreadStateSet* per_thread_states) {
-  const double gc_start_time_ms = phase_times()->cur_collection_start_sec() * 1000.0;
+  const double collection_start_time_ms = phase_times()->cur_collection_start_sec() * 1000.0;
 
   while (!evacuation_failed() && _collection_set.optional_region_length() > 0) {
 
-    double time_used_ms = os::elapsedTime() * 1000.0 - gc_start_time_ms;
+    double time_used_ms = os::elapsedTime() * 1000.0 - collection_start_time_ms;
     double time_left_ms = MaxGCPauseMillis - time_used_ms;
 
     if (time_left_ms < 0 ||

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

@@ -146,6 +146,8 @@ class G1CollectedHeap : public CollectedHeap {
   friend class G1GCAllocRegion;
   friend class G1HeapVerifier;
 
+  friend class G1YoungGCVerifierMark;
+
   // Closures used in implementation.
   friend class G1ParScanThreadState;
   friend class G1ParScanThreadStateSet;

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

@@ -192,7 +192,7 @@ void G1GCPhaseTimes::reset() {
   _weak_phase_times.reset();
 }
 
-void G1GCPhaseTimes::note_gc_start() {
+void G1GCPhaseTimes::record_gc_pause_start() {
   _gc_start_counter = os::elapsed_counter();
   reset();
 }
@@ -211,7 +211,7 @@ double G1GCPhaseTimes::worker_time(GCParPhases phase, uint worker) {
   return 0.0;
 }
 
-void G1GCPhaseTimes::note_gc_end() {
+void G1GCPhaseTimes::record_gc_pause_end() {
   _gc_pause_time_ms = TimeHelper::counter_to_millis(os::elapsed_counter() - _gc_start_counter);
 
   double uninitialized = WorkerDataArray<double>::uninitialized();
@@ -519,8 +519,9 @@ void G1GCPhaseTimes::print_other(double accounted_ms) const {
 }
 
 void G1GCPhaseTimes::print() {
-  note_gc_end();
-
+  // Check if some time has been recorded for verification and only then print
+  // the message. We do not use Verify*GC here to print because VerifyGCType
+  // further limits actual verification.
   if (_cur_verify_before_time_ms > 0.0) {
     debug_time("Verify Before", _cur_verify_before_time_ms);
   }
@@ -532,6 +533,7 @@ void G1GCPhaseTimes::print() {
   accounted_ms += print_post_evacuate_collection_set();
   print_other(accounted_ms);
 
+  // See above comment on the _cur_verify_before_time_ms check.
   if (_cur_verify_after_time_ms > 0.0) {
     debug_time("Verify After", _cur_verify_after_time_ms);
   }

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

@@ -206,7 +206,6 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
   WeakProcessorTimes _weak_phase_times;
 
   double worker_time(GCParPhases phase, uint worker);
-  void note_gc_end();
   void reset();
 
   template <class T>
@@ -234,7 +233,8 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
 
  public:
   G1GCPhaseTimes(STWGCTimer* gc_timer, uint max_gc_threads);
-  void note_gc_start();
+  void record_gc_pause_start();
+  void record_gc_pause_end();
   void print();
   static const char* phase_name(GCParPhases phase);
 

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

@@ -113,8 +113,8 @@ void G1Policy::init(G1CollectedHeap* g1h, G1CollectionSet* collection_set) {
   _collection_set->start_incremental_building();
 }
 
-void G1Policy::note_gc_start() {
-  phase_times()->note_gc_start();
+void G1Policy::record_young_gc_pause_start() {
+  phase_times()->record_gc_pause_start();
 }
 
 class G1YoungLengthPredictor {
@@ -517,7 +517,8 @@ void G1Policy::record_concurrent_refinement_stats() {
   }
 }
 
-void G1Policy::record_collection_pause_start(double start_time_sec) {
+void G1Policy::record_young_collection_start() {
+  Ticks now = Ticks::now();
   // We only need to do this here as the policy will only be applied
   // to the GC we're about to start. so, no point is calculating this
   // every time we calculate / recalculate the target young length.
@@ -528,7 +529,7 @@ void G1Policy::record_collection_pause_start(double start_time_sec) {
          max_survivor_regions(), _g1h->num_used_regions(), _g1h->max_regions());
   assert_used_and_recalculate_used_equal(_g1h);
 
-  phase_times()->record_cur_collection_start_sec(start_time_sec);
+  phase_times()->record_cur_collection_start_sec(now.seconds());
 
   record_concurrent_refinement_stats();
 
@@ -628,11 +629,12 @@ double G1Policy::logged_cards_processing_time() const {
 // Anything below that is considered to be zero
 #define MIN_TIMER_GRANULARITY 0.0000001
 
-void G1Policy::record_collection_pause_end(double pause_time_ms, bool concurrent_operation_is_full_mark) {
+void G1Policy::record_young_collection_end(bool concurrent_operation_is_full_mark) {
   G1GCPhaseTimes* p = phase_times();
 
-  double end_time_sec = os::elapsedTime();
   double start_time_sec = phase_times()->cur_collection_start_sec();
+  double end_time_sec = Ticks::now().seconds();
+  double pause_time_ms = (end_time_sec - start_time_sec) * 1000.0;
 
   G1GCPauseType this_pause = collector_state()->young_gc_pause_type(concurrent_operation_is_full_mark);
 
@@ -889,7 +891,8 @@ void G1Policy::report_ihop_statistics() {
   _ihop_control->print();
 }
 
-void G1Policy::print_phases() {
+void G1Policy::record_young_gc_pause_end() {
+  phase_times()->record_gc_pause_end();
   phase_times()->print();
 }
 
@@ -1487,7 +1490,7 @@ void G1Policy::update_survival_estimates_for_next_collection() {
 }
 
 void G1Policy::transfer_survivors_to_cset(const G1SurvivorRegions* survivors) {
-  note_start_adding_survivor_regions();
+  start_adding_survivor_regions();
 
   HeapRegion* last = NULL;
   for (GrowableArrayIterator<HeapRegion*> it = survivors->regions()->begin();
@@ -1503,7 +1506,7 @@ void G1Policy::transfer_survivors_to_cset(const G1SurvivorRegions* survivors) {
 
     last = curr;
   }
-  note_stop_adding_survivor_regions();
+  stop_adding_survivor_regions();
 
   // Don't clear the survivor list handles until the start of
   // the next evacuation pause - we need it in order to re-tag

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

@@ -301,17 +301,19 @@ class G1Policy: public CHeapObj<mtGC> {
 
   void init(G1CollectedHeap* g1h, G1CollectionSet* collection_set);
 
-  void note_gc_start();
+  // Record the start and end of the young gc pause.
+  void record_young_gc_pause_start();
+  void record_young_gc_pause_end();
 
   bool need_to_start_conc_mark(const char* source, size_t alloc_word_size = 0);
 
   bool concurrent_operation_is_full_mark(const char* msg = NULL);
 
   bool about_to_start_mixed_phase() const;
 
-  // Record the start and end of an evacuation pause.
-  void record_collection_pause_start(double start_time_sec);
-  void record_collection_pause_end(double pause_time_ms, bool concurrent_operation_is_full_mark);
+  // Record the start and end of the actual collection part of the evacuation pause.
+  void record_young_collection_start();
+  void record_young_collection_end(bool concurrent_operation_is_full_mark);
 
   // Record the start and end of a full collection.
   void record_full_collection_start();
@@ -328,8 +330,6 @@ class G1Policy: public CHeapObj<mtGC> {
   void record_concurrent_mark_cleanup_start();
   void record_concurrent_mark_cleanup_end(bool has_rebuilt_remembered_sets);
 
-  void print_phases();
-
   bool next_gc_should_be_mixed(const char* true_action_str,
                                const char* false_action_str) const;
 
@@ -427,11 +427,11 @@ class G1Policy: public CHeapObj<mtGC> {
     return _max_survivor_regions;
   }
 
-  void note_start_adding_survivor_regions() {
+  void start_adding_survivor_regions() {
     _survivor_surv_rate_group->start_adding_regions();
   }
 
-  void note_stop_adding_survivor_regions() {
+  void stop_adding_survivor_regions() {
     _survivor_surv_rate_group->stop_adding_regions();
   }
 

test/hotspot/jtreg/gc/g1/TestEagerReclaimHumongousRegionsLog.java

@@ -73,12 +73,12 @@ public static void runTest() throws Exception {
 
         // This gives an array of lines containing eager reclaim of humongous regions
         // log messages contents after the ":" in the following order for every GC:
+        //   Humongous Regions: f->g
         //   Region Register: a.ams
         //   Eagerly Reclaim Humonguous Objects b.cms
         //   Humongous Total: Min: 1, Avg:  1.0, Max: 1, Diff: 0, Sum: c, Workers: 1
         //   Humongous Candidate: Min: 1, Avg:  1.0, Max: 1, Diff: 0, Sum: d, Workers: 1
         //   Humongous Reclaimed: Min: 1, Avg:  1.0, Max: 1, Diff: 0, Sum: e, Workers: 1
-        //   Humongous Regions: f->g
 
         String[] lines = Arrays.stream(output.getStdout().split("\\R"))
                          .filter(s -> (s.contains("Humongous") || s.contains("Region Register"))).map(s -> s.substring(s.indexOf(LogSeparator) + LogSeparator.length()))
@@ -87,12 +87,12 @@ public static void runTest() throws Exception {
         Asserts.assertTrue(lines.length % 6 == 0, "There seems to be an unexpected amount of log messages (total: " + lines.length + ") per GC");
 
         for (int i = 0; i < lines.length; i += 6) {
-            int total = Integer.parseInt(getSumValue(lines[i + 2]));
-            int candidate = Integer.parseInt(getSumValue(lines[i + 3]));
-            int reclaimed = Integer.parseInt(getSumValue(lines[i + 4]));
+            int total = Integer.parseInt(getSumValue(lines[i + 3]));
+            int candidate = Integer.parseInt(getSumValue(lines[i + 4]));
+            int reclaimed = Integer.parseInt(getSumValue(lines[i + 5]));
 
-            int before = Integer.parseInt(lines[i + 5].substring(0, 1));
-            int after = Integer.parseInt(lines[i + 5].substring(3, 4));
+            int before = Integer.parseInt(lines[i].substring(0, 1));
+            int after = Integer.parseInt(lines[i].substring(3, 4));
             System.out.println("total " + total + " candidate " + candidate + " reclaimed " + reclaimed + " before " + before + " after " + after);
 
             Asserts.assertEQ(total, candidate, "Not all humonguous objects are candidates");