Need help on G1 GC young gen Update RS and Scan RS pause reduction

Fri Feb 3 11:09:48 UTC 2017

Hi Thomas/team,

I have put all parameters as per your suggestion but somehow the minor gc pauses are still haunting.

Attaching GC logs.

bash-3.2$ grep -i young gcstats.log.10636|cut -d, -f2|awk -F" " '{print $1}'|awk '$1 > 1'
1.1273134
1.1683221
3.5504848
5.2693987

Kindly suggest me next action.

GC parameters

argv[0]: /usr/java1.7/bin/amd64/java
argv[11]: -Xmx48g
argv[12]: -Xms48g
argv[13]: -XX:-EliminateLocks
argv[14]: -Dorg.omg.CORBA.ORBSingletonClass=org.jacorb.orb.ORBSingleton
argv[15]: -Dorg.omg.CORBA.ORBClass=org.jacorb.orb.ORB
argv[18]: -XX:-ReduceInitialCardMarks
argv[19]: -server
argv[21]: -classpath
argv[25]: -Xss1m
argv[26]: -Xoss1m
argv[27]: -XX:NewSize=1024m
argv[28]: -XX:MaxNewSize=3072m
argv[29]: -XX:PermSize=512m
argv[30]: -XX:MaxPermSize=512m
argv[31]: -XX:ReservedCodeCacheSize=128m
argv[32]: -XX:+HeapDumpOnOutOfMemoryError
argv[33]: -XX:+AggressiveOpts
argv[34]: -Dnetworkaddress.cache.ttl=3600
argv[35]: -Dcom.sun.management.jmxremote.port=11883
argv[36]: -Dcom.sun.management.jmxremote.ssl=false
argv[37]: -Dcom.sun.management.jmxremote.authenticate=false
argv[38]: -XX:+UseG1GC
argv[39]: -XX:MaxGCPauseMillis=500
argv[40]: -XX:+PrintFlagsFinal
argv[41]: -XX:G1RSetUpdatingPauseTimePercent=5
argv[42]: -XX:+PrintGCTimeStamps
argv[43]: -XX:+PrintGCDetails
argv[46]: -XX:+UseLargePages
argv[47]: -XX:+MaxFDLimit
argv[51]: -XX:+ParallelRefProcEnabled
argv[52]: -XX:+DisableExplicitGC
argv[53]: -XX:+UnlockDiagnosticVMOptions
argv[54]: -XX:+G1SummarizeRSetStats
argv[55]: -XX:G1SummarizeRSetStatsPeriod=1
argv[56]: -XX:+PerfDisableSharedMem
argv[57]: -XX:+AlwaysPreTouch
argv[58]: -XX:G1HeapRegionSize=32M
argv[59]: -XX:G1RSetRegionEntries=2048
argv[60]: -XX:+UnlockDiagnosticVMOptions

Thanks,
Amit Mishra

-----Original Message-----
From: Amit Mishra 
Sent: Wednesday, January 25, 2017 15:47
To: 'Thomas Schatzl' <thomas.schatzl at oracle.com>; hotspot-gc-use at openjdk.java.net
Subject: RE: Need help on G1 GC young gen Update RS and Scan RS pause reduction

Thank you very much Thomas but based on our CMS experience we do also set NewGen Size same as Max New Gen to avoid shrinking and expansion of new gen in real time which sometimes results in unexplainable pauses, can we do the same thing here as well to set min/max size as 1 G and see if it improves overall situation , next thing I am going to do it to increase InitiatingHeapOccupancyPercent from 40 to 60% which we generally set for CMS.(CMSInitiatingOccupancyFraction)

I am doing these changes and will let you know once again.

Regards,
Amit Mishra

-----Original Message-----
From: Thomas Schatzl [mailto:thomas.schatzl at oracle.com]
Sent: Wednesday, January 25, 2017 15:38
To: Amit Mishra <amit.mishra at redknee.com>; hotspot-gc-use at openjdk.java.net
Subject: Re: Need help on G1 GC young gen Update RS and Scan RS pause reduction

Hi Amit,

On Tue, 2017-01-24 at 10:41 +0000, Amit Mishra wrote:
> Hello Thomas/team,
> 
> I have put parameters as per your suggestion and now update RS time is 
> manageable but Scan RS and Object copy time are high causing pause 
> time to go beyond 1 second while we do expect max pause time to not to 
> be greater than 500 ms.

From the log it seems that the application, at least during startup time, has quite a bit of variance in the amount of objects that are held live from one garbage collection to the other.

It is quite common for applications to behave differently in this area during startup actually.

Since G1 sizes the young gen based on previous measurements, if there is a long stretch of garbage collections that do not need lots of work, it will increase the size of the young gen. However, at some point the application's behavior changes (i.e. the number of objects that need to be preserved during collection), and then these long pauses occur.

If these long garbage collections are really not desired, the only way I see is to decrease the maximum young generation size, not the minimum one as I wrongly suggested.

From that log I can see that the issue only occurs at the beginning of the run; i.e. the second occurrence is at around 310s, all other ~4100s are fine, using a pretty large young gen (~25G).

To avoid these long pauses you would need to set maximum young gen at (I would guess) around 2G. Since this is a global setting for the entire run, this will decrease throughput a lot.

It's up to you to determine whether this is okay in your case.

To set minimum (and maximum) young generation size there are two sets of options:

Set
  -XX:G1NewSizePercent (back) to 1 and
  -XX:G1MaxNewSizePercent to something like 4-5, maybe 3.

As you might have noticed, there is not much wiggle room with percentages in your case any more, but you can also set absolute min/max young gen sizes via

  -XX:NewSize=X , probably something around or above 1G seems good.
  -XX:MaxNewSize=Y , in your case something around 2-3G should work.

[Please make sure that you set both NewSize/MaxNewSize, otherwise you might experience somewhat unexpected behavior]

I also looked through your current settings below.

> Value of pause are as below(attaching complete gc file for you) grep 
> -i young gcstats.log.3319|cut -d, -f2|awk -F" " '{print $1}'|awk
> '$1 > 1'
> 1.4668911
> 1.2109846
> 
> Note : I am observing pauses just after 4-5 minutes after Application 
> restart post new GC parameters implementation.
> 
> GC parameters are as:
> 
> 
> argv[11]: -Xmx48g
> argv[12]: -Xms48g
> argv[13]: -XX:-EliminateLocks
> argv[14]:
> -Dorg.omg.CORBA.ORBSingletonClass=org.jacorb.orb.ORBSingleton
> argv[15]: -Dorg.omg.CORBA.ORBClass=org.jacorb.orb.ORB
> argv[18]: -XX:-ReduceInitialCardMarks
> argv[19]: -server
> argv[21]: -classpath
> argv[24]: -Djava.io.tmpdir=/tmp
> argv[25]: -Xss1m
> argv[26]: -Xoss1m
> argv[27]: -XX:PermSize=512m
> argv[28]: -XX:MaxPermSize=512m
> argv[29]: -XX:ReservedCodeCacheSize=128m
> argv[30]: -XX:+HeapDumpOnOutOfMemoryError
> argv[31]: -XX:+AggressiveOpts
> argv[32]: -Dnetworkaddress.cache.ttl=3600
> argv[33]: -Dcom.sun.management.jmxremote.port=11883
> argv[34]: -Dcom.sun.management.jmxremote.ssl=false
> argv[35]: -Dcom.sun.management.jmxremote.authenticate=false
> argv[36]: -XX:+UseG1GC
> argv[37]: -XX:MaxGCPauseMillis=500
> argv[38]: -XX:+PrintFlagsFinal
> argv[39]: -XX:G1RSetUpdatingPauseTimePercent=5
> argv[40]: -XX:+PrintGCTimeStamps
> argv[41]: -XX:+PrintGCDetails
> argv[43]: -verbose:gc
> argv[44]: -XX:+UseLargePages
> argv[45]: -XX:+MaxFDLimit
> argv[49]: -XX:+UnlockExperimentalVMOptions
> argv[50]: -XX:G1NewSizePercent=2

^--- as suggested above, use either
G1NewSizePercent/G1MaxNewSizePercent or NewSize/MaxNewSize with the suggested values. NewSize/MaxNewSize don't need the UnlockExperimentalVMOptions btw.

> argv[51]: -XX:+ParallelRefProcEnabled
> argv[52]: -XX:+DisableExplicitGC
> argv[53]: -XX:ParallelGCThreads=70

^--- again, the recommendation is to not set ParallelGCThreads to anything above the number of virtual cpus you have. You could try removing this again. 

> argv[54]: -XX:InitiatingHeapOccupancyPercent=40

I think this is a bit too conservative, but I don't have a good value, and maybe it is required later in the run. Independent on whether you cap maximum new size or not, it might be useful for throughput to increase this a lot.

Some plug for JDK9: G1 automatically determines rather good values for that with that version. :)

> argv[55]: -XX:+UnlockDiagnosticVMOptions
> argv[56]: -XX:+G1SummarizeRSetStats
> argv[57]: -XX:G1SummarizeRSetStatsPeriod=1

^--- again, don't use these two production after your testing completes. If you remove them, I think you can also remove UnlockDiagnosticVMOptions.

> argv[58]: -XX:+PerfDisableSharedMem
> argv[59]: -XX:+AlwaysPreTouch
> argv[60]: -XX:G1HeapRegionSize=32M
> argv[61]: -XX:G1RSetRegionEntries=2048
> argv[62]: -XX:+UnlockDiagnosticVMOptions

^--- no need to repeat that at the end.

Hth,
  Thomas

-------------- next part --------------
A non-text attachment was scrubbed...
Name: gcstats.log.10636_cps_3rdfeb.gz
Type: application/x-gzip
Size: 1877106 bytes
Desc: gcstats.log.10636_cps_3rdfeb.gz
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20170203/76762dfc/gcstats.log.10636_cps_3rdfeb-0001.gz>