G1GC Strange behavior
I decided to try G1GC on my Eclipse Mars RC3 to install JavaEE developers, but I noticed very strange behavior:
As you can see, it ran almost 700 FULL GCs for the application lifecycle, while only 30 minor GCs. Also I noticed that minor GCs are performed when the application is under load - usually when it starts up and loads a lot of stuff, while it does full GCs when it is idle. (It has been idle for most of those 11 hours!) I would expect that when the application does nothing, there will be no need for GC, or in lease it will be a small GC. I also monitored the memory consumption of eclipse - it never went above 130-140MB during idle, so this is another 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 using "buildd" with gcc 4.9. 2
Do you have any ideas why G1GC does these full GCs when no GC is obviously required?
source to share
You are suffering from calls System.gc()
that 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]
Calls seem to be System.gc()
happening every minute. Are you running any strange plugins that might cause this?
Otherwise, periodic calls System.gc()
are often due to Java RMI calls. On older versions of Java, I think this was done every minute, but now it increased to one hour every hour. Regardless, try setting these properties to be sure:
-Dsun.rmi.dgc.server.gcInterval=999999999
-Dsun.rmi.dgc.client.gcInterval=999999999
as JVM parameters.
source to share
All your full GCs are caused by calls System.gc()
. Your GC log shows exactly 698 of them.
Thus, your Eclipse distribution may contain a plugin that makes this number of calls System.gc()
. If you are unable to fix these calls, you can use the VM option -XX:+DisableExplicitGC
to suppress explicit GCs.
source to share