Statistic for failure used and failure waste is added after adjusting PLAB and logging stats at evacuation failure.
bool
G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
...
post_evacuate_collection_set(evacuation_info, &per_thread_states); - here is invoked
_survivor_evac_stats.adjust_desired_plab_sz();
and
_old_evac_stats.adjust_desired_plab_sz();
which are also used for logging.
And then:
const size_t* surviving_young_words = per_thread_states.surviving_young_words();
free_collection_set(g1_policy()->collection_set(), evacuation_info, surviving_young_words);
There is invoked _old_evac_stats.add_failure_used_and_waste(used_words, HeapRegion::GrainWords - used_words); - which adds statistics to next GC iteration.
and then
log_gc_footer(os::elapsed_counter() - pause_start_counter); which adds info that Evacuation Failure is happened.
Typical log is:
[3,313s][debug ][gc,plab ] GC(22) (allocated = 1 wasted = 0 unused = 0 used = 1 undo_waste = 0 region_end_waste = 0 regions filled = 0 direct_allocated = 0 failure_use
d = 0 failure_waste = 0) (plab_sz = 0 desired_plab_sz = 2489)
[3,313s][debug ][gc,plab ] GC(22) (allocated = 1 wasted = 0 unused = 0 used = 1 undo_waste = 0 region_end_waste = 0 regions filled = 0 direct_allocated = 0 failure_use
d = 0 failure_waste = 0) (plab_sz = 0 desired_plab_sz = 6347)
[3,313s][debug ][gc,phases] GC(22) Parallel Time: 59,1 ms
[3,313s][debug ][gc,phases] GC(22) GC Worker Start: Min: 3245,0, Avg: 3245,0, Max: 3245,0, Diff: 0,0
[3,313s][debug ][gc,phases] GC(22) Ext Root Scanning: Min: 0,2, Avg: 0,2, Max: 0,2, Diff: 0,0, Sum: 0,7
[3,313s][debug ][gc,phases] GC(22) Thread Roots: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,1
[3,313s][debug ][gc,phases] GC(22) StringTable Roots: Min: 0,1, Avg: 0,1, Max: 0,2, Diff: 0,0, Sum: 0,6
[3,313s][debug ][gc,phases] GC(22) Universe Roots: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) JNI Handles Roots: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) ObjectSynchronizer Roots: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) FlatProfiler Roots: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) Management Roots: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) SystemDictionary Roots: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) CLDG Roots: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) JVMTI Roots: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) CM RefProcessor Roots: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) Wait For Strong CLD: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) Weak CLD Roots: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) SATB Filtering: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) Update RS: Min: 45,7, Avg: 48,3, Max: 50,4, Diff: 4,7, Sum: 193,1
[3,313s][debug ][gc,phases] GC(22) Processed Buffers: Min: 3, Avg: 3,8, Max: 4, Diff: 1, Sum: 15
[3,313s][debug ][gc,phases] GC(22) Scan HCC: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) Scan RS: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) Code Root Scanning: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,314s][debug ][gc,phases] GC(22) Object Copy: Min: 8,5, Avg: 10,6, Max: 13,2, Diff: 4,7, Sum: 42,5
[3,314s][debug ][gc,phases] GC(22) Termination: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,314s][debug ][gc,phases] GC(22) Termination Attempts: Min: 1, Avg: 1,0, Max: 1, Diff: 0, Sum: 4
[3,314s][debug ][gc,phases] GC(22) GC Worker Other: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,314s][debug ][gc,phases] GC(22) GC Worker Total: Min: 59,1, Avg: 59,1, Max: 59,1, Diff: 0,0, Sum: 236,4
[3,314s][debug ][gc,phases] GC(22) GC Worker End: Min: 3304,1, Avg: 3304,1, Max: 3304,1, Diff: 0,0
[3,314s][debug ][gc,phases] GC(22) Code Root Fixup: 0,0 ms
[3,314s][debug ][gc,phases] GC(22) Code Root Purge: 0,0 ms
[3,314s][debug ][gc,phases] GC(22) Clear CT: 0,0 ms
[3,314s][debug ][gc,phases] GC(22) Expand Heap After Collection: 0,0 ms
[3,314s][debug ][gc,phases] GC(22) Other: 9,3 ms
[3,314s][debug ][gc,phases] GC(22) Evacuation Failure: 9,0 ms
[3,314s][debug ][gc,phases] GC(22) Choose CSet: 0,0 ms
[3,314s][debug ][gc,phases] GC(22) Ref Proc: 0,1 ms
[3,314s][debug ][gc,phases] GC(22) Ref Enq: 0,0 ms
[3,314s][debug ][gc,phases] GC(22) Redirty Cards: 0,0 ms
[3,314s][debug ][gc,phases] GC(22) Parallel Redirty Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,314s][debug ][gc,phases] GC(22) Redirtied Cards: Min: 0, Avg: 257,0, Max: 358, Diff: 358, Sum: 1028
[3,314s][debug ][gc,phases] GC(22) Humongous Register: 0,0 ms
[3,314s][debug ][gc,phases] GC(22) Humongous Reclaim: 0,0 ms
[3,314s][debug ][gc,phases] GC(22) Free CSet: 0,0 ms
[3,334s][debug ][gc,plab ] GC(23) (allocated = 1 wasted = 0 unused = 0 used = 1 undo_waste = 0 region_end_waste = 0 regions filled = 0 direct_allocated = 0 failure_used = 0 failure_waste = 0) (plab_sz = 0 desired_plab_sz = 622)
[3,334s][debug ][gc,plab ] GC(23) (allocated = 1 wasted = 0 unused = 0 used = 1 undo_waste = 0 region_end_waste = 0 regions filled = 0 direct_allocated = 0 failure_used = 130928 failure_waste = 144) (plab_sz = 0 desired_plab_sz = 1586)
As you can see, failure_used and failure_waste are not 0 for next GC (23), GC event when evacuation failure happened has empty failure_waste and failure_used.
bool
G1CollectedHeap::do_collection_pause_at_safepoint(double target_pause_time_ms) {
...
post_evacuate_collection_set(evacuation_info, &per_thread_states); - here is invoked
_survivor_evac_stats.adjust_desired_plab_sz();
and
_old_evac_stats.adjust_desired_plab_sz();
which are also used for logging.
And then:
const size_t* surviving_young_words = per_thread_states.surviving_young_words();
free_collection_set(g1_policy()->collection_set(), evacuation_info, surviving_young_words);
There is invoked _old_evac_stats.add_failure_used_and_waste(used_words, HeapRegion::GrainWords - used_words); - which adds statistics to next GC iteration.
and then
log_gc_footer(os::elapsed_counter() - pause_start_counter); which adds info that Evacuation Failure is happened.
Typical log is:
[3,313s][debug ][gc,plab ] GC(22) (allocated = 1 wasted = 0 unused = 0 used = 1 undo_waste = 0 region_end_waste = 0 regions filled = 0 direct_allocated = 0 failure_use
d = 0 failure_waste = 0) (plab_sz = 0 desired_plab_sz = 2489)
[3,313s][debug ][gc,plab ] GC(22) (allocated = 1 wasted = 0 unused = 0 used = 1 undo_waste = 0 region_end_waste = 0 regions filled = 0 direct_allocated = 0 failure_use
d = 0 failure_waste = 0) (plab_sz = 0 desired_plab_sz = 6347)
[3,313s][debug ][gc,phases] GC(22) Parallel Time: 59,1 ms
[3,313s][debug ][gc,phases] GC(22) GC Worker Start: Min: 3245,0, Avg: 3245,0, Max: 3245,0, Diff: 0,0
[3,313s][debug ][gc,phases] GC(22) Ext Root Scanning: Min: 0,2, Avg: 0,2, Max: 0,2, Diff: 0,0, Sum: 0,7
[3,313s][debug ][gc,phases] GC(22) Thread Roots: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,1
[3,313s][debug ][gc,phases] GC(22) StringTable Roots: Min: 0,1, Avg: 0,1, Max: 0,2, Diff: 0,0, Sum: 0,6
[3,313s][debug ][gc,phases] GC(22) Universe Roots: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) JNI Handles Roots: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) ObjectSynchronizer Roots: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) FlatProfiler Roots: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) Management Roots: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) SystemDictionary Roots: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) CLDG Roots: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) JVMTI Roots: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) CM RefProcessor Roots: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) Wait For Strong CLD: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) Weak CLD Roots: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) SATB Filtering: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) Update RS: Min: 45,7, Avg: 48,3, Max: 50,4, Diff: 4,7, Sum: 193,1
[3,313s][debug ][gc,phases] GC(22) Processed Buffers: Min: 3, Avg: 3,8, Max: 4, Diff: 1, Sum: 15
[3,313s][debug ][gc,phases] GC(22) Scan HCC: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) Scan RS: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,313s][debug ][gc,phases] GC(22) Code Root Scanning: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,314s][debug ][gc,phases] GC(22) Object Copy: Min: 8,5, Avg: 10,6, Max: 13,2, Diff: 4,7, Sum: 42,5
[3,314s][debug ][gc,phases] GC(22) Termination: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,314s][debug ][gc,phases] GC(22) Termination Attempts: Min: 1, Avg: 1,0, Max: 1, Diff: 0, Sum: 4
[3,314s][debug ][gc,phases] GC(22) GC Worker Other: Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,314s][debug ][gc,phases] GC(22) GC Worker Total: Min: 59,1, Avg: 59,1, Max: 59,1, Diff: 0,0, Sum: 236,4
[3,314s][debug ][gc,phases] GC(22) GC Worker End: Min: 3304,1, Avg: 3304,1, Max: 3304,1, Diff: 0,0
[3,314s][debug ][gc,phases] GC(22) Code Root Fixup: 0,0 ms
[3,314s][debug ][gc,phases] GC(22) Code Root Purge: 0,0 ms
[3,314s][debug ][gc,phases] GC(22) Clear CT: 0,0 ms
[3,314s][debug ][gc,phases] GC(22) Expand Heap After Collection: 0,0 ms
[3,314s][debug ][gc,phases] GC(22) Other: 9,3 ms
[3,314s][debug ][gc,phases] GC(22) Evacuation Failure: 9,0 ms
[3,314s][debug ][gc,phases] GC(22) Choose CSet: 0,0 ms
[3,314s][debug ][gc,phases] GC(22) Ref Proc: 0,1 ms
[3,314s][debug ][gc,phases] GC(22) Ref Enq: 0,0 ms
[3,314s][debug ][gc,phases] GC(22) Redirty Cards: 0,0 ms
[3,314s][debug ][gc,phases] GC(22) Parallel Redirty Min: 0,0, Avg: 0,0, Max: 0,0, Diff: 0,0, Sum: 0,0
[3,314s][debug ][gc,phases] GC(22) Redirtied Cards: Min: 0, Avg: 257,0, Max: 358, Diff: 358, Sum: 1028
[3,314s][debug ][gc,phases] GC(22) Humongous Register: 0,0 ms
[3,314s][debug ][gc,phases] GC(22) Humongous Reclaim: 0,0 ms
[3,314s][debug ][gc,phases] GC(22) Free CSet: 0,0 ms
[3,334s][debug ][gc,plab ] GC(23) (allocated = 1 wasted = 0 unused = 0 used = 1 undo_waste = 0 region_end_waste = 0 regions filled = 0 direct_allocated = 0 failure_used = 0 failure_waste = 0) (plab_sz = 0 desired_plab_sz = 622)
[3,334s][debug ][gc,plab ] GC(23) (allocated = 1 wasted = 0 unused = 0 used = 1 undo_waste = 0 region_end_waste = 0 regions filled = 0 direct_allocated = 0 failure_used = 130928 failure_waste = 144) (plab_sz = 0 desired_plab_sz = 1586)
As you can see, failure_used and failure_waste are not 0 for next GC (23), GC event when evacuation failure happened has empty failure_waste and failure_used.
- blocks
-
JDK-8148376 Test for PLAB behavior at evacuation failure.
-
- Resolved
-
- relates to
-
JDK-8030849 Investigate high fragmentation/waste in some situations during allocation during GC in G1
-
- Open
-