G1GC Strange behavior

Question

I've decided to try G1GC on my Eclipse Mars RC3 for JavaEE developers installation, but I observed a very strange behavior:

As you can see it has run almost 700 FULL GCs for the lifecycle of the application, while only 30 minor GCs. Also I noticed that that the minor GCs are executed when the application is under load - usually when it starts and loads a lot of stuff, while it does full GCs when it's idle. (It was idle most of these 11 hours!) I would expect that when the application does nothing there would be no need for GC, or at leas it would be a minor GC. I also monitored the memory consumption of eclipse - during idle time it never incresed to more that 130-140 MB, so this is one more reason why these full GCs look strange.

Here is my eclipse.ini jvm config:

-server
-Xverify:none
-XX:+AggressiveOpts
-XX:+UseG1GC
-XX:MaxGCPauseMillis=100
-XX:+UseStringDeduplication
-XX:+UseCompressedOops
-XX:+UseCompressedClassPointers
-XX:MaxMetaspaceSize=256m
-Xloggc:/home/svetlin/software/eclipse/gc.log
-XX:+PrintGCDetails
-XX:+PrintGCTimeStamps
-XX:+PrintGCDateStamps 
-XX:+UseGCLogFileRotation
-XX:NumberOfGCLogFiles=5
-XX:GCLogFileSize=20m
-Xms1g
-Xmx1g
                 

Here is the GC log: http://pastebin.com/sVBe4w1A

Java version: OpenJDK 64-Bit Server VM (25.45-b02) for linux-amd64 JRE (1.8.0_45-internal-b14), built on May 17 2015 19:21:01 by "buildd" with gcc 4.9.2

Do you have any idea why G1GC does these full GC when there is obviously not need for GC at all ?

Answer 1

You are suffering from System.gc() calls as can be seen in your log:

2015-06-14T14:56:23.682+0300: 12790,173: [Full GC (System.gc())  121M->118M(1024M), 0,4524898 secs]
   [Eden: 4096,0K(561,0M)->0,0B(561,0M) Survivors: 0,0B->0,0B Heap: 121,7M(1024,0M)->118,2M(1024,0M)], [Metaspace: 135216K->135216K(1177600K)]
 [Times: user=0,71 sys=0,00, real=0,45 secs]
2015-06-14T14:57:23.682+0300: 12850,174: [Full GC (System.gc())  121M->118M(1024M), 0,4732930 secs]
   [Eden: 3072,0K(561,0M)->0,0B(561,0M) Survivors: 0,0B->0,0B Heap: 121,2M(1024,0M)->118,2M(1024,0M)], [Metaspace: 135216K->135216K(1177600K)]
 [Times: user=0,73 sys=0,00, real=0,47 secs]
2015-06-14T14:58:28.684+0300: 12915,175: [Full GC (System.gc())  169M->118M(1024M), 0,4912699 secs]
   [Eden: 52,0M(561,0M)->0,0B(561,0M) Survivors: 0,0B->0,0B Heap: 169,9M(1024,0M)->118,8M(1024,0M)], [Metaspace: 135601K->135601K(1177600K)]
 [Times: user=0,74 sys=0,00, real=0,49 secs]

The System.gc() calls seem to happen once every minute. Do you run any weird plugins that could cause this?

Otherwise, periodic System.gc() calls are often due to the Java RMI runtime calling them. On older Java versions I think this was done every minute but is now increased to once every hour. Regardless, try setting those properties just to be sure:

-Dsun.rmi.dgc.server.gcInterval=999999999
-Dsun.rmi.dgc.client.gcInterval=999999999

as JVM options.

Answer 2

All your full GCs are caused by calls to System.gc(). Your GC log shows exactly 698 of them.

So your Eclipse distro might contain a plugin that causes this number of System.gc() calls. If you cannot fix these calls you might consider using the VM option -XX:+DisableExplicitGC to suppress explicit GCs.