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

[Thomas Schatzl]

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