# HG changeset patch # User tschatzl # Date 1395047622 -3600 # Node ID e541bff96524c525de7616422cc5c834a9f03a5a # Parent 13a3b426f64d2aca5c03c7262180968cddc2cb10 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 diff -r 13a3b426f64d -r e541bff96524 hotspot/src/share/vm/gc_implementation/g1/g1CollectedHeap.cpp --- 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) { diff -r 13a3b426f64d -r e541bff96524 hotspot/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.cpp --- 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)); diff -r 13a3b426f64d -r e541bff96524 hotspot/src/share/vm/gc_implementation/g1/g1GCPhaseTimes.hpp --- 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; } diff -r 13a3b426f64d -r e541bff96524 hotspot/src/share/vm/gc_implementation/g1/g1RemSet.cpp --- 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 diff -r 13a3b426f64d -r e541bff96524 hotspot/test/gc/g1/TestGCLogMessages.java --- 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"); + } + } }