JDK-8147121 : Evacuation failure allocation statistics added too late
  • Type: Bug
  • Component: hotspot
  • Sub-Component: gc
  • Affected Version: 9
  • Priority: P4
  • Status: Resolved
  • Resolution: Fixed
  • Submitted: 2016-01-14
  • Updated: 2016-03-15
  • Resolved: 2016-03-02
The Version table provides details related to the release that this issue/RFE will be addressed.

Unresolved : Release in which this issue/RFE will be addressed.
Resolved: Release in which this issue/RFE has been resolved.
Fixed : Release in which this issue/RFE has been fixed. The release containing this fix may be available for download as an Early Access Release or a General Availability Release.

To download the current JDK release, click here.
JDK 9
9 b110Fixed
Related Reports
Blocks :  
JDK-8148376 - Test for PLAB behavior at evacuation failure.
Relates :  
JDK-8030849 - Investigate high fragmentation/waste in some situations during allocation during GC in G1
Description
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.