--- old/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp 2014-02-25 14:00:11.324953609 +0100 +++ new/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp 2014-02-25 14:00:11.232953610 +0100 @@ -2361,8 +2361,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(); } @@ -4378,6 +4382,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()) { @@ -4405,6 +4411,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) { --- old/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp 2014-02-25 14:00:11.912953602 +0100 +++ new/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp 2014-02-25 14:00:11.844953603 +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)); --- old/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp 2014-02-25 14:00:12.440953596 +0100 +++ new/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp 2014-02-25 14:00:12.336953598 +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; } --- old/src/share/vm/gc_implementation/g1/g1RemSet.cpp 2014-02-25 14:00:12.840953592 +0100 +++ new/src/share/vm/gc_implementation/g1/g1RemSet.cpp 2014-02-25 14:00:12.772953593 +0100 @@ -462,8 +462,9 @@ 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 @@ -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 --- old/test/gc/g1/TestGCLogMessages.java 2014-02-25 14:00:13.316953587 +0100 +++ new/test/gc/g1/TestGCLogMessages.java 2014-02-25 14:00:13.248953587 +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 { @@ -86,6 +126,21 @@ for (int i = 0; i < 1024; i++) { garbage = new byte[128 * 1024]; } + 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"); } }