調整GC（CMS）的參數

Question

我正在使用CMS進行GC，但每兩個月後CPU的使用率會非常高。

有一張GC日誌，當情況變得更糟時，您可能會發現很長的STW。

3519696.386: [GC [1 CMS-initial-mark: 8617524K(12582912K)] 17105967K(23907584K), 4.9369140 secs] [Times: user=4.94 sys=0.00, real=4.94 secs] 
3519701.324: [CMS-concurrent-mark-start] 
3519709.419: [CMS-concurrent-mark: 8.096/8.096 secs] [Times: user=16.17 sys=0.00, real=8.09 secs] 
3519709.420: [CMS-concurrent-preclean-start] 
3519709.442: [CMS-concurrent-preclean: 0.023/0.023 secs] [Times: user=0.02 sys=0.00, real=0.02 secs] 
3519709.442: [CMS-concurrent-abortable-preclean-start] 
CMS: abort preclean due to time 3519714.691: [CMS-concurrent-abortable-preclean: 3.345/5.248 secs] [Times: user=3.36 sys=0.00, real=5.25 secs] 
3519714.692: [GC[YG occupancy: 8489655 K (11324672 K)]3519714.692: [Rescan (parallel) , 8.4072250 secs]3519723.099: [weak refs processing, 0.0000190 secs]3519723.099: [scrub string table, 0.0008130 secs] [1 CMS-remark: 8617524K(12582912K)] 17107180K(23907584K), 8.4081940 secs] [Times: user=65.71 sys=0.15, real=8.41 secs] 
3519723.100: [CMS-concurrent-sweep-start] 
3519725.451: [CMS-concurrent-sweep: 2.350/2.350 secs] [Times: user=2.36 sys=0.00, real=2.35 secs] 
3519725.451: [CMS-concurrent-reset-start] 
3519725.478: [CMS-concurrent-reset: 0.028/0.028 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 
3519727.480: [GC [1 CMS-initial-mark: 8617522K(12582912K)] 17107229K(23907584K), 4.9378950 secs] [Times: user=4.94 sys=0.00, real=4.94 secs] 
3519732.418: [CMS-concurrent-mark-start] 

我的GC參數：

java -server -Xmx24g -Xms24g -XX:NewSize=12g -XX:MaxNewSize=12g -XX:+HeapDumpOnOutOfMemoryError -XX:MaxDirectMemorySize=24g -XX:+UseConcMarkSweepGC -XX:+UseCMSCompactAtFullCollection -XX:ReservedCodeCacheSize=128m -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:CMSInitiatingOccupancyFraction=68 

有9個CPU和我的服務器上安裝64G內存。

你能幫忙弄清楚爲什麼每月變得更糟的關鍵點？

Answer 1

好吧，讓我們來詳細瞭解一下。首先我會注意到，所有時間似乎都是用戶，而不是sys，所以主要的嫌疑人是JVM和應用程序。

氣相色譜儀是在老電廠觸發的。容量爲12582912K的8617524K的佔用率。堆使用總量爲17105967K，大小爲23907584K。

初始標記需要5秒。

3519696.386: [GC [1 CMS-initial-mark: 8617524K(12582912K)] 17105967K(23907584K), 4.9369140 secs] [Times: user=4.94 sys=0.00, real=4.94 secs] 

AFAIK初始標記只處理GC根。你可以看到這些是here，但事實是它很多很奇怪。我的第一個懷疑是這是由時間來safepoints的影響，所以也許能：

-XX：+ PrintSafepointStatistics -XX：PrintSafepointStatisticsCount = 1

併發標記階段需要8S

3519709.419: [CMS-concurrent-mark: 8.096/8.096 secs] [Times: user=16.17 sys=0.00, real=8.09 secs] 

這是掃描活物

Preclean比較快。

可中止的預清除在5秒後被取消，AFAIK出現時可用CMSMaxAbortablePrecleanTime配置。挖掘這個選項，我發現在這個階段進行次要收集是可取的，如果不這樣做可能會導致CMS中發生可變的大停頓。增加CMSMaxAbortablePrecleanTime並激活CMSScavengeBeforeRemark。看看這個帖子Jon Masamitsu。

年輕一代在8G和重新掃描了8s，這似乎太多了。再次同樣的評論。 safepoints。

3519714.692：[GC [YG佔用：8489655 K（11324672 K）] 3519714.692：[重新掃描（平行），8.4072250秒] 3519723.099：[弱參處理，0.0000190秒] 3519723.099：[擦洗字符串表，0.0008130秒] [1 CMS-remark：8617524K（12582912K）] 17107180K（23907584K），8.4081940sec] [Times：user = 65.71 sys = 0.15，real = 8.41sec]

注意，在此期間實際增加的大小爲：8617524K

併發掃描的最終清理需要2.35秒，並且堆內容似乎沒有實質性改變。你仍然有大致相同的年輕和堆用法。

所以總結我看到兩點：

• 你堆大，你就到達CMSInitiatingOccupancyFraction和觸發CMS，以及大量的時間似乎對掃描活動對象走了。無論哪種方式，檢查尺寸點的時間，看看是否可以改善。
• GC並沒有真正收取多少，所以你在這些情況下一個很可能：
  • 你要保持大量的長壽命的對象（例如：高速緩存）。在這種情況下，您想要增加CMSInitiatingOccuppancyFraction（正如您所期望的那樣，舊gen會變得非常滿）。但是請注意，您不會宣傳任何中等或短期的物品，因爲這些物品最終（一天或兩個月內）會導致漫長的地理信息系統。那就是：避免老流失。
  • 您正在生成大量短暫居中對象，因此您需要避免宣傳。減少撥款，增加伊甸園。

任何關於你的應用程序的詳細信息，等等肯定會有助於指甲會好些。我希望這會有所幫助。

Answer 2

在你的日誌中，我沒有看到正常的年輕GC。 CMS Stop-the-World階段旨在回收年輕空間收集方面的效果。

3519727.480: [GC [1 CMS-initial-mark: 8617522K(12582912K)] 17107229K(23907584K), 4.9378950 secs] [Times: user=4.94 sys=0.00, real=4.94 secs] 

這裏CMS-initial-mark必須在一個線程中掃描8.6 GiB的年輕空間。如果在年輕的GC年輕人佔領空間後將立即援引，那麼這個數字會小得多。

對於CMS-remark也是如此。

年輕人有很大的年輕的空間，所以你最終在情況，當你舊的空間更頻繁地收集這個年輕的空間。

這裏有幾個選項來補救

• -XX:CMSWaitDuration=3600000讓CMS-initial-mark等待長達一個小時，直到下一個年輕的GC。
• -XX:+CMSScavengeBeforeRemark讓CMS-remark強制年輕的收集產生可預測的暫停時間。其中有平行CMS-initial-mark

更多細節

使用最新的Java 7/8是this article可用。