8035398: Add card redirty time in "Other" time in G1

Show the time taken by card redirtying during GC in a new "Redirty Cards" line.

Reviewed-by: jwilhelm, brutisso

hotspot/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp

@@ -169,14 +169,6 @@ public:
   int calls() { return _calls; }
 };
 
-class RedirtyLoggedCardTableEntryFastClosure : public CardTableEntryClosure {
-public:
-  bool do_card_ptr(jbyte* card_ptr, int worker_i) {
-    *card_ptr = CardTableModRefBS::dirty_card_val();
-    return true;
-  }
-};
-
 YoungList::YoungList(G1CollectedHeap* g1h) :
     _g1h(g1h), _head(NULL), _length(0), _last_sampled_rs_lengths(0),
     _survivor_head(NULL), _survivor_tail(NULL), _survivor_length(0) {
@@ -5270,6 +5262,29 @@ void G1CollectedHeap::unlink_string_and_symbol_table(BoolObjectClosure* is_alive
   }
 }
 
+class RedirtyLoggedCardTableEntryFastClosure : public CardTableEntryClosure {
+public:
+  bool do_card_ptr(jbyte* card_ptr, int worker_i) {
+    *card_ptr = CardTableModRefBS::dirty_card_val();
+    return true;
+  }
+};
+
+void G1CollectedHeap::redirty_logged_cards() {
+  guarantee(G1DeferredRSUpdate, "Must only be called when using deferred RS updates.");
+  double redirty_logged_cards_start = os::elapsedTime();
+
+  RedirtyLoggedCardTableEntryFastClosure redirty;
+  dirty_card_queue_set().set_closure(&redirty);
+  dirty_card_queue_set().apply_closure_to_all_completed_buffers();
+
+  DirtyCardQueueSet& dcq = JavaThread::dirty_card_queue_set();
+  dcq.merge_bufferlists(&dirty_card_queue_set());
+  assert(dirty_card_queue_set().completed_buffers_num() == 0, "All should be consumed");
+
+  g1_policy()->phase_times()->record_redirty_logged_cards_time_ms((os::elapsedTime() - redirty_logged_cards_start) * 1000.0);
+}
+
 // Weak Reference Processing support
 
 // An always "is_alive" closure that is used to preserve referents.
@@ -5926,13 +5941,7 @@ void G1CollectedHeap::evacuate_collection_set(EvacuationInfo& evacuation_info) {
   enqueue_discovered_references(n_workers);
 
   if (G1DeferredRSUpdate) {
-    RedirtyLoggedCardTableEntryFastClosure redirty;
+    redirty_logged_cards();
-    dirty_card_queue_set().set_closure(&redirty);
-    dirty_card_queue_set().apply_closure_to_all_completed_buffers();
-
-    DirtyCardQueueSet& dcq = JavaThread::dirty_card_queue_set();
-    dcq.merge_bufferlists(&dirty_card_queue_set());
-    assert(dirty_card_queue_set().completed_buffers_num() == 0, "All should be consumed");
   }
   COMPILER2_PRESENT(DerivedPointerTable::update_pointers());
 }

hotspot/src/share/vm/gc_implementation/g1/g1CollectedHeap.hpp

@@ -1651,6 +1651,8 @@ public:
   // in symbol table, possibly in parallel.
   void unlink_string_and_symbol_table(BoolObjectClosure* is_alive, bool unlink_strings = true, bool unlink_symbols = true);
 
+  // Redirty logged cards in the refinement queue.
+  void redirty_logged_cards();
   // Verification
 
   // The following is just to alert the verification code

hotspot/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp

@@ -314,6 +314,9 @@ void G1GCPhaseTimes::print(double pause_time_sec) {
     _recorded_non_young_cset_choice_time_ms));
   print_stats(2, "Ref Proc", _cur_ref_proc_time_ms);
   print_stats(2, "Ref Enq", _cur_ref_enq_time_ms);
+  if (G1DeferredRSUpdate) {
+    print_stats(2, "Redirty Cards", _recorded_redirty_logged_cards_time_ms);
+  }
   print_stats(2, "Free CSet",
     (_recorded_young_free_cset_time_ms +
     _recorded_non_young_free_cset_time_ms));

hotspot/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp

@@ -143,6 +143,8 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
   double _recorded_young_cset_choice_time_ms;
   double _recorded_non_young_cset_choice_time_ms;
 
+  double _recorded_redirty_logged_cards_time_ms;
+
   double _recorded_young_free_cset_time_ms;
   double _recorded_non_young_free_cset_time_ms;
 
@@ -256,6 +258,10 @@ class G1GCPhaseTimes : public CHeapObj<mtGC> {
     _recorded_non_young_cset_choice_time_ms = time_ms;
   }
 
+  void record_redirty_logged_cards_time_ms(double time_ms) {
+    _recorded_redirty_logged_cards_time_ms = time_ms;
+  }
+
   void record_cur_collection_start_sec(double time_ms) {
     _cur_collection_start_sec = time_ms;
   }

hotspot/test/gc/g1/TestGCLogMessages.java

@@ -23,7 +23,7 @@
 
 /*
  * @test TestPrintGCDetails
- * @bug 8035406 8027295
+ * @bug 8035406 8027295 8035398
  * @summary Ensure that the PrintGCDetails output for a minor GC with G1
  * includes the expected necessary messages.
  * @key gc
@@ -42,6 +42,7 @@ public class TestGCLogMessages {
 
     OutputAnalyzer output = new OutputAnalyzer(pb.start());
 
+    output.shouldNotContain("[Redirty Cards");
     output.shouldNotContain("[Code Root Purge");
     output.shouldNotContain("[Young Free CSet");
     output.shouldNotContain("[Non-Young Free CSet");
@@ -54,6 +55,7 @@ public class TestGCLogMessages {
 
     output = new OutputAnalyzer(pb.start());
 
+    output.shouldContain("[Redirty Cards");
     output.shouldContain("[Code Root Purge");
     output.shouldNotContain("[Young Free CSet");
     output.shouldNotContain("[Non-Young Free CSet");
@@ -68,6 +70,7 @@ public class TestGCLogMessages {
 
     output = new OutputAnalyzer(pb.start());
 
+    output.shouldContain("[Redirty Cards");
     output.shouldContain("[Code Root Purge");
     output.shouldContain("[Young Free CSet");
     output.shouldContain("[Non-Young Free CSet");