G1 collector stays on small young-generation size longer than expected after concurrent cycle

[Wolfgang Pedot]

Hello,

I have spend quite some time tuning G1 for my use case now and I am 
generally pleased with the results (ignoring PermGen for now). I do have 
a question of understanding about the automatic sizing of 
young-generation though, here are parts of my GC-log (only 
Date/Timestamp and sizes):

2013-10-28T15:55:56.323+0100: 21273.211: [GC pause (young)
    [Eden: 4032.0M(4032.0M)->0.0B(3960.0M) Survivors: 400.0M->432.0M 
Heap: 13.5G(14.6G)->9834.7M(14.6G)]
2013-10-28T15:56:18.653+0100: 21295.541: [GC pause (young)
    [Eden: 3960.0M(3960.0M)->0.0B(3944.0M) Survivors: 432.0M->416.0M 
Heap: 13.5G(14.6G)->9868.7M(14.6G)]
2013-10-28T15:57:00.727+0100: 21337.615: [GC pause (young)
    [Eden: 3944.0M(3944.0M)->0.0B(3880.0M) Survivors: 416.0M->416.0M 
Heap: 13.5G(14.6G)->9931.4M(14.6G)]
2013-10-28T15:57:43.165+0100: 21380.053: [GC pause (young)
    [Eden: 3880.0M(3880.0M)->0.0B(3808.0M) Survivors: 416.0M->432.0M 
Heap: 13.5G(14.6G)->9987.4M(14.6G)]
2013-10-28T15:58:04.731+0100: 21401.619: [GC pause (young)
    [Eden: 3808.0M(3808.0M)->0.0B(3784.0M) Survivors: 432.0M->408.0M 
Heap: 13.5G(14.6G)->10036.7M(14.6G)]

Up to here everything is normal, heap usage reaches the threshold.


2013-10-28T15:58:33.923+0100: 21430.811: [GC pause (young) (initial-mark)
    [Eden: 3784.0M(3784.0M)->0.0B(3728.0M) Survivors: 408.0M->408.0M 
Heap: 13.5G(14.6G)->10096.0M(14.6G)]
2013-10-28T15:58:36.234+0100: 21433.122: [GC concurrent-cleanup-end, 
0.0004450 secs]
2013-10-28T15:59:19.111+0100: 21475.998: [GC pause (young)
    [Eden: 3728.0M(3728.0M)->0.0B(360.0M) Survivors: 408.0M->384.0M 
Heap: 12.9G(14.6G)->9559.3M(14.6G)]

Now mixed collects start and young-gen size is reduced to facilitate 
collection of old-regions (I guess):

2013-10-28T15:59:22.778+0100: 21479.666: [GC pause (mixed)
    [Eden: 360.0M(360.0M)->0.0B(648.0M) Survivors: 384.0M->96.0M Heap: 
9919.3M(14.6G)->8419.4M(14.6G)]
2013-10-28T15:59:30.652+0100: 21487.540: [GC pause (mixed)
    [Eden: 648.0M(648.0M)->0.0B(648.0M) Survivors: 96.0M->96.0M Heap: 
9067.4M(14.6G)->7480.0M(14.6G)]
2013-10-28T15:59:38.671+0100: 21495.559: [GC pause (mixed)
    [Eden: 648.0M(648.0M)->0.0B(648.0M) Survivors: 96.0M->96.0M Heap: 
8128.0M(14.6G)->7263.3M(14.6G)]

During the last collect G1 decided there is no more need for mixed:

  21495.811: [G1Ergonomics (Mixed GCs) do not continue mixed GCs, 
reason: reclaimable percentage not over threshold, candidate old 
regions: 203 regions, reclaimable: 784279232 bytes (4.99 %), threshold: 
5.00 %]

Now I would expect the young-generation size to increase again but as 
you can see below that does not happen for another 11 collects:


2013-10-28T15:59:44.685+0100: 21501.573: [GC pause (young)
    [Eden: 648.0M(648.0M)->0.0B(648.0M) Survivors: 96.0M->96.0M Heap: 
7911.3M(14.6G)->7293.7M(14.6G)]
2013-10-28T15:59:51.136+0100: 21508.024: [GC pause (young)
    [Eden: 648.0M(648.0M)->0.0B(648.0M) Survivors: 96.0M->96.0M Heap: 
7941.7M(14.6G)->7391.1M(14.6G)]
2013-10-28T15:59:58.723+0100: 21515.610: [GC pause (young)
    [Eden: 648.0M(648.0M)->0.0B(648.0M) Survivors: 96.0M->96.0M Heap: 
8039.1M(14.6G)->7477.8M(14.6G)]
2013-10-28T16:00:01.284+0100: 21518.172: [GC pause (young)
    [Eden: 648.0M(648.0M)->0.0B(648.0M) Survivors: 96.0M->96.0M Heap: 
8125.8M(14.6G)->7548.1M(14.6G)]
2013-10-28T16:00:05.597+0100: 21522.485: [GC pause (young)
    [Eden: 648.0M(648.0M)->0.0B(648.0M) Survivors: 96.0M->96.0M Heap: 
8196.1M(14.6G)->7582.0M(14.6G)]
2013-10-28T16:00:06.595+0100: 21523.483: [GC pause (young)
    [Eden: 648.0M(648.0M)->0.0B(648.0M) Survivors: 96.0M->96.0M Heap: 
8230.0M(14.6G)->7629.0M(14.6G)]
2013-10-28T16:00:07.417+0100: 21524.305: [GC pause (young)
    [Eden: 648.0M(648.0M)->0.0B(648.0M) Survivors: 96.0M->96.0M Heap: 
8277.0M(14.6G)->7634.9M(14.6G)]
2013-10-28T16:00:09.160+0100: 21526.048: [GC pause (young)
    [Eden: 648.0M(648.0M)->0.0B(648.0M) Survivors: 96.0M->96.0M Heap: 
8282.9M(14.6G)->7659.5M(14.6G)]
2013-10-28T16:00:10.519+0100: 21527.407: [GC pause (young)
    [Eden: 648.0M(648.0M)->0.0B(648.0M) Survivors: 96.0M->96.0M Heap: 
8307.5M(14.6G)->7675.9M(14.6G)]
2013-10-28T16:00:11.861+0100: 21528.749: [GC pause (young)
    [Eden: 648.0M(648.0M)->0.0B(648.0M) Survivors: 96.0M->96.0M Heap: 
8323.9M(14.6G)->7724.2M(14.6G)]
2013-10-28T16:00:13.625+0100: 21530.513: [GC pause (young)
    [Eden: 648.0M(648.0M)->0.0B(648.0M) Survivors: 96.0M->96.0M Heap: 
8372.2M(14.6G)->7774.0M(14.6G)]
2013-10-28T16:00:19.956+0100: 21536.844: [GC pause (young)
    [Eden: 648.0M(648.0M)->0.0B(6368.0M) Survivors: 96.0M->88.0M Heap: 
8422.0M(14.6G)->7768.2M(14.6G)]
2013-10-28T16:01:04.700+0100: 21581.588: [GC pause (young)
    [Eden: 6368.0M(6368.0M)->0.0B(6208.0M) Survivors: 88.0M->176.0M 
Heap: 13.8G(14.6G)->7858.4M(14.6G)]

Predicted and real pause-times for those collects are well below the 
pause-target (~120ms vs 300ms) and mixed collects have stopped, is there 
another reason to keep young-gen small during that time? I can provide 
the full log if it helps.

Relevant parameters:

/opt/jdk1.7.0_45/bin/java -Xmx15000M -Xms15000M  -XX:+UseG1GC 
-XX:MaxGCPauseMillis=300 -XX:G1HeapRegionSize=8m 
-XX:+ParallelRefProcEnabled -XX:InitiatingHeapOccupancyPercent=64 
-XX:G1ReservePercent=5 -XX:G1MixedGCLiveThresholdPercent=70 
-XX:G1HeapWastePercent=5

I have been playing around with the percentages because we had to many 
inefficient concurrent cycles and heap is rather tight.
I manually set the region-size to 8MB because the heap-size is close to 
16GB.

any Ideas?
Wolfgang Pedot