8160055: Misplaced call to ClassLoaderDataGraph::clear_claimed_marks during initial mark
authorjprovino
Mon, 24 Oct 2016 10:10:30 -0400
changeset 42048 c1f066b53dd7
parent 42046 e3e741af6407
child 42049 2577785d980a
8160055: Misplaced call to ClassLoaderDataGraph::clear_claimed_marks during initial mark Summary: The call to ClassLoaderDataGraph::clear_claimed_marks() during initial mark in g1CollectedHeap.cpp:4420 is misplaced. Reviewed-by: tschatzl, kbarrett
hotspot/src/share/vm/gc/g1/g1CollectedHeap.cpp
hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.cpp
hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.hpp
hotspot/test/gc/g1/TestGCLogMessages.java
--- a/hotspot/src/share/vm/gc/g1/g1CollectedHeap.cpp	Mon Oct 24 09:55:58 2016 +0200
+++ b/hotspot/src/share/vm/gc/g1/g1CollectedHeap.cpp	Mon Oct 24 10:10:30 2016 -0400
@@ -4420,6 +4420,19 @@
   NOT_PRODUCT(set_evacuation_failure_alot_for_current_gc();)
 
   assert(dirty_card_queue_set().completed_buffers_num() == 0, "Should be empty");
+
+  G1GCPhaseTimes* phase_times = g1_policy()->phase_times();
+
+  // InitialMark needs claim bits to keep track of the marked-through CLDs.
+  if (collector_state()->during_initial_mark_pause()) {
+    double start_clear_claimed_marks = os::elapsedTime();
+
+    ClassLoaderDataGraph::clear_claimed_marks();
+
+    double recorded_clear_claimed_marks_time_ms = (os::elapsedTime() - start_clear_claimed_marks) * 1000.0;
+    phase_times->record_clear_claimed_marks_time_ms(recorded_clear_claimed_marks_time_ms);
+  }
+
   double start_par_time_sec = os::elapsedTime();
   double end_par_time_sec;
 
@@ -4427,10 +4440,6 @@
     const uint n_workers = workers()->active_workers();
     G1RootProcessor root_processor(this, n_workers);
     G1ParTask g1_par_task(this, per_thread_states, _task_queues, &root_processor, n_workers);
-    // InitialMark needs claim bits to keep track of the marked-through CLDs.
-    if (collector_state()->during_initial_mark_pause()) {
-      ClassLoaderDataGraph::clear_claimed_marks();
-    }
 
     print_termination_stats_hdr();
 
@@ -4444,8 +4453,6 @@
     // reported parallel time.
   }
 
-  G1GCPhaseTimes* phase_times = g1_policy()->phase_times();
-
   double par_time_ms = (end_par_time_sec - start_par_time_sec) * 1000.0;
   phase_times->record_par_time(par_time_ms);
 
--- a/hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.cpp	Mon Oct 24 09:55:58 2016 +0200
+++ b/hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.cpp	Mon Oct 24 10:10:30 2016 -0400
@@ -101,6 +101,7 @@
   _gc_start_counter = os::elapsed_counter();
   _cur_expand_heap_time_ms = 0.0;
   _external_accounted_time_ms = 0.0;
+  _recorded_clear_claimed_marks_time_ms = 0.0;
 
   for (int i = 0; i < GCParPhasesSentinel; i++) {
     if (_gc_par_phases[i] != NULL) {
@@ -306,6 +307,10 @@
   debug_line("Reference Processing", _cur_ref_proc_time_ms);
   debug_line("Reference Enqueuing", _cur_ref_enq_time_ms);
   debug_line("Redirty Cards", _recorded_redirty_logged_cards_time_ms);
+  if (_recorded_clear_claimed_marks_time_ms > 0.0) {
+    debug_line("Clear Claimed Marks", _recorded_clear_claimed_marks_time_ms);
+  }
+
   trace_phase(_gc_par_phases[RedirtyCards]);
   if (G1EagerReclaimHumongousObjects) {
     debug_line("Humongous Register", _cur_fast_reclaim_humongous_register_time_ms);
--- a/hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.hpp	Mon Oct 24 09:55:58 2016 +0200
+++ b/hotspot/src/share/vm/gc/g1/g1GCPhaseTimes.hpp	Mon Oct 24 10:10:30 2016 -0400
@@ -103,6 +103,8 @@
 
   double _external_accounted_time_ms;
 
+  double _recorded_clear_claimed_marks_time_ms;
+
   double _recorded_young_cset_choice_time_ms;
   double _recorded_non_young_cset_choice_time_ms;
 
@@ -257,6 +259,10 @@
     _external_accounted_time_ms += time_ms;
   }
 
+  void record_clear_claimed_marks_time_ms(double recorded_clear_claimed_marks_time_ms) {
+    _recorded_clear_claimed_marks_time_ms = recorded_clear_claimed_marks_time_ms;
+  }
+
   double cur_collection_start_sec() {
     return _cur_collection_start_sec;
   }
--- a/hotspot/test/gc/g1/TestGCLogMessages.java	Mon Oct 24 09:55:58 2016 +0200
+++ b/hotspot/test/gc/g1/TestGCLogMessages.java	Mon Oct 24 10:10:30 2016 -0400
@@ -23,7 +23,7 @@
 
 /*
  * @test TestGCLogMessages
- * @bug 8035406 8027295 8035398 8019342 8027959 8048179 8027962 8069330 8076463 8150630
+ * @bug 8035406 8027295 8035398 8019342 8027959 8048179 8027962 8069330 8076463 8150630 8160055
  * @summary Ensure the output for a minor GC with G1
  * includes the expected necessary messages.
  * @key gc
@@ -31,6 +31,9 @@
  * @library /test/lib
  * @modules java.base/jdk.internal.misc
  *          java.management
+ * @build sun.hotspot.WhiteBox
+ * @run main ClassFileInstaller sun.hotspot.WhiteBox
+ * @run main TestGCLogMessages
  */
 
 import jdk.test.lib.process.OutputAnalyzer;
@@ -122,6 +125,7 @@
     public static void main(String[] args) throws Exception {
         new TestGCLogMessages().testNormalLogs();
         new TestGCLogMessages().testWithToSpaceExhaustionLogs();
+        new TestGCLogMessages().testWithInitialMark();
     }
 
     private void testNormalLogs() throws Exception {
@@ -183,6 +187,20 @@
         output.shouldHaveExitValue(0);
     }
 
+    private void testWithInitialMark() throws Exception {
+        ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC",
+                                                                  "-Xmx10M",
+                                                                  "-Xbootclasspath/a:.",
+                                                                  "-Xlog:gc*=debug",
+                                                                  "-XX:+UnlockDiagnosticVMOptions",
+                                                                  "-XX:+WhiteBoxAPI",
+                                                                  GCTestWithInitialMark.class.getName());
+
+        OutputAnalyzer output = new OutputAnalyzer(pb.start());
+        output.shouldContain("Clear Claimed Marks");
+        output.shouldHaveExitValue(0);
+    }
+
     static class GCTest {
         private static byte[] garbage;
         public static void main(String [] args) {
@@ -209,5 +227,13 @@
             System.out.println("Done");
         }
     }
+
+    static class GCTestWithInitialMark {
+        public static void main(String [] args) {
+            sun.hotspot.WhiteBox WB = sun.hotspot.WhiteBox.getWhiteBox();
+            WB.g1StartConcMarkCycle();
+        }
+    }
+
 }