# HG changeset patch
# User tschatzl
# Date 1444740553 -7200
# Node ID b8a3901ac5b3e7c006dd66af6f073f27289c292e
# Parent  e1034e5d33ebf16ba9a4076f1790f887944c0ea7
8069330: Adjustment of concurrent refinement thresholds does not take hot card cache into account
Summary: Measure HCC processing time separately and remove that time from the calculation of the refinement thresholds. HCC processing time is still taken into account for general pause time predictions.
Reviewed-by: tbenson, jmasa

diff -r e1034e5d33eb -r b8a3901ac5b3 hotspot/src/share/vm/gc/g1/concurrentG1Refine.hpp
--- a/hotspot/src/share/vm/gc/g1/concurrentG1Refine.hpp	Tue Oct 13 08:37:44 2015 +0200
+++ b/hotspot/src/share/vm/gc/g1/concurrentG1Refine.hpp	Tue Oct 13 14:49:13 2015 +0200
@@ -112,6 +112,8 @@
   int thread_threshold_step() const { return _thread_threshold_step; }
 
   G1HotCardCache* hot_card_cache() { return &_hot_card_cache; }
+
+  static bool hot_card_cache_enabled() { return G1HotCardCache::default_use_cache(); }
 };
 
 #endif // SHARE_VM_GC_G1_CONCURRENTG1REFINE_HPP
diff -r e1034e5d33eb -r b8a3901ac5b3 hotspot/src/share/vm/gc/g1/g1CollectedHeap.cpp
--- a/hotspot/src/share/vm/gc/g1/g1CollectedHeap.cpp	Tue Oct 13 08:37:44 2015 +0200
+++ b/hotspot/src/share/vm/gc/g1/g1CollectedHeap.cpp	Tue Oct 13 14:49:13 2015 +0200
@@ -2258,14 +2258,11 @@
 }
 #endif // PRODUCT
 
-void G1CollectedHeap::iterate_dirty_card_closure(CardTableEntryClosure* cl,
-                                                 DirtyCardQueue* into_cset_dcq,
-                                                 bool concurrent,
-                                                 uint worker_i) {
-  // Clean cards in the hot card cache
-  G1HotCardCache* hot_card_cache = _cg1r->hot_card_cache();
-  hot_card_cache->drain(worker_i, g1_rem_set(), into_cset_dcq);
-
+void G1CollectedHeap::iterate_hcc_closure(CardTableEntryClosure* cl, uint worker_i) {
+  _cg1r->hot_card_cache()->drain(cl, worker_i);
+}
+
+void G1CollectedHeap::iterate_dirty_card_closure(CardTableEntryClosure* cl, uint worker_i) {
   DirtyCardQueueSet& dcqs = JavaThread::dirty_card_queue_set();
   size_t n_completed_buffers = 0;
   while (dcqs.apply_closure_to_completed_buffer(cl, worker_i, 0, true)) {
diff -r e1034e5d33eb -r b8a3901ac5b3 hotspot/src/share/vm/gc/g1/g1CollectedHeap.hpp
--- a/hotspot/src/share/vm/gc/g1/g1CollectedHeap.hpp	Tue Oct 13 08:37:44 2015 +0200
+++ b/hotspot/src/share/vm/gc/g1/g1CollectedHeap.hpp	Tue Oct 13 14:49:13 2015 +0200
@@ -1011,9 +1011,11 @@
   // continues humongous regions too.
   void reset_gc_time_stamps(HeapRegion* hr);
 
-  void iterate_dirty_card_closure(CardTableEntryClosure* cl,
-                                  DirtyCardQueue* into_cset_dcq,
-                                  bool concurrent, uint worker_i);
+  // Apply the given closure on all cards in the Hot Card Cache, emptying it.
+  void iterate_hcc_closure(CardTableEntryClosure* cl, uint worker_i);
+
+  // Apply the given closure on all cards in the Dirty Card Queue Set, emptying it.
+  void iterate_dirty_card_closure(CardTableEntryClosure* cl, uint worker_i);
 
   // The shared block offset table array.
   G1BlockOffsetSharedArray* bot_shared() const { return _bot_shared; }
diff -r e1034e5d33eb -r b8a3901ac5b3 hotspot/src/share/vm/gc/g1/g1CollectorPolicy.cpp
--- a/hotspot/src/share/vm/gc/g1/g1CollectorPolicy.cpp	Tue Oct 13 08:37:44 2015 +0200
+++ b/hotspot/src/share/vm/gc/g1/g1CollectorPolicy.cpp	Tue Oct 13 14:49:13 2015 +0200
@@ -92,6 +92,7 @@
   _prev_collection_pause_end_ms(0.0),
   _rs_length_diff_seq(new TruncatedSeq(TruncatedSeqLength)),
   _cost_per_card_ms_seq(new TruncatedSeq(TruncatedSeqLength)),
+  _cost_scan_hcc_seq(new TruncatedSeq(TruncatedSeqLength)),
   _young_cards_per_entry_ratio_seq(new TruncatedSeq(TruncatedSeqLength)),
   _mixed_cards_per_entry_ratio_seq(new TruncatedSeq(TruncatedSeqLength)),
   _cost_per_entry_ms_seq(new TruncatedSeq(TruncatedSeqLength)),
@@ -192,6 +193,7 @@
 
   _rs_length_diff_seq->add(rs_length_diff_defaults[index]);
   _cost_per_card_ms_seq->add(cost_per_card_ms_defaults[index]);
+  _cost_scan_hcc_seq->add(0.0);
   _young_cards_per_entry_ratio_seq->add(
                                   young_cards_per_entry_ratio_defaults[index]);
   _cost_per_entry_ms_seq->add(cost_per_entry_ms_defaults[index]);
@@ -1046,10 +1048,12 @@
 
   if (update_stats) {
     double cost_per_card_ms = 0.0;
+    double cost_scan_hcc = phase_times()->average_time_ms(G1GCPhaseTimes::ScanHCC);
     if (_pending_cards > 0) {
-      cost_per_card_ms = phase_times()->average_time_ms(G1GCPhaseTimes::UpdateRS) / (double) _pending_cards;
+      cost_per_card_ms = (phase_times()->average_time_ms(G1GCPhaseTimes::UpdateRS) - cost_scan_hcc) / (double) _pending_cards;
       _cost_per_card_ms_seq->add(cost_per_card_ms);
     }
+    _cost_scan_hcc_seq->add(cost_scan_hcc);
 
     double cost_per_entry_ms = 0.0;
     if (cards_scanned > 10) {
@@ -1146,8 +1150,25 @@
 
   // Note that _mmu_tracker->max_gc_time() returns the time in seconds.
   double update_rs_time_goal_ms = _mmu_tracker->max_gc_time() * MILLIUNITS * G1RSetUpdatingPauseTimePercent / 100.0;
-  adjust_concurrent_refinement(phase_times()->average_time_ms(G1GCPhaseTimes::UpdateRS),
-                               phase_times()->sum_thread_work_items(G1GCPhaseTimes::UpdateRS), update_rs_time_goal_ms);
+
+  double scan_hcc_time_ms = phase_times()->average_time_ms(G1GCPhaseTimes::ScanHCC);
+
+  if (update_rs_time_goal_ms < scan_hcc_time_ms) {
+    ergo_verbose2(ErgoTiming,
+                  "adjust concurrent refinement thresholds",
+                  ergo_format_reason("Scanning the HCC expected to take longer than Update RS time goal")
+                  ergo_format_ms("Update RS time goal")
+                  ergo_format_ms("Scan HCC time"),
+                  update_rs_time_goal_ms,
+                  scan_hcc_time_ms);
+
+    update_rs_time_goal_ms = 0;
+  } else {
+    update_rs_time_goal_ms -= scan_hcc_time_ms;
+  }
+  adjust_concurrent_refinement(phase_times()->average_time_ms(G1GCPhaseTimes::UpdateRS) - scan_hcc_time_ms,
+                               phase_times()->sum_thread_work_items(G1GCPhaseTimes::UpdateRS),
+                               update_rs_time_goal_ms);
 
   _collectionSetChooser->verify();
 }
diff -r e1034e5d33eb -r b8a3901ac5b3 hotspot/src/share/vm/gc/g1/g1CollectorPolicy.hpp
--- a/hotspot/src/share/vm/gc/g1/g1CollectorPolicy.hpp	Tue Oct 13 08:37:44 2015 +0200
+++ b/hotspot/src/share/vm/gc/g1/g1CollectorPolicy.hpp	Tue Oct 13 14:49:13 2015 +0200
@@ -219,6 +219,7 @@
 
   TruncatedSeq* _rs_length_diff_seq;
   TruncatedSeq* _cost_per_card_ms_seq;
+  TruncatedSeq* _cost_scan_hcc_seq;
   TruncatedSeq* _young_cards_per_entry_ratio_seq;
   TruncatedSeq* _mixed_cards_per_entry_ratio_seq;
   TruncatedSeq* _cost_per_entry_ms_seq;
@@ -324,8 +325,12 @@
     return get_new_prediction(_cost_per_card_ms_seq);
   }
 
+  double predict_scan_hcc_ms() const {
+    return get_new_prediction(_cost_scan_hcc_seq);
+  }
+
   double predict_rs_update_time_ms(size_t pending_cards) const {
-    return (double) pending_cards * predict_cost_per_card_ms();
+    return (double) pending_cards * predict_cost_per_card_ms() + predict_scan_hcc_ms();
   }
 
   double predict_young_cards_per_entry_ratio() const {
diff -r e1034e5d33eb -r b8a3901ac5b3 hotspot/src/share/vm/gc/g1/g1ErgoVerbose.cpp
--- a/hotspot/src/share/vm/gc/g1/g1ErgoVerbose.cpp	Tue Oct 13 08:37:44 2015 +0200
+++ b/hotspot/src/share/vm/gc/g1/g1ErgoVerbose.cpp	Tue Oct 13 14:49:13 2015 +0200
@@ -56,6 +56,7 @@
   case ErgoCSetConstruction:  return "CSet Construction";
   case ErgoConcCycles:        return "Concurrent Cycles";
   case ErgoMixedGCs:          return "Mixed GCs";
+  case ErgoTiming:            return "Timing";
   default:
     ShouldNotReachHere();
     // Keep the Windows compiler happy
diff -r e1034e5d33eb -r b8a3901ac5b3 hotspot/src/share/vm/gc/g1/g1ErgoVerbose.hpp
--- a/hotspot/src/share/vm/gc/g1/g1ErgoVerbose.hpp	Tue Oct 13 08:37:44 2015 +0200
+++ b/hotspot/src/share/vm/gc/g1/g1ErgoVerbose.hpp	Tue Oct 13 14:49:13 2015 +0200
@@ -70,6 +70,7 @@
   ErgoCSetConstruction,
   ErgoConcCycles,
   ErgoMixedGCs,
+  ErgoTiming,
 
   ErgoHeuristicNum
 } ErgoHeuristic;
diff -r e1034e5d33eb -r b8a3901ac5b3 hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.cpp
--- a/hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.cpp	Tue Oct 13 08:37:44 2015 +0200
+++ b/hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.cpp	Tue Oct 13 14:49:13 2015 +0200
@@ -23,6 +23,7 @@
  */
 
 #include "precompiled.hpp"
+#include "gc/g1/concurrentG1Refine.hpp"
 #include "gc/g1/g1CollectedHeap.inline.hpp"
 #include "gc/g1/g1GCPhaseTimes.hpp"
 #include "gc/g1/g1Log.hpp"
@@ -269,6 +270,8 @@
   _gc_par_phases[SATBFiltering] = new WorkerDataArray<double>(max_gc_threads, "SATB Filtering (ms)", true, G1Log::LevelFinest, 3);
 
   _gc_par_phases[UpdateRS] = new WorkerDataArray<double>(max_gc_threads, "Update RS (ms)", true, G1Log::LevelFiner, 2);
+  _gc_par_phases[ScanHCC] = new WorkerDataArray<double>(max_gc_threads, "Scan HCC (ms)", true, G1Log::LevelFiner, 3);
+  _gc_par_phases[ScanHCC]->set_enabled(ConcurrentG1Refine::hot_card_cache_enabled());
   _gc_par_phases[ScanRS] = new WorkerDataArray<double>(max_gc_threads, "Scan RS (ms)", true, G1Log::LevelFiner, 2);
   _gc_par_phases[CodeRoots] = new WorkerDataArray<double>(max_gc_threads, "Code Root Scanning (ms)", true, G1Log::LevelFiner, 2);
   _gc_par_phases[ObjCopy] = new WorkerDataArray<double>(max_gc_threads, "Object Copy (ms)", true, G1Log::LevelFiner, 2);
diff -r e1034e5d33eb -r b8a3901ac5b3 hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.hpp
--- a/hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.hpp	Tue Oct 13 08:37:44 2015 +0200
+++ b/hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.hpp	Tue Oct 13 14:49:13 2015 +0200
@@ -56,6 +56,7 @@
     WeakCLDRoots,
     SATBFiltering,
     UpdateRS,
+    ScanHCC,
     ScanRS,
     CodeRoots,
     ObjCopy,
diff -r e1034e5d33eb -r b8a3901ac5b3 hotspot/src/share/vm/gc/g1/g1HotCardCache.cpp
--- a/hotspot/src/share/vm/gc/g1/g1HotCardCache.cpp	Tue Oct 13 08:37:44 2015 +0200
+++ b/hotspot/src/share/vm/gc/g1/g1HotCardCache.cpp	Tue Oct 13 14:49:13 2015 +0200
@@ -26,7 +26,6 @@
 #include "gc/g1/dirtyCardQueue.hpp"
 #include "gc/g1/g1CollectedHeap.inline.hpp"
 #include "gc/g1/g1HotCardCache.hpp"
-#include "gc/g1/g1RemSet.hpp"
 #include "runtime/atomic.inline.hpp"
 
 G1HotCardCache::G1HotCardCache(G1CollectedHeap *g1h):
@@ -81,9 +80,7 @@
   return (previous_ptr == current_ptr) ? previous_ptr : card_ptr;
 }
 
-void G1HotCardCache::drain(uint worker_i,
-                           G1RemSet* g1rs,
-                           DirtyCardQueue* into_cset_dcq) {
+void G1HotCardCache::drain(CardTableEntryClosure* cl, uint worker_i) {
   if (!default_use_cache()) {
     assert(_hot_cache == NULL, "Logic");
     return;
@@ -101,21 +98,8 @@
     for (size_t i = start_idx; i < end_idx; i++) {
       jbyte* card_ptr = _hot_cache[i];
       if (card_ptr != NULL) {
-        if (g1rs->refine_card(card_ptr, worker_i, true)) {
-          // The part of the heap spanned by the card contains references
-          // that point into the current collection set.
-          // We need to record the card pointer in the DirtyCardQueueSet
-          // that we use for such cards.
-          //
-          // The only time we care about recording cards that contain
-          // references that point into the collection set is during
-          // RSet updating while within an evacuation pause.
-          // In this case worker_i should be the id of a GC worker thread
-          assert(SafepointSynchronize::is_at_safepoint(), "Should be at a safepoint");
-          assert(worker_i < ParallelGCThreads, "incorrect worker id: %u", worker_i);
-
-          into_cset_dcq->enqueue(card_ptr);
-        }
+        bool result = cl->do_card_ptr(card_ptr, worker_i);
+        assert(result, "Closure should always return true");
       } else {
         break;
       }
diff -r e1034e5d33eb -r b8a3901ac5b3 hotspot/src/share/vm/gc/g1/g1HotCardCache.hpp
--- a/hotspot/src/share/vm/gc/g1/g1HotCardCache.hpp	Tue Oct 13 08:37:44 2015 +0200
+++ b/hotspot/src/share/vm/gc/g1/g1HotCardCache.hpp	Tue Oct 13 14:49:13 2015 +0200
@@ -32,9 +32,9 @@
 #include "runtime/thread.hpp"
 #include "utilities/globalDefinitions.hpp"
 
+class CardTableEntryClosure;
 class DirtyCardQueue;
 class G1CollectedHeap;
-class G1RemSet;
 class HeapRegion;
 
 // An evicting cache of cards that have been logged by the G1 post
@@ -84,11 +84,11 @@
   // The number of cached cards a thread claims when flushing the cache
   static const int ClaimChunkSize = 32;
 
-  bool default_use_cache() const {
+ public:
+  static bool default_use_cache() {
     return (G1ConcRSLogCacheSize > 0);
   }
 
- public:
   G1HotCardCache(G1CollectedHeap* g1h);
   ~G1HotCardCache();
 
@@ -113,7 +113,7 @@
 
   // Refine the cards that have delayed as a result of
   // being in the cache.
-  void drain(uint worker_i, G1RemSet* g1rs, DirtyCardQueue* into_cset_dcq);
+  void drain(CardTableEntryClosure* cl, uint worker_i);
 
   // Set up for parallel processing of the cards in the hot cache
   void reset_hot_cache_claimed_index() {
diff -r e1034e5d33eb -r b8a3901ac5b3 hotspot/src/share/vm/gc/g1/g1RemSet.cpp
--- a/hotspot/src/share/vm/gc/g1/g1RemSet.cpp	Tue Oct 13 08:37:44 2015 +0200
+++ b/hotspot/src/share/vm/gc/g1/g1RemSet.cpp	Tue Oct 13 14:49:13 2015 +0200
@@ -263,6 +263,7 @@
                                               DirtyCardQueue* into_cset_dcq) :
     _g1rs(g1h->g1_rem_set()), _into_cset_dcq(into_cset_dcq)
   {}
+
   bool do_card_ptr(jbyte* card_ptr, uint worker_i) {
     // The only time we care about recording cards that
     // contain references that point into the collection set
@@ -285,11 +286,16 @@
 };
 
 void G1RemSet::updateRS(DirtyCardQueue* into_cset_dcq, uint worker_i) {
-  G1GCParPhaseTimesTracker x(_g1p->phase_times(), G1GCPhaseTimes::UpdateRS, worker_i);
-  // Apply the given closure to all remaining log entries.
   RefineRecordRefsIntoCSCardTableEntryClosure into_cset_update_rs_cl(_g1, into_cset_dcq);
 
-  _g1->iterate_dirty_card_closure(&into_cset_update_rs_cl, into_cset_dcq, false, worker_i);
+  G1GCParPhaseTimesTracker x(_g1p->phase_times(), G1GCPhaseTimes::UpdateRS, worker_i);
+  {
+    // Apply the closure to the entries of the hot card cache.
+    G1GCParPhaseTimesTracker y(_g1p->phase_times(), G1GCPhaseTimes::ScanHCC, worker_i);
+    _g1->iterate_hcc_closure(&into_cset_update_rs_cl, worker_i);
+  }
+  // Apply the closure to all remaining log entries.
+  _g1->iterate_dirty_card_closure(&into_cset_update_rs_cl, worker_i);
 }
 
 void G1RemSet::cleanupHRRS() {
diff -r e1034e5d33eb -r b8a3901ac5b3 hotspot/test/gc/g1/TestGCLogMessages.java
--- a/hotspot/test/gc/g1/TestGCLogMessages.java	Tue Oct 13 08:37:44 2015 +0200
+++ b/hotspot/test/gc/g1/TestGCLogMessages.java	Tue Oct 13 14:49:13 2015 +0200
@@ -23,7 +23,7 @@
 
 /*
  * @test TestGCLogMessages
- * @bug 8035406 8027295 8035398 8019342 8027959 8048179 8027962
+ * @bug 8035406 8027295 8035398 8019342 8027959 8048179 8027962 8069330
  * @summary Ensure that the PrintGCDetails output for a minor GC with G1
  * includes the expected necessary messages.
  * @key gc
@@ -55,6 +55,8 @@
     };
 
     private LogMessageWithLevel allLogMessages[] = new LogMessageWithLevel[] {
+        // Update RS
+        new LogMessageWithLevel("Scan HCC (ms)", Level.FINER),
         // Ext Root Scan
         new LogMessageWithLevel("Thread Roots (ms)", Level.FINEST),
         new LogMessageWithLevel("StringTable Roots (ms)", Level.FINEST),