8227084: Add timing information for merge heap root preparation
authortschatzl
Wed, 17 Jul 2019 16:33:19 +0200
changeset 55722 5ee183a90e65
parent 55721 6891a4438ae6
child 55723 95706898c3ea
8227084: Add timing information for merge heap root preparation Reviewed-by: sangheki, kbarrett
src/hotspot/share/gc/g1/g1CollectedHeap.cpp
src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp
src/hotspot/share/gc/g1/g1GCPhaseTimes.hpp
src/hotspot/share/gc/g1/g1RemSet.cpp
src/hotspot/share/gc/g1/g1RemSet.hpp
test/hotspot/jtreg/gc/g1/TestGCLogMessages.java
--- a/src/hotspot/share/gc/g1/g1CollectedHeap.cpp	Wed Jul 17 16:33:19 2019 +0200
+++ b/src/hotspot/share/gc/g1/g1CollectedHeap.cpp	Wed Jul 17 16:33:19 2019 +0200
@@ -3683,7 +3683,7 @@
 
   {
     Ticks start = Ticks::now();
-    rem_set()->merge_heap_roots(false /* remset_only */, G1GCPhaseTimes::MergeRS);
+    rem_set()->merge_heap_roots(true /* initial_evacuation */);
     p->record_merge_heap_roots_time((Ticks::now() - start).seconds() * 1000.0);
   }
 
@@ -3759,7 +3759,7 @@
 
     {
       Ticks start = Ticks::now();
-      rem_set()->merge_heap_roots(true /* remset_only */, G1GCPhaseTimes::OptMergeRS);
+      rem_set()->merge_heap_roots(false /* initial_evacuation */);
       phase_times()->record_or_add_optional_merge_heap_roots_time((Ticks::now() - start).seconds() * 1000.0);
     }
 
--- a/src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp	Wed Jul 17 16:33:19 2019 +0200
+++ b/src/hotspot/share/gc/g1/g1GCPhaseTimes.cpp	Wed Jul 17 16:33:19 2019 +0200
@@ -166,6 +166,8 @@
   _cur_strong_code_root_purge_time_ms = 0.0;
   _cur_merge_heap_roots_time_ms = 0.0;
   _cur_optional_merge_heap_roots_time_ms = 0.0;
+  _cur_prepare_merge_heap_roots_time_ms = 0.0;
+  _cur_optional_prepare_merge_heap_roots_time_ms = 0.0;
   _cur_evac_fail_recalc_used = 0.0;
   _cur_evac_fail_remove_self_forwards = 0.0;
   _cur_string_deduplication_time_ms = 0.0;
@@ -413,6 +415,8 @@
   const double sum_ms = _cur_optional_evac_ms + _cur_optional_merge_heap_roots_time_ms;
   if (sum_ms > 0) {
     info_time("Merge Optional Heap Roots", _cur_optional_merge_heap_roots_time_ms);
+
+    debug_time("Prepare Optional Merge Heap Roots", _cur_optional_prepare_merge_heap_roots_time_ms);
     debug_phase(_gc_par_phases[OptMergeRS]);
 
     info_time("Evacuate Optional Collection Set", _cur_optional_evac_ms);
@@ -427,6 +431,7 @@
 double G1GCPhaseTimes::print_evacuate_initial_collection_set() const {
   info_time("Merge Heap Roots", _cur_merge_heap_roots_time_ms);
 
+  debug_time("Prepare Merge Heap Roots", _cur_prepare_merge_heap_roots_time_ms);
   debug_phase(_gc_par_phases[MergeRS]);
   if (G1HotCardCache::default_use_cache()) {
     debug_phase(_gc_par_phases[MergeHCC]);
--- a/src/hotspot/share/gc/g1/g1GCPhaseTimes.hpp	Wed Jul 17 16:33:19 2019 +0200
+++ b/src/hotspot/share/gc/g1/g1GCPhaseTimes.hpp	Wed Jul 17 16:33:19 2019 +0200
@@ -164,6 +164,9 @@
   double _cur_merge_heap_roots_time_ms;
   double _cur_optional_merge_heap_roots_time_ms;
 
+  double _cur_prepare_merge_heap_roots_time_ms;
+  double _cur_optional_prepare_merge_heap_roots_time_ms;
+
   double _cur_prepare_tlab_time_ms;
   double _cur_resize_tlab_time_ms;
 
@@ -308,6 +311,14 @@
     _cur_optional_merge_heap_roots_time_ms += ms;
   }
 
+  void record_prepare_merge_heap_roots_time(double ms) {
+    _cur_prepare_merge_heap_roots_time_ms += ms;
+  }
+
+  void record_or_add_optional_prepare_merge_heap_roots_time(double ms) {
+    _cur_optional_prepare_merge_heap_roots_time_ms += ms;
+  }
+
   void record_evac_fail_recalc_used_time(double ms) {
     _cur_evac_fail_recalc_used = ms;
   }
--- a/src/hotspot/share/gc/g1/g1RemSet.cpp	Wed Jul 17 16:33:19 2019 +0200
+++ b/src/hotspot/share/gc/g1/g1RemSet.cpp	Wed Jul 17 16:33:19 2019 +0200
@@ -1078,28 +1078,29 @@
 
   HeapRegionClaimer _hr_claimer;
   G1RemSetScanState* _scan_state;
-  bool _remembered_set_only;
-
-  G1GCPhaseTimes::GCParPhases _merge_phase;
+  bool _initial_evacuation;
 
   volatile bool _fast_reclaim_handled;
 
 public:
-  G1MergeHeapRootsTask(G1RemSetScanState* scan_state, uint num_workers, bool remembered_set_only, G1GCPhaseTimes::GCParPhases merge_phase) :
+  G1MergeHeapRootsTask(G1RemSetScanState* scan_state, uint num_workers, bool initial_evacuation) :
     AbstractGangTask("G1 Merge Heap Roots"),
     _hr_claimer(num_workers),
     _scan_state(scan_state),
-    _remembered_set_only(remembered_set_only),
-    _merge_phase(merge_phase),
+    _initial_evacuation(initial_evacuation),
     _fast_reclaim_handled(false) { }
 
   virtual void work(uint worker_id) {
     G1CollectedHeap* g1h = G1CollectedHeap::heap();
     G1GCPhaseTimes* p = g1h->phase_times();
 
+    G1GCPhaseTimes::GCParPhases merge_remset_phase = _initial_evacuation ?
+                                                     G1GCPhaseTimes::MergeRS :
+                                                     G1GCPhaseTimes::OptMergeRS;
+
     // We schedule flushing the remembered sets of humongous fast reclaim candidates
     // onto the card table first to allow the remaining parallelized tasks hide it.
-    if (!_remembered_set_only &&
+    if (_initial_evacuation &&
         p->fast_reclaim_humongous_candidates() > 0 &&
         !_fast_reclaim_handled &&
         !Atomic::cmpxchg(true, &_fast_reclaim_handled, false)) {
@@ -1107,33 +1108,33 @@
       G1FlushHumongousCandidateRemSets cl(_scan_state);
       g1h->heap_region_iterate(&cl);
 
-      p->record_or_add_thread_work_item(_merge_phase, worker_id, cl.merged_sparse(), G1GCPhaseTimes::MergeRSMergedSparse);
-      p->record_or_add_thread_work_item(_merge_phase, worker_id, cl.merged_fine(), G1GCPhaseTimes::MergeRSMergedFine);
-      p->record_or_add_thread_work_item(_merge_phase, worker_id, cl.merged_coarse(), G1GCPhaseTimes::MergeRSMergedCoarse);
+      p->record_or_add_thread_work_item(merge_remset_phase, worker_id, cl.merged_sparse(), G1GCPhaseTimes::MergeRSMergedSparse);
+      p->record_or_add_thread_work_item(merge_remset_phase, worker_id, cl.merged_fine(), G1GCPhaseTimes::MergeRSMergedFine);
+      p->record_or_add_thread_work_item(merge_remset_phase, worker_id, cl.merged_coarse(), G1GCPhaseTimes::MergeRSMergedCoarse);
     }
 
     // Merge remembered sets of current candidates.
     {
-      G1GCParPhaseTimesTracker x(p, _merge_phase, worker_id, !_remembered_set_only /* must_record */);
+      G1GCParPhaseTimesTracker x(p, merge_remset_phase, worker_id, _initial_evacuation /* must_record */);
       G1MergeCardSetClosure cl(_scan_state);
       g1h->collection_set_iterate_increment_from(&cl, &_hr_claimer, worker_id);
 
-      p->record_or_add_thread_work_item(_merge_phase, worker_id, cl.merged_sparse(), G1GCPhaseTimes::MergeRSMergedSparse);
-      p->record_or_add_thread_work_item(_merge_phase, worker_id, cl.merged_fine(), G1GCPhaseTimes::MergeRSMergedFine);
-      p->record_or_add_thread_work_item(_merge_phase, worker_id, cl.merged_coarse(), G1GCPhaseTimes::MergeRSMergedCoarse);
+      p->record_or_add_thread_work_item(merge_remset_phase, worker_id, cl.merged_sparse(), G1GCPhaseTimes::MergeRSMergedSparse);
+      p->record_or_add_thread_work_item(merge_remset_phase, worker_id, cl.merged_fine(), G1GCPhaseTimes::MergeRSMergedFine);
+      p->record_or_add_thread_work_item(merge_remset_phase, worker_id, cl.merged_coarse(), G1GCPhaseTimes::MergeRSMergedCoarse);
     }
 
     // Apply closure to log entries in the HCC.
-    if (!_remembered_set_only && G1HotCardCache::default_use_cache()) {
-      assert(_merge_phase == G1GCPhaseTimes::MergeRS, "Wrong merge phase");
+    if (_initial_evacuation && G1HotCardCache::default_use_cache()) {
+      assert(merge_remset_phase == G1GCPhaseTimes::MergeRS, "Wrong merge phase");
       G1GCParPhaseTimesTracker x(p, G1GCPhaseTimes::MergeHCC, worker_id);
       G1MergeLogBufferCardsClosure cl(g1h, _scan_state);
       g1h->iterate_hcc_closure(&cl, worker_id);
     }
 
     // Now apply the closure to all remaining log entries.
-    if (!_remembered_set_only) {
-      assert(_merge_phase == G1GCPhaseTimes::MergeRS, "Wrong merge phase");
+    if (_initial_evacuation) {
+      assert(merge_remset_phase == G1GCPhaseTimes::MergeRS, "Wrong merge phase");
       G1GCParPhaseTimesTracker x(p, G1GCPhaseTimes::MergeLB, worker_id);
 
       G1MergeLogBufferCardsClosure cl(g1h, _scan_state);
@@ -1162,19 +1163,30 @@
                        percent_of(num_visited_cards, total_old_region_cards));
 }
 
-void G1RemSet::merge_heap_roots(bool remembered_set_only, G1GCPhaseTimes::GCParPhases merge_phase) {
+void G1RemSet::merge_heap_roots(bool initial_evacuation) {
+  G1CollectedHeap* g1h = G1CollectedHeap::heap();
+
   {
+    Ticks start = Ticks::now();
+
     _scan_state->prepare_for_merge_heap_roots();
+
+    Tickspan total = Ticks::now() - start;
+    if (initial_evacuation) {
+      g1h->phase_times()->record_prepare_merge_heap_roots_time(total.seconds() * 1000.0);
+    } else {
+      g1h->phase_times()->record_or_add_optional_prepare_merge_heap_roots_time(total.seconds() * 1000.0);
+    }
   }
 
-  WorkGang* workers = G1CollectedHeap::heap()->workers();
-  size_t const increment_length = G1CollectedHeap::heap()->collection_set()->increment_length();
+  WorkGang* workers = g1h->workers();
+  size_t const increment_length = g1h->collection_set()->increment_length();
 
-  uint const num_workers = !remembered_set_only ? workers->active_workers() :
-                                                  MIN2(workers->active_workers(), (uint)increment_length);
+  uint const num_workers = initial_evacuation ? workers->active_workers() :
+                                                MIN2(workers->active_workers(), (uint)increment_length);
 
   {
-    G1MergeHeapRootsTask cl(_scan_state, num_workers, remembered_set_only, merge_phase);
+    G1MergeHeapRootsTask cl(_scan_state, num_workers, initial_evacuation);
     log_debug(gc, ergo)("Running %s using %u workers for " SIZE_FORMAT " regions",
                         cl.name(), num_workers, increment_length);
     workers->run_task(&cl, num_workers);
--- a/src/hotspot/share/gc/g1/g1RemSet.hpp	Wed Jul 17 16:33:19 2019 +0200
+++ b/src/hotspot/share/gc/g1/g1RemSet.hpp	Wed Jul 17 16:33:19 2019 +0200
@@ -95,8 +95,8 @@
 
   // Merge cards from various sources (remembered sets, hot card cache, log buffers)
   // and calculate the cards that need to be scanned later (via scan_heap_roots()).
-  // If remembered_set_only is set, only merge remembered set cards.
-  void merge_heap_roots(bool remembered_set_only, G1GCPhaseTimes::GCParPhases merge_phase);
+  // If initial_evacuation is set, this is called during the initial evacuation.
+  void merge_heap_roots(bool initial_evacuation);
 
   // Prepare for and cleanup after scanning the heap roots. Must be called
   // once before and after in sequential code.
--- a/test/hotspot/jtreg/gc/g1/TestGCLogMessages.java	Wed Jul 17 16:33:19 2019 +0200
+++ b/test/hotspot/jtreg/gc/g1/TestGCLogMessages.java	Wed Jul 17 16:33:19 2019 +0200
@@ -97,6 +97,7 @@
 
         // Merge Heap Roots
         new LogMessageWithLevel("Merge Heap Roots", Level.INFO),
+        new LogMessageWithLevel("Prepare Merge Heap Roots", Level.DEBUG),
         new LogMessageWithLevel("Remembered Sets", Level.DEBUG),
         new LogMessageWithLevel("Merged Sparse", Level.DEBUG),
         new LogMessageWithLevel("Merged Fine", Level.DEBUG),