CODEWITHSUNDEEP
javagarbage-collectiong1gc
Neetesh
Neetesh

Reputation: 71

Java heap is full but all regions are empty

I am trying to tune G1 GC. Application run for sometimes then heap gets full but it shows regions of Eden, survivor and old is 0 and the full GC get called to free up space.

Flags I used: Xmx:30G -XX:+UseG1GC -XX:+AlwaysPreTouch -XX:+UseStringDeduplication -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+ExplicitGCInvokesConcurrent -XX:+ParallelRefProcEnabled -XX:MaxGCPauseMillis=200 -XX:ParallelGCThreads=12 -XX:ConcGCThreads=4

GC LOG:

    {Heap before GC invocations=629 (full 0):
 garbage-first heap   total 31457280K, used 31434556K [0x0000000080000000, 0x0000000080807800, 0x0000000800000000)
  region size 8192K, 0 young (0K), 0 survivors (0K)
 Metaspace       used 41962K, capacity 42424K, committed 42956K, reserved 1087488K
  class space    used 4589K, capacity 4749K, committed 4812K, reserved 1048576K
2017-12-07T14:47:41.979+0000: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 100663296 bytes, new threshold 15 (max 15)
 18116.906: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 0, predicted base time: 48.13 ms, remaining time: 151.87 ms, target pause time: 200.00 ms]
 18116.906: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 0 regions, survivors: 0 regions, predicted young region time: 0.00 ms]
 18116.906: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 0 regions, survivors: 0 regions, old: 0 regions, predicted pause time: 48.13 ms, target pause time: 200.00 ms]
2017-12-07T14:47:41.981+0000: [SoftReference, 0 refs, 0.0004177 secs]2017-12-07T14:47:41.981+0000: [WeakReference, 0 refs, 0.0002174 secs]2017-12-07T14:47:41.981+0000: [FinalReference, 0 refs, 0.0003298 secs]2017-12-07T14:47:41.982+0000: [PhantomReference, 0 refs, 0 refs, 0.0004635 secs]2017-12-07T14:47:41.982+0000: [JNI Weak Reference, 0.0000152 secs], 0.0439856 secs]
   [Parallel Time: 1.4 ms, GC Workers: 12]
      [GC Worker Start (ms): Min: 18116906.3, Avg: 18116906.3, Max: 18116906.4, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.5, Avg: 0.6, Max: 0.9, Diff: 0.4, Sum: 6.9]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
         [Processed Buffers: Min: 0, Avg: 0.1, Max: 1, Diff: 1, Sum: 1]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.4]
      [Termination (ms): Min: 0.0, Avg: 0.6, Max: 0.7, Diff: 0.7, Sum: 6.8]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 12]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 1.2, Avg: 1.2, Max: 1.3, Diff: 0.1, Sum: 15.0]
      [GC Worker End (ms): Min: 18116907.6, Avg: 18116907.6, Max: 18116907.6, Diff: 0.0]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [String Dedup Fixup: 39.9 ms, GC Workers: 12]
      [Queue Fixup (ms): Min: 0.0, Avg: 11.3, Max: 18.1, Diff: 18.1, Sum: 135.1]
      [Table Fixup (ms): Min: 21.7, Avg: 27.8, Max: 35.2, Diff: 13.5, Sum: 333.3]
   [Clear CT: 0.1 ms]
   [Other: 2.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.6 ms]
      [Ref Enq: 0.1 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.2 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 0.0B(1536.0M)->0.0B(1536.0M) Survivors: 0.0B->0.0B Heap: 30.0G(30.0G)->30.0G(30.0G)]
Heap after GC invocations=630 (full 0):
 garbage-first heap   total 31457280K, used 31434556K [0x0000000080000000, 0x0000000080807800, 0x0000000800000000)
  region size 8192K, 0 young (0K), 0 survivors (0K)
 Metaspace       used 41962K, capacity 42424K, committed 42956K, reserved 1087488K
  class space    used 4589K, capacity 4749K, committed 4812K, reserved 1048576K
}
 [Times: user=0.49 sys=0.01, real=0.05 secs] 
{Heap before GC invocations=630 (full 0):
 garbage-first heap   total 31457280K, used 31434556K [0x0000000080000000, 0x0000000080807800, 0x0000000800000000)
  region size 8192K, 0 young (0K), 0 survivors (0K)
 Metaspace       used 41962K, capacity 42424K, committed 42956K, reserved 1087488K
  class space    used 4589K, capacity 4749K, committed 4812K, reserved 1048576K
2017-12-07T14:47:42.024+0000: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 100663296 bytes, new threshold 15 (max 15)
 18116.952: [G1Ergonomics (CSet Construction) start choosing CSet, _pending_cards: 0, predicted base time: 47.06 ms, remaining time: 152.94 ms, target pause time: 200.00 ms]
 18116.952: [G1Ergonomics (CSet Construction) add young regions to CSet, eden: 0 regions, survivors: 0 regions, predicted young region time: 0.00 ms]
 18116.952: [G1Ergonomics (CSet Construction) finish choosing CSet, eden: 0 regions, survivors: 0 regions, old: 0 regions, predicted pause time: 47.06 ms, target pause time: 200.00 ms]
2017-12-07T14:47:42.026+0000: [SoftReference, 0 refs, 0.0003988 secs]2017-12-07T14:47:42.027+0000: [WeakReference, 0 refs, 0.0003844 secs]2017-12-07T14:47:42.027+0000: [FinalReference, 0 refs, 0.0002286 secs]2017-12-07T14:47:42.027+0000: [PhantomReference, 0 refs, 0 refs, 0.0004361 secs]2017-12-07T14:47:42.028+0000: [JNI Weak Reference, 0.0000169 secs], 0.0433898 secs]
   [Parallel Time: 1.5 ms, GC Workers: 12]
      [GC Worker Start (ms): Min: 18116952.0, Avg: 18116952.1, Max: 18116952.1, Diff: 0.1]
      [Ext Root Scanning (ms): Min: 0.7, Avg: 0.8, Max: 0.9, Diff: 0.1, Sum: 9.5]
      [Update RS (ms): Min: 0.0, Avg: 0.0, Max: 0.2, Diff: 0.2, Sum: 0.2]
         [Processed Buffers: Min: 0, Avg: 0.1, Max: 1, Diff: 1, Sum: 1]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.5]
      [Termination (ms): Min: 0.0, Avg: 0.4, Max: 0.5, Diff: 0.5, Sum: 5.3]
         [Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 12]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [GC Worker Total (ms): Min: 1.3, Avg: 1.3, Max: 1.4, Diff: 0.1, Sum: 16.1]
      [GC Worker End (ms): Min: 18116953.4, Avg: 18116953.4, Max: 18116953.4, Diff: 0.0]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [String Dedup Fixup: 39.2 ms, GC Workers: 12]
      [Queue Fixup (ms): Min: 0.0, Avg: 11.4, Max: 15.4, Diff: 15.4, Sum: 136.9]
      [Table Fixup (ms): Min: 23.7, Avg: 27.7, Max: 39.1, Diff: 15.4, Sum: 332.3]
   [Clear CT: 0.1 ms]
   [Other: 2.5 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1.6 ms]
      [Ref Enq: 0.1 ms]
      [Redirty Cards: 0.1 ms]
      [Humongous Register: 0.2 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.1 ms]
   [Eden: 0.0B(1536.0M)->0.0B(1536.0M) Survivors: 0.0B->0.0B Heap: 30.0G(30.0G)->30.0G(30.0G)]
Heap after GC invocations=631 (full 0):
 garbage-first heap   total 31457280K, used 31434556K [0x0000000080000000, 0x0000000080807800, 0x0000000800000000)
  region size 8192K, 0 young (0K), 0 survivors (0K)
 Metaspace       used 41962K, capacity 42424K, committed 42956K, reserved 1087488K
  class space    used 4589K, capacity 4749K, committed 4812K, reserved 1048576K
}
 [Times: user=0.49 sys=0.00, real=0.04 secs] 
 18116.996: [G1Ergonomics (Heap Sizing) attempt heap expansion, reason: allocation request failed, allocation request: 16 bytes]
 18116.997: [G1Ergonomics (Heap Sizing) expand the heap, requested expansion amount: 8388608 bytes, attempted expansion amount: 8388608 bytes]
 18116.997: [G1Ergonomics (Heap Sizing) did not expand the heap, reason: heap already fully expanded]
{Heap before GC invocations=631 (full 0):
 garbage-first heap   total 31457280K, used 31434556K [0x0000000080000000, 0x0000000080807800, 0x0000000800000000)
  region size 8192K, 0 young (0K), 0 survivors (0K)
 Metaspace       used 41962K, capacity 42424K, committed 42956K, reserved 1087488K
  class space    used 4589K, capacity 4749K, committed 4812K, reserved 1048576K
2017-12-07T14:47:42.069+0000: [Full GC (Allocation Failure) 2017-12-07T14:48:06.386+0000: [SoftReference, 122 refs, 0.0001069 secs]2017-12-07T14:48:06.386+0000: [WeakReference, 22631 refs, 0.0079235 secs]2017-12-07T14:48:06.394+0000: [FinalReference, 395 refs, 0.0005771 secs]2017-12-07T14:48:06.394+0000: [PhantomReference, 0 refs, 0 refs, 0.0000163 secs]2017-12-07T14:48:06.394+0000: [JNI Weak Reference, 0.0000357 secs] 29G->14G(30G), 53.8180666 secs]
   [Eden: 0.0B(1536.0M)->0.0B(1536.0M) Survivors: 0.0B->0.0B Heap: 30.0G(30.0G)->14.4G(30.0G)], [Metaspace: 41962K->41951K(1087488K)]
Heap after GC invocations=632 (full 1):
 garbage-first heap   total 31457280K, used 15144510K [0x0000000080000000, 0x0000000080807800, 0x0000000800000000)
  region size 8192K, 0 young (0K), 0 survivors (0K)
 Metaspace       used 41951K, capacity 42406K, committed 42956K, reserved 1087488K
  class space    used 4587K, capacity 4746K, committed 4812K, reserved 1048576K
}

Please help me to figure out the problem and how to avoid full GC.

Upvotes: 0

Views: 1855

Answers (1)

the8472
the8472

Reputation: 43052

This is probably OpenJDK bug 8165150, meaning you are experiencing noop young gen collections before a Full GC. This is suboptimal, but as long as the full GC occurs and can free memory the JVM should recover.

You can avoid this problem by ensuring that there is enough free space in the heap, that your application does not leak and a that concurrent cycle is initiated before it fills up, e.g. by tuning the IHOP.

Your life set size after the Full GC is only 14GiB, so a an IHOP around 60% may help.

Upvotes: 1

Related Questions