From 410f7cf3ac956a9c65235b23cc078e775112ce95 Mon Sep 17 00:00:00 2001 From: tschatzl Date: Mon, 24 Mar 2014 15:30:46 +0100 Subject: [PATCH] 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 --- .../gc_implementation/g1/g1CollectedHeap.cpp | 8 +++ .../gc_implementation/g1/g1GCPhaseTimes.cpp | 10 ++++ .../gc_implementation/g1/g1GCPhaseTimes.hpp | 16 ++++++ .../vm/gc_implementation/g1/g1RemSet.cpp | 5 +- test/gc/g1/TestGCLogMessages.java | 55 +++++++++++++++++++ 5 files changed, 93 insertions(+), 1 deletion(-) diff --git a/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp b/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp index 6f343621a..9db4117fc 100644 --- a/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp +++ b/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp @@ -2360,8 +2360,12 @@ public: }; 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(); } @@ -4394,6 +4398,8 @@ void G1CollectedHeap::finalize_for_evac_failure() { 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()) { @@ -4421,6 +4427,8 @@ void G1CollectedHeap::remove_self_forwarding_pointers() { } _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) { diff --git a/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp b/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp index 6b6a2cf7f..0c784a7dd 100644 --- a/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp +++ b/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp @@ -309,6 +309,16 @@ void G1GCPhaseTimes::print(double pause_time_sec) { 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)); diff --git a/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp b/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp index 7868a8972..e574777d3 100644 --- a/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp +++ b/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp @@ -133,6 +133,10 @@ class G1GCPhaseTimes : public CHeapObj { 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 @@ class G1GCPhaseTimes : public CHeapObj { _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; } diff --git a/src/share/vm/gc_implementation/g1/g1RemSet.cpp b/src/share/vm/gc_implementation/g1/g1RemSet.cpp index a11be17ef..68d280301 100644 --- a/src/share/vm/gc_implementation/g1/g1RemSet.cpp +++ b/src/share/vm/gc_implementation/g1/g1RemSet.cpp @@ -463,8 +463,9 @@ void G1RemSet::cleanup_after_oops_into_collection_set_do() { int into_cset_n_buffers = into_cset_dcqs.completed_buffers_num(); if (_g1->evacuation_failed()) { - // Restore remembered sets for the regions pointing into the collection set. + 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 @@ -483,6 +484,8 @@ void G1RemSet::cleanup_after_oops_into_collection_set_do() { } 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 diff --git a/test/gc/g1/TestGCLogMessages.java b/test/gc/g1/TestGCLogMessages.java index bf45db412..451506641 100644 --- a/test/gc/g1/TestGCLogMessages.java +++ b/test/gc/g1/TestGCLogMessages.java @@ -35,6 +35,11 @@ import com.oracle.java.testlibrary.OutputAnalyzer; 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 @@ public class TestGCLogMessages { 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 @@ public class TestGCLogMessages { 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"); + } + } } -- GitLab