8035654: Add times for evacuation failure handling in "Other" time
Summary: Detailed breakdown of time spent in the evacuation failure handling phases to make the "Other" time roughly correspond to the sum of its parts.
Reviewed-by: jwilhelm, jmasa
--- a/hotspot/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp Mon Mar 17 10:13:27 2014 +0100
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp Mon Mar 17 10:13:42 2014 +0100
@@ -2360,8 +2360,12 @@
};
size_t G1CollectedHeap::recalculate_used() const {
+ double recalculate_used_start = os::elapsedTime();
+
SumUsedClosure blk;
heap_region_iterate(&blk);
+
+ g1_policy()->phase_times()->record_evac_fail_recalc_used_time((os::elapsedTime() - recalculate_used_start) * 1000.0);
return blk.result();
}
@@ -4376,6 +4380,8 @@
void G1CollectedHeap::remove_self_forwarding_pointers() {
assert(check_cset_heap_region_claim_values(HeapRegion::InitialClaimValue), "sanity");
+ double remove_self_forwards_start = os::elapsedTime();
+
G1ParRemoveSelfForwardPtrsTask rsfp_task(this);
if (G1CollectedHeap::use_parallel_gc_threads()) {
@@ -4403,6 +4409,8 @@
}
_objs_with_preserved_marks.clear(true);
_preserved_marks_of_objs.clear(true);
+
+ g1_policy()->phase_times()->record_evac_fail_remove_self_forwards((os::elapsedTime() - remove_self_forwards_start) * 1000.0);
}
void G1CollectedHeap::push_on_evac_failure_scan_stack(oop obj) {
--- a/hotspot/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp Mon Mar 17 10:13:27 2014 +0100
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp Mon Mar 17 10:13:42 2014 +0100
@@ -309,6 +309,16 @@
if (_cur_verify_before_time_ms > 0.0) {
print_stats(2, "Verify Before", _cur_verify_before_time_ms);
}
+ if (G1CollectedHeap::heap()->evacuation_failed()) {
+ double evac_fail_handling = _cur_evac_fail_recalc_used + _cur_evac_fail_remove_self_forwards +
+ _cur_evac_fail_restore_remsets;
+ print_stats(2, "Evacuation Failure", evac_fail_handling);
+ if (G1Log::finest()) {
+ print_stats(3, "Recalculate Used", _cur_evac_fail_recalc_used);
+ print_stats(3, "Remove Self Forwards", _cur_evac_fail_remove_self_forwards);
+ print_stats(3, "Restore RemSet", _cur_evac_fail_restore_remsets);
+ }
+ }
print_stats(2, "Choose CSet",
(_recorded_young_cset_choice_time_ms +
_recorded_non_young_cset_choice_time_ms));
--- a/hotspot/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp Mon Mar 17 10:13:27 2014 +0100
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp Mon Mar 17 10:13:42 2014 +0100
@@ -133,6 +133,10 @@
double _cur_strong_code_root_migration_time_ms;
double _cur_strong_code_root_purge_time_ms;
+ double _cur_evac_fail_recalc_used;
+ double _cur_evac_fail_restore_remsets;
+ double _cur_evac_fail_remove_self_forwards;
+
double _cur_clear_ct_time_ms;
double _cur_ref_proc_time_ms;
double _cur_ref_enq_time_ms;
@@ -230,6 +234,18 @@
_cur_strong_code_root_purge_time_ms = ms;
}
+ void record_evac_fail_recalc_used_time(double ms) {
+ _cur_evac_fail_recalc_used = ms;
+ }
+
+ void record_evac_fail_restore_remsets(double ms) {
+ _cur_evac_fail_restore_remsets = ms;
+ }
+
+ void record_evac_fail_remove_self_forwards(double ms) {
+ _cur_evac_fail_remove_self_forwards = ms;
+ }
+
void record_ref_proc_time(double ms) {
_cur_ref_proc_time_ms = ms;
}
--- a/hotspot/src/share/vm/gc_implementation/g1/g1RemSet.cpp Mon Mar 17 10:13:27 2014 +0100
+++ b/hotspot/src/share/vm/gc_implementation/g1/g1RemSet.cpp Mon Mar 17 10:13:42 2014 +0100
@@ -462,8 +462,9 @@
int into_cset_n_buffers = into_cset_dcqs.completed_buffers_num();
if (_g1->evacuation_failed()) {
+ double restore_remembered_set_start = os::elapsedTime();
+
// Restore remembered sets for the regions pointing into the collection set.
-
if (G1DeferredRSUpdate) {
// If deferred RS updates are enabled then we just need to transfer
// the completed buffers from (a) the DirtyCardQueueSet used to hold
@@ -482,6 +483,8 @@
}
assert(n_completed_buffers == into_cset_n_buffers, "missed some buffers");
}
+
+ _g1->g1_policy()->phase_times()->record_evac_fail_restore_remsets((os::elapsedTime() - restore_remembered_set_start) * 1000.0);
}
// Free any completed buffers in the DirtyCardQueueSet used to hold cards
--- a/hotspot/test/gc/g1/TestGCLogMessages.java Mon Mar 17 10:13:27 2014 +0100
+++ b/hotspot/test/gc/g1/TestGCLogMessages.java Mon Mar 17 10:13:42 2014 +0100
@@ -35,6 +35,11 @@
public class TestGCLogMessages {
public static void main(String[] args) throws Exception {
+ testNormalLogs();
+ testWithToSpaceExhaustionLogs();
+ }
+
+ private static void testNormalLogs() throws Exception {
ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC",
"-Xmx10M",
@@ -74,8 +79,43 @@
output.shouldContain("[Code Root Purge");
output.shouldContain("[Young Free CSet");
output.shouldContain("[Non-Young Free CSet");
+
+ // also check evacuation failure messages once
+ output.shouldNotContain("[Evacuation Failure");
+ output.shouldNotContain("[Recalculate Used");
+ output.shouldNotContain("[Remove Self Forwards");
+ output.shouldNotContain("[Restore RemSet");
+ output.shouldHaveExitValue(0);
+ }
+
+ private static void testWithToSpaceExhaustionLogs() throws Exception {
+ ProcessBuilder pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC",
+ "-Xmx10M",
+ "-Xmn5M",
+ "-XX:+PrintGCDetails",
+ GCTestWithToSpaceExhaustion.class.getName());
+
+ OutputAnalyzer output = new OutputAnalyzer(pb.start());
+ output.shouldContain("[Evacuation Failure");
+ output.shouldNotContain("[Recalculate Used");
+ output.shouldNotContain("[Remove Self Forwards");
+ output.shouldNotContain("[Restore RemSet");
output.shouldHaveExitValue(0);
+ pb = ProcessTools.createJavaProcessBuilder("-XX:+UseG1GC",
+ "-Xmx10M",
+ "-Xmn5M",
+ "-XX:+PrintGCDetails",
+ "-XX:+UnlockExperimentalVMOptions",
+ "-XX:G1LogLevel=finest",
+ GCTestWithToSpaceExhaustion.class.getName());
+
+ output = new OutputAnalyzer(pb.start());
+ output.shouldContain("[Evacuation Failure");
+ output.shouldContain("[Recalculate Used");
+ output.shouldContain("[Remove Self Forwards");
+ output.shouldContain("[Restore RemSet");
+ output.shouldHaveExitValue(0);
}
static class GCTest {
@@ -89,4 +129,19 @@
System.out.println("Done");
}
}
+
+ static class GCTestWithToSpaceExhaustion {
+ private static byte[] garbage;
+ private static byte[] largeObject;
+ public static void main(String [] args) {
+ largeObject = new byte[5*1024*1024];
+ System.out.println("Creating garbage");
+ // create 128MB of garbage. This should result in at least one GC,
+ // some of them with to-space exhaustion.
+ for (int i = 0; i < 1024; i++) {
+ garbage = new byte[128 * 1024];
+ }
+ System.out.println("Done");
+ }
+ }
}