G1 garbage collection Ext Root Scanning time increase linearly as application runs

[Ashley Taylor]

Hi,

We are testing the performance of the G1 garbage collection.
Our goal is to be able to remove the full gc pause that eventually happens when we CMS.

We have noticed that the garbage collection pause time starts off really well but over time it keeps climbing.

Looking at the logs we see that the section that is increasing linearly with time is the Ext Root Scanning
Here is a Root Scanning 1 Hour into the application here the total gc pause is around 80ms
  [Ext Root Scanning (ms):  11.5  0.8  1.5  1.8  1.6  4.8  1.2  1.5  1.2  1.4  1.1  1.6  1.2  1.1  1.1  1.1  1.2  1.2
       Avg:   2.1, Min:   0.8, Max:  11.5, Diff:  10.7]


Here is a snap shot after 19 hours. Here the pause is around 280ms
      [Ext Root Scanning (ms):  1.2  184.7  1.3  1.3  1.8  6.3  1.7  1.2  1.5  1.2  1.2  1.1  1.2  1.1  1.2  1.1  1.2  1.2
       Avg:  11.8, Min:   1.1, Max: 184.7, Diff: 183.6]

It seems that some task is linearly increasing with time, which only effects one thread.

After manually firing a full gc the total pause time returns back to around 80ms

After full GC
[Ext Root Scanning (ms):  2.4  1.7  4.5  2.6  4.6  2.1  2.1  1.7  2.1  1.8  1.8  2.2  0.6  0.0  0.0  0.0  0.0  0.0
       Avg:   1.7, Min:   0.0, Max:   4.6, Diff:   4.6]


The test is run with a constant load applied on the application that should hold the machine at around load 6.
We have around 3GB of data within the heap which  will very rarely become garbage, life of these objects would be several hours to days.
the rest will only live for 10s of milliseconds.
The JVM memory usage floats between 4-6gb.

Have checked a thread dump. There are no threads that have very large stack traces.
What could cause this increasing pause durations? Is there any way to get more information out of what that thread is actually trying to do, or any tuning options?


Environment

JVM Arguments
-Xms8g
-Xmx8g
-XX:+UseG1GC
-XX:InitiatingHeapOccupancyPercent=0 #found that having this at zero has greatly reduced the frequency of GC pause over 500ms and the overhead is not that noticeable to our application
-XX:MaxGCPauseMillis=70
-XX:+UseLargePages


Environment
java version "1.7.0_13"
Java(TM) SE Runtime Environment (build 1.7.0_13-b20)
Java HotSpot(TM) 64-Bit Server VM (build 23.7-b01, mixed mode)


Operating System
redhat 5.8 machine.
The machine has 12 cores/ 24threads and 48gb of ram.



Cheers,
Ashley Taylor
Software Engineer
Email: ashley.taylor at sli-systems.com<mailto:ashley.taylor at sli-systems.com>
Website: www.sli-systems.com<http://www.sli-systems.com/>
Blog: blog.sli-systems.com<http://blog.sli-systems.com/>
Podcast: EcommercePodcast.com<http://ecommercepodcast.com/>
Twitter: www.twitter.com/slisystems<http://www.twitter.com/slisystems>

[sli_logo_2011]

-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20130219/2b6e9da6/attachment.html 
-------------- next part --------------
A non-text attachment was scrubbed...
Name: image001.png
Type: image/png
Size: 8602 bytes
Desc: image001.png
Url : http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20130219/2b6e9da6/image001.png