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
--- 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();
+ }
+ }
+
}