【翻譯】JMV GC 停頓時(shí)間過長(zhǎng)問題排查

原文地址：Troubleshooting Long GC Pauses
個(gè)人興趣翻譯，能力有限，如有疏漏，請(qǐng)幫忙指正: http://www.itdecent.cn/u/e2917208bd0d。

較短的時(shí)間停頓是很多企業(yè)應(yīng)用程序運(yùn)行時(shí)最主要的目標(biāo)，尤其對(duì)于一些過長(zhǎng)的響應(yīng)延遲可能會(huì)導(dǎo)致事務(wù)超時(shí)的事務(wù)系統(tǒng)。對(duì)于運(yùn)行在JVM上面的一些系統(tǒng)，垃圾回收（GC）有時(shí)會(huì)造成較長(zhǎng)時(shí)間的停頓。
在本文中，我會(huì)介紹幾種我們可能會(huì)遇到的GC導(dǎo)致長(zhǎng)時(shí)間停頓的場(chǎng)景，并分析我們應(yīng)該如何診斷和排查這些問題。

原因

下面是應(yīng)用程序運(yùn)行時(shí)可能會(huì)導(dǎo)致GC長(zhǎng)時(shí)間停頓的幾種場(chǎng)景。

1、JVM 堆（heap）中有碎片

Java 堆中的碎片可能會(huì)引起頻繁的GC活動(dòng)，并且有可能引起GC長(zhǎng)時(shí)間停頓。這種情況在CMS垃圾收集器并發(fā)收集時(shí)老年代空間沒有啟用碎片壓縮時(shí)出現(xiàn)的可能性更大一點(diǎn)。
CMS垃圾收集器工作時(shí)，由于老年代中存在碎片，年輕代收集時(shí)會(huì)遇到“promotion failures”問題，進(jìn)而引起“Concurrent Mode Failure”失敗，最終會(huì)觸發(fā)比并發(fā)收集耗時(shí)更長(zhǎng)的Full GC的stop-the-world行為。
這些碎片可能會(huì)導(dǎo)致直接在老年代分配對(duì)象失敗，因而引起Full GC，盡管老年代還有很多剩余空間。頻繁的碎片導(dǎo)致對(duì)象分配失敗會(huì)造成頻繁的Full GC，從而從總體上增加了應(yīng)用的停頓時(shí)間。
下面這段CMS收集器的日志顯示出在老年代有大量的碎片，導(dǎo)致新生代回收時(shí)出現(xiàn)“promotion failures”異常，并且引起CMS回收時(shí)“Concurrent Mode Failure”。進(jìn)而引起一次耗時(shí)達(dá)到17.1365396s的Full GC。

{Heap before GC invocations=7430 (full 24):
par new
generation total 134400K, used 121348K
[0x53000000, 0x5c600000, 0x5c600000)
eden space
115200K, 99% used [0x53000000,
0x5a07e738, 0x5a080000)
from space
19200K, 32% used [0x5a080000,
0x5a682cc0, 0x5b340000)
to space 19200K, 0% used [0x5b340000, 0x5b340000, 0x5c600000)
concurrent
mark-sweep generation total 2099200K, used 1694466K [0x5c600000, 0xdc800000, 0xdc800000)
concurrent-mark-sweep perm gen total 409600K,
used 186942K [0xdc800000, 0xf5800000, 0xfbc00000)
10628.167: [GC Before GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 103224160
Max Chunk Size:
5486
Number of Blocks: 57345
Av. Block Size: 1800
Tree Height:
36
Statistics for IndexedFreeLists:
--------------------------------
Total Free Space: 371324
Max Chunk Size:
254
Number of Blocks: 8591 <---- High fragmentation
Av. Block Size: 43
free=103595484
frag=1.0000 <---- High fragmentation
Before GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 0
Max Chunk Size: 0
Number of Blocks: 0
Tree Height: 0
Statistics for IndexedFreeLists:
--------------------------------
Total Free Space: 0
Max Chunk Size: 0
Number of Blocks: 0
free=0 frag=0.0000
10628.168: [ParNew (promotion failed)
Desired survivor size 9830400 bytes, new threshold 1 (max
1)
- age 1: 4770440 bytes, 4770440 total
: 121348K->122157K(134400K), 0.4263254 secs]10628,594:
[CMS10630.887: [CMS-concurrent-mark: 7.286/8.682 secs] [Times: user=14.81
sys=0.34, real=8.68 secs] (concurrent mode failure):
1698044K->625427K(2099200K), 17.1365396 secs]
1815815K->625427K(2233600K), [CMS Perm : 186942K->180711K(409600K)]After
GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 377269492
Max Chunk Size:
377269492
Number of Blocks: 1
Av. Block Size: 377269492
Tree Height: 1
Statistics for IndexedFreeLists:
--------------------------------
Total Free Space: 0
Max Chunk Size: 0
Number of Blocks: 0
free=377269492
frag=0.0000
After GC:
Statistics for BinaryTreeDictionary:
------------------------------------
Total Free Space: 0
Max Chunk Size: 0
Number of Blocks: 0
Tree Height: 0
Statistics for IndexedFreeLists:
--------------------------------
Total Free Space: 0
Max Chunk Size: 0
Number of Blocks: 0
free=0 frag=0.0000
, 17.5645589 secs] [Times: user=17.82 sys=0.06,
real=17.57 secs]
Heap after GC invocations=7431 (full 25):
par new
generation total 134400K, used 0K
[0x53000000, 0x5c600000, 0x5c600000)
eden space
115200K, 0% used [0x53000000,
0x53000000, 0x5a080000)
from space
19200K, 0% used [0x5b340000,
0x5b340000, 0x5c600000)
to space 19200K, 0% used [0x5a080000, 0x5a080000, 0x5b340000)
concurrent
mark-sweep generation total 2099200K, used 625427K [0x5c600000, 0xdc800000,
0xdc800000)
concurrent-mark-sweep perm gen total 409600K,
used 180711K [0xdc800000, 0xf5800000, 0xfbc00000)
}

應(yīng)用程序停頓的時(shí)間總共有17.5730653s。

2、GC期間系統(tǒng)在做其他操作

有些時(shí)候垃圾回收期間發(fā)生的一些系統(tǒng)操作也會(huì)引起GC停頓時(shí)間變長(zhǎng)，比如swap空間交換或者網(wǎng)絡(luò)活動(dòng)。這些都有可能導(dǎo)致幾秒到幾分鐘的停頓。
如果你的系統(tǒng)配置了使用swap空間，那么操作系統(tǒng)就會(huì)把JVM進(jìn)程一些不活躍的空間轉(zhuǎn)移到虛擬內(nèi)存，以便可以釋放內(nèi)存空間給當(dāng)前進(jìn)程的活躍線程或系統(tǒng)的其他進(jìn)程。由于需要操作速度比物理內(nèi)存慢很多的硬盤，因此swap空間交換是代價(jià)非常昂貴的操作。所以，如果在GC期間系統(tǒng)需要swap空間交換，那么GC就會(huì)持續(xù)更長(zhǎng)的時(shí)間。
下面是一段新生代GC持續(xù)了29.47s的日志：

{Heap before GC invocations=132 (full 0):
par new
generation total 2696384K, used
2696384K [0xfffffffc20010000, 0xfffffffce0010000, 0xfffffffce0010000)
eden space
2247040K, 100% used [0xfffffffc20010000, 0xfffffffca9270000,
0xfffffffca9270000)
from space
449344K, 100% used [0xfffffffca9270000, 0xfffffffcc4940000, 0xfffffffcc4940000)
to space 449344K, 0% used [0xfffffffcc4940000,
0xfffffffcc4940000, 0xfffffffce0010000)
concurrent
mark-sweep generation total 9437184K, used 1860619K [0xfffffffce0010000,
0xffffffff20010000, 0xffffffff20010000)
concurrent-mark-sweep perm gen total 1310720K,
used 511451K [0xffffffff20010000, 0xffffffff70010000, 0xffffffff70010000)
2013-07-17T03:58:06.601-0700: 51522.120: [GC Before GC: :
2696384K->449344K(2696384K), 29.4779282 secs]
4557003K->2326821K(12133568K) ,29.4795222 secs] [Times: user=915.56
sys=6.35, real=29.48 secs]

相應(yīng)的系統(tǒng)‘vmstat’命令在03:58輸出的日志如下：

kthr memory page disk faults cpu
r b w swap free re mf pi
po fr de sr s0 s1 s2 s3 in sy cs us sy id
20130717_035806 0 0 0 77611960 94847600 55 266 0 0 0 0 0
0 0 0 0 3041 2644 2431 44 8 48
20130717_035815 0 0 0 76968296 94828816 79 324 0 18 18 0
0 0 0 1 0 3009 3642 2519 59 13 28
20130717_035831 1 0 0 77316456 94816000 389 2848 0 7 7 0
0 0 0 2 0 40062 78231 61451 42 6 53
20130717_035841 2 0 0 77577552 94798520 115 591 0 13 13 0
0 13 12 1 0 4991 8104 5413 2 0 98

這次Minor GC持續(xù)了約29s。相對(duì)應(yīng)的在此期間系統(tǒng)‘vmstat’命令輸出信息顯示系統(tǒng)可用的swap空間減少了差不多600M。這意味著在GC期間一些當(dāng)前進(jìn)程非必須的內(nèi)存頁從物理內(nèi)存中被移到了swap空間。
從上面的信息可以看出，系統(tǒng)的物理內(nèi)存不夠所有運(yùn)行在系統(tǒng)上面的進(jìn)程使用。解決的方式就是運(yùn)行盡量少的進(jìn)程，同時(shí)增加更多的物理內(nèi)存。上面的日志展示永久代配置的最大使用空間是9G，但是僅有1.8G使用了物理內(nèi)存。因此有效的解決方式是減少堆空間的大小，減少物理內(nèi)存的壓力，盡量避免或者減少swap空間的交換活動(dòng)。
除了swap空間交換，我們也要監(jiān)控在GC期間是否有IO操作或者網(wǎng)絡(luò)活動(dòng)。這兩項(xiàng)可以使用‘iostat’和‘netstat’工具監(jiān)控。同樣使用‘mpstat’工具輸出CPU統(tǒng)計(jì)信息觀察GC停頓期間是否有可用的CPU資源也非常有用。

3、過小的堆空間配置

如果應(yīng)用程序占用的空間超過我們?yōu)镴VM設(shè)置的最大堆空間，那么就會(huì)導(dǎo)致頻繁的GC操作。因?yàn)槎芽臻g過小，為對(duì)象分配空間的請(qǐng)求失敗，JVM就會(huì)調(diào)用GC操作，釋放空間。但是由于每次GC并不能夠釋放足夠的空間，因此越來越多的對(duì)象分配失敗的請(qǐng)求會(huì)引起更多的GC調(diào)用。
對(duì)應(yīng)用程序而言，Full GC會(huì)引起更長(zhǎng)的應(yīng)用停頓。如下面的日志所示，因?yàn)橛谰么臻g基本已經(jīng)滿了，所以在永久代分配對(duì)象的操作失敗，觸發(fā)了一次Full GC：

166687.013: [Full GC [PSYoungGen:
126501K->0K(922048K)] [PSOldGen: 2063794K->1598637K(2097152K)]
2190295K->1598637K(3019200K) [PSPermGen: 165840K->164249K(166016K)],
6.8204928 secs] [Times: user=6.80 sys=0.02, real=6.81 secs]
166699.015: [Full GC [PSYoungGen:
125518K->0K(922048K)] [PSOldGen: 1763798K->1583621K(2097152K)]
1889316K->1583621K(3019200K) [PSPermGen: 165868K->164849K(166016K)],
4.8204928 secs] [Times: user=4.80 sys=0.02, real=4.81 secs]

類似的因老年代剩余空間過小導(dǎo)致的對(duì)象在老年代分配失敗或者“promotion failures”也會(huì)觸發(fā)頻繁的Full GC。
這種問題的解決方案就是根據(jù)應(yīng)用平均使用空間的大小合理配置JVM堆的大小。

4、JVM的bug

JVM的一些bug也會(huì)引起GC長(zhǎng)時(shí)間停頓，比如下面列出的一些JVM bug就有可能造成Java程序長(zhǎng)時(shí)間的GC停頓：

如果你正在運(yùn)行的JVM版本包含以上bug，請(qǐng)升級(jí)到其他修復(fù)版本。

5、顯示調(diào)用系統(tǒng)GC

請(qǐng)檢查一下是否有顯示調(diào)用系統(tǒng)GC的操作。應(yīng)用程序或者第三方模塊的某些類對(duì)System.gc()方法的調(diào)用會(huì)引起stop-the-world的Full GC操作。這些顯示的系統(tǒng)GC調(diào)用也會(huì)造成長(zhǎng)時(shí)間停頓。

164638.058: [Full GC (System) [PSYoungGen: 22789K->0K(992448K)]
[PSOldGen: 1645508K->1666990K(2097152K)] 1668298K->1666990K(3089600K)
[PSPermGen: 164914K->164914K(166720K)], 5.7499132 secs] [Times: user=5.69
sys=0.06, real=5.75 secs]

如果你正在使用RMI框架，并觀察到有固定頻率的Full GC發(fā)生，那么就是這些RMI框架的實(shí)現(xiàn)類在定時(shí)觸發(fā)System.gc()方法調(diào)用。觸發(fā)間隔可以通過下面兩個(gè)系統(tǒng)配置項(xiàng)配置：

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

這兩個(gè)配置項(xiàng)的默認(rèn)值在JDK 1.4.2版本和5.0版本是60s，在JDK 6及以后的版本中，都是1小時(shí)。如果你想禁止因System.gc()方法調(diào)用引起的Full GC操作，可以在應(yīng)用運(yùn)行時(shí)增加這個(gè)-XX:+DisableExplicitGCJVM參數(shù)。

如何解決這個(gè)問題

1、收集GC日志時(shí)配置上這些參數(shù)：-XX:+PrintGCDetails -XX:+PrintHeapAtGC -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintGCApplicationStoppedTime。如果是CMS收集器，再增加-XX:PrintFLSStatistics=2這個(gè)配置。
這些GC日志可以給我們有關(guān)GC停頓的頻率和性質(zhì)的詳細(xì)信息，即他們可以告訴我們GC停頓是發(fā)生在新生代還是老年代，以及停頓發(fā)生的頻率等相關(guān)信息。

2、用Solaris和其他Linux平臺(tái)上的‘iostat’、‘netstat’、‘mpstat’、‘vmstat’等系統(tǒng)工具或者Windows操作系統(tǒng)上的進(jìn)程監(jiān)視器和任務(wù)管理器從全局監(jiān)控系統(tǒng)的運(yùn)行情況。

3、使用GCHisto工具使GC日志可視化，發(fā)現(xiàn)哪些GC操作耗時(shí)較長(zhǎng)，并發(fā)現(xiàn)這些GC的一些共性。

4、通過GC日志發(fā)現(xiàn)是否在Java堆中存在碎片。

5、監(jiān)控配置的Java 堆空間是否夠應(yīng)用程序使用。

6、檢查你的應(yīng)用程序是否運(yùn)行在包含已知的會(huì)導(dǎo)致GC長(zhǎng)時(shí)間停頓的bug的JVM版本。如果是，就升級(jí)到新的修復(fù)版本。

?著作權(quán)歸作者所有,轉(zhuǎn)載或內(nèi)容合作請(qǐng)聯(lián)系作者
【社區(qū)內(nèi)容提示】社區(qū)部分內(nèi)容疑似由AI輔助生成，瀏覽時(shí)請(qǐng)結(jié)合常識(shí)與多方信息審慎甄別。
平臺(tái)聲明：文章內(nèi)容（如有圖片或視頻亦包括在內(nèi)）由作者上傳并發(fā)布，文章內(nèi)容僅代表作者本人觀點(diǎn)，簡(jiǎn)書系信息發(fā)布平臺(tái)，僅提供信息存儲(chǔ)服務(wù)。

相關(guān)閱讀更多精彩內(nèi)容

友情鏈接更多精彩內(nèi)容