Uploaded image for project: 'JDK'
  1. JDK
  2. JDK-8147121

Evacuation failure allocation statistics added too late

XMLWordPrintable

    • Icon: Bug Bug
    • Resolution: Fixed
    • Icon: P4 P4
    • 9
    • 9
    • hotspot
    • gc
    • b110

      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.

            tschatzl Thomas Schatzl
            mchernov Michail Chernov
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

              Created:
              Updated:
              Resolved: