G1GC奇怪行为

Question

我决定在我的JavaEE开发环境中的Eclipse Mars RC3上尝试使用G1GC，但我观察到了一个非常奇怪的行为：

如您所见，它已经运行了近700次FULL GCs，而仅有30次minor GCs。此外，我注意到当应用程序处于负载状态时通常会执行minor GCs - 通常是在启动并加载大量内容时，而在空闲时则进行full GCs。（这11个小时中它大部分时间都是空闲的！）我期望当应用程序什么也不做时就没有必要进行GC，或者至少只需要进行一次minor GC。我还监测了Eclipse的内存消耗 - 在空闲时间内它从未增加到超过130-140 MB，这是这些full GCs看起来很奇怪的另一个原因。

这是我的eclipse.ini jvm配置：

-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
                 

这里是GC日志：http://pastebin.com/sVBe4w1A Java版本：OpenJDK 64位服务器VM（25.45-b02），用于Linux-amd64 JRE（1.8.0_45-internal-b14），由“buildd”于2015年5月17日19:21:01使用gcc 4.9.2构建。

您有没有想法，为什么G1GC会在明显不需要进行GC的情况下执行这些full GC？

- Svetlin Zarev

Answer 1

您在日志中可以看到您正在受到 System.gc() 调用的影响。

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]

System.gc()调用似乎每隔一分钟发生一次。你是否运行了任何可能导致这种情况的奇怪插件？

否则，定期的System.gc()调用通常是由Java RMI运行时调用的。 在旧的Java版本中，我认为这是每分钟执行一次，但现在增加到每小时执行一次。 无论如何，为确保请尝试设置这些属性：

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

作为JVM选项。

- K Erlandsson

---

我应该手动查看日志，而不是使用GCViewer。不过很有趣的是，哪个组件在调用System.gc()以及为什么要这样做。 - Svetlin Zarev

Answer 2

你所有的full GC都是由调用System.gc()引起的。你的GC日志中显示一共发生了698次。

因此，你的Eclipse发布版本可能包含一个插件，导致这些数量的System.gc()调用。如果你无法解决这些调用，你可以考虑使用VM选项-XX:+DisableExplicitGC来抑制显式GC。

- Stefan Ferstl