G1GC not auto adjusting NewSize (Long GC times)

Question

My application is G1GC with a memory size of 45GB. I am seeing long GC times. While investigating, I found that only 5% of the heap for young generation which is being filled up very frequently leading to frequent collections. Moreover, although most of the heap is empty, GC is not adjusting the "NewSize" and it is constant at 5% and most of the heap is reserved (but unused) for "Tenured Generation". G1GC documentations suggests that NewSize is adjusted automatically during every GC collection.

https://docs.oracle.com/javase/9/gctuning/garbage-first-garbage-collector.htm#JSGCT-GUID-C268549C-7D95-499C-9B24-A6670B44E49C

Question:-

Default values for "G1MaxNewSizePercent" and G1NewSizePercent are 60% and 5% respectively, why GC is not adjusting the size automatically and why is it stuck at 5%. http://www.oracle.com/technetwork/articles/java/g1gc-1984535.html
Do I need to do something special for GC to start auto adjusting?
Why most of the heap got reserved for the tenured generation at first place?

Following is the GCViewer snapshot

JVM flags

sudo -u ./jcmd [PID] VM.flags

-XX:+AlwaysPreTouch
-XX:CICompilerCount=15 
-XX:ConcGCThreads=6 
-XX:G1HeapRegionSize=16777216 
-XX:GCLogFileSize=10485760 
-XX:+HeapDumpOnOutOfMemoryError 
-XX:InitialHeapSize=48318382080 
-XX:MarkStackSize=4194304 
-XX:MaxHeapSize=48318382080 
-XX:MaxNewSize=28991029248 
-XX:MinHeapDeltaBytes=16777216 
-XX:NumberOfGCLogFiles=5 
-XX:-OmitStackTraceInFastThrow 
-XX:OnOutOfMemoryError=/bin/kill -9 %p 
-XX:+PrintGC -XX:+PrintGCApplicationStoppedTime 
-XX:+PrintGCDateStamps 
-XX:+PrintGCDetails 
-XX:+PrintGCTimeStamps 
-XX:+PrintTenuringDistribution 
-XX:+UseG1GC 
-XX:+UseGCLogFileRotation

GC LOG snapshot

     2018-02-26T21:44:51.808+0000: 3964500.472: Total time for which application threads were stopped: 1.6367601 seconds, Stopping threads took: 0.0013929 seconds
2018-02-26T21:45:30.402+0000: 3964539.066: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 150994944 bytes, new threshold 15 (max 15)
- age   1:    9990048 bytes,    9990048 total
- age   2:    3134528 bytes,   13124576 total
- age   3:    3096528 bytes,   16221104 total
- age   4:    3214512 bytes,   19435616 total
- age   5:    1927232 bytes,   21362848 total
- age   6:    1268760 bytes,   22631608 total
- age   7:     717648 bytes,   23349256 total
- age   8:     439232 bytes,   23788488 total
- age   9:     246680 bytes,   24035168 total
- age  10:     167256 bytes,   24202424 total
- age  11:      49928 bytes,   24252352 total
- age  12:      54232 bytes,   24306584 total
- age  13:      58920 bytes,   24365504 total
- age  14:      56704 bytes,   24422208 total
- age  15:      43744 bytes,   24465952 total
, 1.5579128 secs]
   [Parallel Time: 34.2 ms, GC Workers: 25]
      [GC Worker Start (ms): Min: 3964539071.6, Avg: 3964539071.9, Max: 3964539072.2, Diff: 0.6]
      [Ext Root Scanning (ms): Min: 9.4, Avg: 11.8, Max: 14.3, Diff: 4.9, Sum: 294.7]
      [Update RS (ms): Min: 6.1, Avg: 9.8, Max: 19.2, Diff: 13.1, Sum: 245.1]
         [Processed Buffers: Min: 14, Avg: 162.4, Max: 668, Diff: 654, Sum: 4059]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.3]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.0]
      [Object Copy (ms): Min: 2.3, Avg: 9.4, Max: 11.7, Diff: 9.4, Sum: 235.3]
      [Termination (ms): Min: 1.0, Avg: 2.4, Max: 4.3, Diff: 3.3, Sum: 60.0]
         [Termination Attempts: Min: 78, Avg: 230.8, Max: 303, Diff: 225, Sum: 5769]
      [GC Worker Other (ms): Min: 0.1, Avg: 0.1, Max: 0.3, Diff: 0.2, Sum: 3.6]
      [GC Worker Total (ms): Min: 33.2, Avg: 33.6, Max: 33.9, Diff: 0.7, Sum: 839.0]
      [GC Worker End (ms): Min: 3964539105.5, Avg: 3964539105.5, Max: 3964539105.6, Diff: 0.1]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.7 ms]
   [Other: 1522.9 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1510.4 ms]
      [Ref Enq: 0.1 ms]
      [Redirty Cards: 0.4 ms]
      [Humongous Register: 0.1 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.5 ms]
   [Eden: 2256.0M(2256.0M)->0.0B(2256.0M) Survivors: 48.0M->48.0M Heap: 5703.0M(45.0G)->3449.3M(45.0G)]
 [Times: user=1.62 sys=0.34, real=1.56 secs]
2018-02-26T21:45:31.963+0000: 3964540.627: Total time for which application threads were stopped: 1.5935495 seconds, Stopping threads took: 0.0057849 seconds
2018-02-26T21:45:40.547+0000: 3964549.211: Total time for which application threads were stopped: 0.0743828 seconds, Stopping threads took: 0.0024422 seconds
2018-02-26T21:45:51.083+0000: 3964559.748: Total time for which application threads were stopped: 0.0173656 seconds, Stopping threads took: 0.0011296 seconds
2018-02-26T21:46:06.646+0000: 3964575.310: [GC pause (G1 Evacuation Pause) (young)
Desired survivor size 150994944 bytes, new threshold 15 (max 15)
- age   1:   10282952 bytes,   10282952 total
- age   2:    3420512 bytes,   13703464 total
- age   3:    2663240 bytes,   16366704 total
- age   4:    2506952 bytes,   18873656 total
- age   5:    1215280 bytes,   20088936 total
- age   6:     555136 bytes,   20644072 total
- age   7:     542128 bytes,   21186200 total
- age   8:     336520 bytes,   21522720 total
- age   9:     173096 bytes,   21695816 total
- age  10:     117656 bytes,   21813472 total
- age  11:      44280 bytes,   21857752 total
- age  12:      45728 bytes,   21903480 total
- age  13:      53928 bytes,   21957408 total
- age  14:      58128 bytes,   22015536 total
- age  15:      56704 bytes,   22072240 total
, 1.2324057 secs]
   [Parallel Time: 39.1 ms, GC Workers: 25]
      [GC Worker Start (ms): Min: 3964575316.2, Avg: 3964575317.5, Max: 3964575318.7, Diff: 2.4]
      [Ext Root Scanning (ms): Min: 9.0, Avg: 12.4, Max: 16.1, Diff: 7.0, Sum: 311.0]
      [Update RS (ms): Min: 2.1, Avg: 8.2, Max: 16.4, Diff: 14.3, Sum: 206.0]
         [Processed Buffers: Min: 24, Avg: 149.3, Max: 246, Diff: 222, Sum: 3732]
      [Scan RS (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.4]
      [Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.1]
      [Object Copy (ms): Min: 6.9, Avg: 12.5, Max: 15.5, Diff: 8.6, Sum: 311.5]
      [Termination (ms): Min: 2.6, Avg: 3.9, Max: 4.7, Diff: 2.1, Sum: 96.9]
         [Termination Attempts: Min: 179, Avg: 384.9, Max: 448, Diff: 269, Sum: 9622]
      [GC Worker Other (ms): Min: 0.0, Avg: 0.5, Max: 0.7, Diff: 0.7, Sum: 12.4]
      [GC Worker Total (ms): Min: 36.3, Avg: 37.5, Max: 38.7, Diff: 2.4, Sum: 938.3]
      [GC Worker End (ms): Min: 3964575354.9, Avg: 3964575355.0, Max: 3964575355.1, Diff: 0.1]
   [Code Root Fixup: 0.1 ms]
   [Code Root Purge: 0.0 ms]
   [Clear CT: 0.6 ms]
   [Other: 1192.6 ms]
      [Choose CSet: 0.0 ms]
      [Ref Proc: 1180.2 ms]
      [Ref Enq: 0.1 ms]
      [Redirty Cards: 0.4 ms]
      [Humongous Register: 1.8 ms]
      [Humongous Reclaim: 0.0 ms]
      [Free CSet: 0.3 ms]
   [Eden: 2256.0M(2256.0M)->0.0B(2256.0M) Survivors: 48.0M->48.0M Heap: 5705.3M(45.0G)->3439.2M(45.0G)]
 [Times: user=1.86 sys=0.00, real=1.23 secs]
2018-02-26T21:46:07.880+0000: 3964576.545: Total time for which application threads were stopped: 1.2492396 seconds, Stopping threads took: 0.0013324 seconds
2018-02-26T21:46:41.430+0000: 3964610.095: Total time for which application threads were stopped: 0.0331942 seconds, Stopping threads took: 0.0043586 seconds
2018-02-26T21:46:44.246+0000: 3964612.910: [GC pause (G1 Evacuation Pause) (young)

Laxman Prabhu · Accepted Answer · 2018-02-27T07:19:32.610

You are spending most of the time in Reference Processing. Almost all of your GC Time.

[Ref Proc: 1180.2 ms] .

Reference Processing stage involves processing any soft/weak/final/phantom/JNI references discovered by the STW reference processor.

The Eden(Young Gen) Memory is determined by Heuristics collected by the G1 collector on every GC. It adjusts the Young Gen according to the GC history so that the maximum pause time matches your target pause time. If your target pause time is short, the eden memory can be short.

If nothing is set, the target pause time by default is 200ms. I am guessing because your Ref Proc time is so large, G1 keeps your eden region size small to give you the best possible pause time.

You should investigate what references are on the heap and see if this is normal for your application to produce these many references. Fix that and your Eden memory should increase automatically.

You should try JDK 11. We had the same problem with references and the problem is completely gone with JDK 11 — cocorossello, Oct 15 '18 at 15:49

G1GC not auto adjusting NewSize (Long GC times)

1 Answers1