JVM堆內存很富足時，為什麼經常連續發生兩次full GC？

12-25

jvm大神你好，我遇到一個問題，請幫忙分析下，是什麼原因導致的full gc：
現象很奇怪，經常性出現兩次連續full gc，發生full gc時堆剩餘內存還很富足

環境：
1.java版本
java version "1.7.0_79"
Java(TM) SE Runtime Environment (build 1.7.0_79-b15)
Java HotSpot(TM) 64-Bit Server VM (build 24.79-b02, mixed mode)

2.啟動參數
java -server -Xms4096m -Xmx4096m -Xmn1536m -Xss256K -XX:PermSize=128m -XX:MaxPermSize=256m -XX:ReservedCodeCacheSize=64m -XX:+UseParallelGC -XX:+UseParallelOldGC -XX:ParallelGCThreads=2 -XX:+UseBiasedLocking -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintTenuringDistribution -XX:+PrintGCApplicationStoppedTime

3.gc日誌（發生full gc前後的gc日誌）
2016-11-22T10:01:27.012+0800: 403507.772: Total time for which application threads were stopped: 0.0003780 seconds
2016-11-22T10:13:14.071+0800: 404214.832: [GC
Desired survivor size 117964800 bytes, new threshold 1 (max 15)
[PSYoungGen: 1333185K-&>10727K(1446912K)] 1452262K-&>131813K(4068352K), 0.0215750 secs] [Times: user=0.03 sys=0.00, real=0.03 secs]
2016-11-22T10:13:14.093+0800: 404214.854: Total time for which application threads were stopped: 0.0225360 seconds
此處省略類似的日誌...
2016-11-22T10:13:14.102+0800: 404214.863: Total time for which application threads were stopped: 0.0002030 seconds
2016-11-22T10:13:14.238+0800: 404214.999: [GC
Desired survivor size 113246208 bytes, new threshold 1 (max 15)
[PSYoungGen: 23905K-&>5252K(1462272K)] 144991K-&>130159K(4083712K), 0.0078300 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2016-11-22T10:13:14.246+0800: 404215.007: [Full GC [PSYoungGen: 5252K-&>0K(1462272K)] [ParOldGen: 124906K-&>121506K(2621440K)] 130159K-&>121506K(4083712K) [PSPermGen: 42425K-&>42351K(131072K)], 0.2893160 secs] [Times: user=0.51 sys=0.00, real=0.29 secs]
2016-11-22T10:13:14.535+0800: 404215.296: Total time for which application threads were stopped: 0.2980130 seconds
2016-11-22T10:14:14.512+0800: 404275.273: [GC
Desired survivor size 108003328 bytes, new threshold 1 (max 15)
[PSYoungGen: 18345K-&>5378K(1457664K)] 139852K-&>126885K(4079104K), 0.0060680 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]
2016-11-22T10:14:14.519+0800: 404275.279: [Full GC [PSYoungGen: 5378K-&>0K(1457664K)] [ParOldGen: 121506K-&>121043K(2621440K)] 126885K-&>121043K(4079104K) [PSPermGen: 42351K-&>42351K(131072K)], 0.1845710 secs] [Times: user=0.32 sys=0.00, real=0.19 secs]
2016-11-22T10:14:14.703+0800: 404275.464: Total time for which application threads were stopped: 0.1917300 seconds

這是針對HotSpot VM的問題。如果是很頻繁的發生這種奇怪的full GC的話，多半是三種外部請求觸發的GC的一種：

System.gc()
Heap inspection (例如jmap -histo:live）
GC locker（由JNI critical系API觸發。請跳傳送門：現代 JVM 的垃圾回收裡面還有「引用計數」嗎？）

題主用的是Oracle JDK7，既然題主說這個現象「經常性出現」，那麼要知道是上述三種情況的哪一種，最好的辦法是用：

jstat -gccause

命令來看看到底觸發GC的原因是什麼。

如果發現是System.gc()，那麼可以另外想辦法來尋找是誰在調用System.gc()；
如果發現是heap inspection，那麼要檢查一下有沒有豬隊友在有事沒事就跑諸如jmap -histo:live命令；
如果發現是GC locker，那…得看看題主的程序依賴的JNI庫都幹了什麼了。

Oracle JDK8的話，打開PrintGCDetails之後GC log里會自帶GC cause信息，就不用這麼麻煩了。

啟動參數添加 -XX:+DisableExplicitGC，屏蔽掉System.GC試試，如果FullGC 不存在了，那麼就是代碼主動調用的FullGC。

-XX:+DisableExplicitGC 禁用系統觸發gc。
有些框架代碼里也會使用System.GC

rmi server默認自動一小時gc一次，看看是不是這種情況？