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

[Amit Mishra]

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.

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
argv[51]: -XX:+ParallelRefProcEnabled
argv[52]: -XX:+DisableExplicitGC
argv[53]: -XX:ParallelGCThreads=70
argv[54]: -XX:InitiatingHeapOccupancyPercent=40
argv[55]: -XX:+UnlockDiagnosticVMOptions
argv[56]: -XX:+G1SummarizeRSetStats
argv[57]: -XX:G1SummarizeRSetStatsPeriod=1
argv[58]: -XX:+PerfDisableSharedMem
argv[59]: -XX:+AlwaysPreTouch
argv[60]: -XX:G1HeapRegionSize=32M
argv[61]: -XX:G1RSetRegionEntries=2048
argv[62]: -XX:+UnlockDiagnosticVMOptions



Thanks,
Amit Mishra

-----Original Message-----
From: Thomas Schatzl [mailto:thomas.schatzl at oracle.com] 
Sent: Tuesday, January 24, 2017 13:33
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 Fri, 2017-01-20 at 10:51 +0000, Amit Mishra wrote:
> Thank you very much Thomas, after making said changes RSUpdate time is 
> in control but Scan RS is still high.
>  

  can you summarize your GC parameters again, and also, are these high Scan RS times you observe regular or not?

Did you check with -XX:+G1SummarizeRSetStats - XX:G1SummarizeRSetStatsPeriod=<some value> whether there are still coarsenings?

Could you also please provide a longer snippet of your log file containing a few gcs before and after this occurrence?

Other worthwhile tries could be to fudge with -XX:ParallelGCThreads, either decreasing or increasing them (up to your vcpus) by ten or so to see whether that phase suffers from synchronization issues.

The high scan rs times could maybe also a bit mitigated by increasing G1NewSizePercent to maybe two or three to see whether g1 can avoid large young remembered sets by that (Object copy might go up a bit then though).

It may be easier to think of causes for the issues you are experiencing by having a little bit of more information.

Thanks,
  Thomas

-------------- next part --------------
A non-text attachment was scrubbed...
Name: gcstats.log.3319_cps_24jan
Type: application/octet-stream
Size: 439720 bytes
Desc: gcstats.log.3319_cps_24jan
URL: <http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20170124/b402f3bc/gcstats.log-0001.3319_cps_24jan>