Seeking assistance with long garbage collection pauses with G1GC

[Steven Toth]

Hello,

We've been struggling with long pauses with the G1GC garbage collector for several weeks now and was hoping to get some assistance.  

We have a Java app running in a standalone JVM on RHEL.  The app listens for data on one or more sockets, queues the data, and has scheduled threads pulling the data off the queue and persisting it. The data is wide, over 700 data elements per record, though all of the data elements are small Strings, Integers, or Longs.

The app runs smoothly for periods of time, sometimes 30 minutes to an hour, but then we experience one or more long garbage collection pauses. The logs indicate the majority of the pause time is spent in the Object Copy time. The long pauses also have high sys time relative to the other shorter collections.

Here are the JVM details:

java version "1.7.0_03" 
Java(TM) SE Runtime Environment (build 1.7.0_03-b04) Java HotSpot(TM) 64-Bit Server VM (build 22.1-b02, mixed mode)

Here are the JVM options:

-XX:MaxPermSize=256m -XX:PermSize=256m -Xms3G -Xmx3G -XX:+UseG1GC -XX:G1HeapRegionSize=32M -XX:-UseGCOverheadLimit \ -Xloggc:logs/gc-STAT5-collector.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps \ -XX:+PrintGCTimeStamps -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=8 -XX:GCLogFileSize=10M -XX:+PrintGCApplicationStoppedTime \ -XX:MaxNewSize=1G -XX:NewSize=1G \ -XX:+PrintGCApplicationStoppedTime -XX:+PrintTenuringDistribution -XX:+PrintAdaptiveSizePolicy

After several iterations of experimenting with an assortment of options (including no options other than -Xms and -Xmx) the aforementioned options have given us the best performance with the fewest amount of long pauses.  However we're still experiencing several dozen garbage collections a day that range from 1-5 seconds.  

The process is taskset to 4 cores (all on the same socket), but is barely using 2 of them. All of the processes on this box are pinned to their own cores (with 0 and 1 unused). The machine has plenty of free memory (20+G) and top shows the process using 2.5G of RES memory.

A day's worth of garbage collection logs are attached, but here is an example of the GC log output with high Object Copy and sys time.  There are numerous GC events comparable to the example below with near identical Eden/Survivors/Heap sizes that take well under 100 millis whereas this example took over 2 seconds. 

[Object Copy (ms): 2090.4 2224.0 2484.0 2160.1 1603.9 2071.2 887.8 1608.1 1992.0 2030.5 1692.5 1583.9 2140.3 1703.0 2174.0 1949.5 1941.1 2190.1 2153.3 1604.1 1930.8 1892.6 1651.9

[Eden: 1017M(1017M)->0B(1016M) Survivors: 7168K->8192K Heap: 1062M(3072M)->47M(3072M)] 

[Times: user=2.24 sys=7.22, real=2.49 secs]

Any help would be greatly appreciated. 

Thanks. 

-Steve


****Confidentiality Note**** This e-mail may contain confidential and or privileged information and is solely for the use of the sender's intended recipient(s). Any review, dissemination, copying, printing or other use of this e-mail by any other persons or entities is prohibited. If you have received this e-mail in error, please contact the sender immediately by reply email and delete the material from any computer.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: gc-STAT5-collector.log.zip
Type: application/x-zip-compressed
Size: 10776 bytes
Desc: gc-STAT5-collector.log.zip
Url : http://mail.openjdk.java.net/pipermail/hotspot-gc-use/attachments/20131211/d479c4b7/gc-STAT5-collector.log.zip