JVM GC的工作非常奇怪

在嘗試了許多不同的JVM GC設置並進行了大量測試之後，我遇到了長時間的主要GC暫停問題，現在我正在使用G1GC JVM GC進行測試。除此之外，我還使用性能監視器收集數據，並且只有正在運行的應用程序（系統服務旁邊......）是GlassFish服務器和我的應用程序。在性能監視器日誌中我沒有發現任何奇怪的東西（CPU使用率約爲5-10％，GC發生時會稍微高一點，內存使用率約爲60％......）。現在是測試的第五天，我注意到以下幾點：JVM GC的工作非常奇怪

enter image description here

直到第二次發生重大（混合）GC一切都很好（小GC大約20毫秒長，GC表現160000M/S，...）。第二個主要的GC花費了大約2秒（長 - 首先花費了150ms，但不是關鍵），之後小GC比以前長得多（參見圖中灰色線代表較小（年輕）GC的持續時間）和GC性能僅爲12000M/s，仍在下降。我想知道爲什麼在第二個主要的GC之後發生這種情況，即使沒有其他應用程序正在運行，並且CPU /內存使用情況與以前相同。我不知道這裏發生了什麼事。我還有一個問題 - 我在不同的PC上運行相同的測試，它具有較少的RAM和較舊的處理器和GC性能，大約爲5000M/s（小型GC大約爲50-100ms），我認爲這是正常的，因爲處理器更糟糕和更少的RAM。奇怪的是，主要的GC在運行3天后還沒有發生，而老一代的增長速度比這裏慢得多，即使設置相同。爲什麼增長要慢得多（這裏兩天約150MB，三天約80MB）？謝謝你所有的答案，我不知道爲什麼GC表現異常（首先它工作正常，然後表現惡化）。

編輯：here是在GCViewer進口，還事件從GCViewer詳細統計完整的GC日誌文件：

enter image description here

日誌中的第三個主要GC：

2015-06-08T08:09:13.123+0200: 572815.533: [GC concurrent-root-region-scan-start] 
2015-06-08T08:09:13.139+0200: 572815.560: [GC concurrent-root-region-scan-end, 0.0271771 secs] 
2015-06-08T08:09:13.139+0200: 572815.560: [GC concurrent-mark-start] 
2015-06-08T08:09:16.302+0200: 572818.721: [GC concurrent-mark-end, 3.1612900 secs] 
2015-06-08T08:09:16.318+0200: 572818.729: [GC remark 572818.729: [Finalize Marking, 0.0002590 secs] 572818.729: [GC ref-proc, 0.4479462 secs] 572819.177: [Unloading, 3.2004912 secs], 3.6499382 secs] 
[Times: user=0.20 sys=0.08, real=3.64 secs]

再次，真正的時間遠遠高於用戶+ sys，卸載階段耗時3秒以上。

來源

2015-06-06 user4341206

請說明什麼顏色的含義，什麼是這個生長線代表。我們可以在這裏看到主要GC的持續時間嗎？如果是的話，他們在哪裏？ – AdamSkywalker

您能提供感興趣的時間跨度的原始GC日誌嗎？也請務必使用'-XX：+ PrintGCDetails'登錄 – the8472

好吧，紫色線是終身（舊）代，藍色線用於堆（所以基本上是年輕一代，因爲它始於老一代線），下面的灰線是次要的GC時間，主要的GC時間（老一代同時收集;不是完整的GC）是兩條黃色線，堆大小下降（首先需要0.1秒，接近2秒）。此圖來自GCViewer應用程序。我會立即上傳原始GC日誌。 – user4341206

如果不深入研究問題，不能給你一個驗證的解釋，但讓我們試試。

您很可能會閱讀G1 GC oracle文檔，並且知道此收集器是爲具有巨大堆的應用程序製作的。它旨在減少主要垃圾收集期間的長時間停頓。

在你的例子中，我們可以看到次要的GC暫停在secong主要GC之後增加。我不知道G1的內部機制，但直覺告訴我，第二大GC是G1分析其性能的一個內部「信號」（他是否實現了吞吐量目標/暫停目標）。所以在我看來，在分析之後，G1決定改變其內部參數。我敢打賭，長時間的小GC停頓表明G1增加了年輕一代的空間。

他爲什麼這麼做？那麼，年齡較大的一代會降低老一代的推廣速度。所以老一代的空間會比較慢。很可能G1試圖阻止下一次主要的GC暫停，直到之前（2秒）。

再說一遍，我不能保證事情沒有深度分析就像我說的那樣工作，但我試着給你指示。

那麼你的「慢」機器，工作3天沒有大的GC暫停 - 如果不知道GC配置和你的應用程序如何工作，真的很難說。我敢打賭，應用程序負載較低。

來源

2015-06-06 18:58:03 AdamSkywalker

謝謝你的回答。你寫的東西是有道理的，爲什麼較小的GC時間更長 - 所以老一代的空間會更慢，我想這也可以從圖中看出來（紫色線比以前增加得更慢）。我沒有想到這一點。是的，我閱讀了所有GC的文檔，我也嘗試了所有這些文檔，但現在除了G1GC（http://stackoverflow.com/questions/30566779/jvm-gc-problems）之外，我都暫停了所有這些文檔。我也使用性能監視器，但我沒有發現任何有用的東西。也許G1GC也試圖阻止像這裏那樣的較慢機器上的主要GC ... – user4341206

但是，如果GC真的決定這樣意味着吞吐量和GC性能會更低（現在GC性能降低大約20％，吞吐量現在只有0.02％）。我真的很想知道下一個主要GC會持續多久。你能否告訴我，如果你建議我不要爲我的服務器使用G1GC，因爲堆的大小很小？如果是這樣，你可以告訴我什麼設置使用CMS來獲得更小的暫停時間（請參閱我的其他問題鏈接我發佈在以前的評論？謝謝... – user4341206

正如@the8472提到的，你可以給G1一個暫停目標我沒有提到答案，因爲我認爲你已經這樣做了，無論如何，我讀了你的第二個問題來獲得更多的細節，對於512 Mb堆，你有很長的主要GC，它不是GC問題我敢打賭，問題是1）在Glassfish服務器2）Windows工具。我會嘗試Tomcat /切換到Linux。當Windows性能計數器顯着減慢應用程序時，我擁有真實世界的體驗。 – AdamSkywalker

由於您好像關注暫停時間，所以我沒有在您的JVM標誌中看到任何暫停時間目標。

您可以通過MaxGCMinorPauseMillis（僅次要）和MaxGCPauseMillis（總體）設置暫停時間目標。

這些只是目標，收集者可能由於各種原因未能滿足他們。默認情況下，GC只允許在GCing上佔用1％的CPU時間。因此，如果未能實現其目標，則可以嘗試設置GCTimeRatio=19，以授予其5％的時間（交換暫停時間的吞吐量）。

在日誌中最長停頓似乎是這樣的一個：

2015-06-05T09:14:51.909+0200: 317539.613: [GC remark 317539.613: [Finalize Marking, 0.0003625 secs] 317539.613: [GC ref-proc, 0.9890475 secs] 317540.602: [Unloading, 0.9739555 secs], 1.9643775 secs]

您可以嘗試打倒基準處理時間-XX:+ParallelRefProcEnabled

來源

2015-06-06 20:06:56 the8472

我試圖用CMS設置MaxGCPauseMillis，但它並沒有幫助（雖然有很長時間的停頓，雖然）...與G1GC MaxGCPauseMillis設置爲默認200毫秒，因此我刪除了MaxGCPauseMillis標誌，因爲我想使用此默認設置。我會嘗試GCTimeRatio = 19，直到現在我還沒有聽說過這個選項。 – user4341206

更新了我的回答 – the8472

謝謝，我也會用這個標誌。如果我理解正確，這應該會減少ref-proc時間 - 班級卸載時間如何，是否還有一個標誌可以減少這個時間呢？ – user4341206

JVM GC的工作非常奇怪

回答

相關問題