一些長時間GC停頓問題的排查及解決辦法

Java架構技術棧發表於2019-03-27
GC

對於許多企業級應用，尤其是OLTP應用來說，長暫停很可能導致服務超時，而對這些執行在JVM上的應用來說，垃圾回收（GC）可能是長暫停最主要的原因。本文將描述一些可能碰到GC長暫停的不同場景，以及說明我們如何排查和解決這些GC停頓的問題。

下面是一些應用在執行時，可能導致GC長暫停的不同場景。

1. 碎片化

這個絕對要排在第一位。因為，正是因為碎片化問題--CMS最致命的缺陷，導致這個統治了OLAP系統十多年的垃圾回收器直接退出歷史舞臺（CMS已經是deprecated，未來版本會被移除，請珍惜那些配置了CMS的JVM吧），面對G1以及最新的ZGC，天生殘(碎)缺(片)的CMS毫無還手之力。

對於CMS，由於老年代的碎片化問題，在YGC時可能碰到晉升失敗（promotion failures，即使老年代還有足夠多有效的空間，但是仍然可能導致分配失敗，因為沒有足夠連續的空間），從而觸發Concurrent Mode Failure，發生會完全STW的FullGC。FullGC相比CMS這種併發模式的GC需要更長的停頓時間才能完成垃圾回收工作，這絕對是Java應用最大的災難之一。

為什麼CMS場景下會有碎片化問題？由於CMS在老年代回收時，採用的是標記清理（Mark-Sweep）演算法，它在垃圾回收時並不會壓縮堆，日積月累，導致老年代的碎片化問題會越來越嚴重，直到發生單執行緒的Mark-Sweep-Compact GC，即FullGC，會完全STW。如果堆比較大的話，STW的時間可能需要好幾秒，甚至十多秒，幾十秒都有可能。

接下來的cms gc日誌，由於碎片率非常高，從而導致promotion failure，然後發生concurrent mode failure，觸發的FullGC總計花了17.1365396秒才完成：

{Heap before GC invocations=7430 (full 24):

parnew 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 <---- High fragmentation

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.4263254secs]

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 <---- No fragmentation

Av. Block Size: 377269492

Tree Height: 1 <---- No fragmentation

Statistics for IndexedFreeLists:

--------------------------------

Total Free Space: 0

Max Chunk Size: 0

Number of Blocks: 0

free=377269492

frag=0.0000 <---- No fragmentation

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):

parnew 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)

}

Total time for which application threads were stopped: 17.5730653 seconds
複製程式碼

一些長時間GC停頓問題的排查及解決辦法2. GC時作業系統的活動

當發生GC時，一些作業系統的活動，比如swap，可能導致GC停頓時間更長，這些停頓可能是幾秒，甚至幾十秒級別。

如果你的系統配置了允許使用swap空間，作業系統可能把JVM程式的非活動記憶體頁移到swap空間，從而釋放記憶體給當前活動程式（可能是作業系統上其他程式，取決於系統排程）。Swapping由於需要訪問磁碟，所以相比實體記憶體，它的速度慢的令人髮指。所以，如果在GC的時候，系統正好需要執行Swapping，那麼GC停頓的時間一定會非常非常非常恐怖。

下面是一段持續了29.48秒的YGC日誌：

{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]
複製程式碼

最後一行[Times: user=915.56, sys=6.35, real=29.48 secs]中real就是YGC時應用真實的停頓時間。

發生YGC的這個時間點，vmstat命令輸出結果如下：

r b w swap free re mf pi po fr de sr s0 s1 s2 s3 in sy cs us sy id

0 0 0 77611960 94847600 55 266 0 0 0 0 0 0 0 0 0 3041 2644 2431 44 8 48

0 0 0 76968296 94828816 79 324 0 18 18 0 0 0 0 1 0 3009 3642 2519 59 13 28

1 0 0 77316456 94816000 389 2848 0 7 7 0 0 0 0 2 0 40062 78231 61451 42 6 53

2 0 0 77577552 94798520 115 591 0 13 13 0 0 13 12 1 0 4991 8104 5413 2 0 98
複製程式碼
一些長時間GC停頓問題的排查及解決辦法YGC總計花了29秒才完成。vmstat命令輸出結果表示，可用swap空間在這個時間段減少了600m。這就意味著，在GC的時候，記憶體中的一些頁被移到了swap空間，這個記憶體頁不一定屬於JVM程式，可能是其他作業系統上的其他程式。

從上面可以看出，作業系統上可用物理內容不足以執行系統上所有的程式，解決辦法就是儘可能執行更少的程式，增加RAM從而提升系統的實體記憶體。在這個例子中，Old區有9G，但是隻使用了1.8G（mark-sweep generation total 9437184K, used 1860619K）。我們可以適當的降低Old區的大小以及整個堆的大小，從而減少記憶體壓力，最小化系統上的應用發生swapping的可能。

除了swapping以外，我們也需要監控瞭解長GC暫停時的任何IO或者網路活動情況等, 可以通過iostat和netstat兩個工具來實現. 我們還能通過mpstat檢視CPU統計資訊，從而弄清楚在GC的時候是否有足夠的CPU資源。

3. 堆空間不夠

如果應用程式需要的記憶體比我們執行的Xmx還要大，也會導致頻繁的垃圾回收，甚至OOM。由於堆空間不足，物件分配失敗，JVM就需要呼叫GC嘗試回收已經分配的空間，但是GC並不能釋放更多的空間，從而又回導致GC，進入惡性迴圈。

應用執行時，頻繁的FullGC會引起長時間停頓，在下面這個例子中，Perm空間幾乎是滿的，並且在Perm區嘗試分配記憶體也都失敗了，從而觸發FullGC：

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]
複製程式碼
一些長時間GC停頓問題的排查及解決辦法同樣的，如果在老年代的空間不夠的話，也會導致頻繁FullGC，這類問題比較好辦，給足老年代和永久代，不要做太摳門的人了，嘿嘿。

4. JVM Bug

什麼軟體都有BUG，JVM也不例外。有時候，GC的長時間停頓就有可能是BUG引起的。例如，下面列舉的這些JVM的BUG，就可能導致Java應用在GC時長時間停頓。

6459113: CMS+ParNew: wildly different ParNew pause times depending on heap shape caused by allocation spread

fixed in JDK 6u1 and 7

6572569: CMS: consistently skewed work distribution indicated in (long) re-mark pauses

fixed in JDK 6u4 and 7

6631166: CMS: better heuristics when combatting fragmentation

fixed in JDK 6u21 and 7

6999988: CMS: Increased fragmentation leading to promotion failure after CR#6631166 got implemented

fixed in JDK 6u25 and 7

6683623: G1: use logarithmic BOT code such as used by other collectors

fixed in JDK 6u14 and 7

6976350: G1: deal with fragmentation while copying objects during GC

fixed in JDK 8
複製程式碼
一些長時間GC停頓問題的排查及解決辦法如果你的JDK正好是上面這些版本，強烈建議升級到更新BUG已經修復的版本。

5. 顯示System.gc呼叫

檢查是否有顯示的System.gc呼叫，應用中的一些類裡，或者第三方模組中呼叫System.gc呼叫從而觸發STW的FullGC，也可能會引起非常長時間的停頓。如下GC日誌所示，Full GC後面的（System）表示它是由呼叫System.GC觸發的FullGC，並且耗時5.75秒：

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]
複製程式碼
一些長時間GC停頓問題的排查及解決辦法如果你使用了RMI，能觀察到固定時間間隔的FullGC，也是由於RMI的實現呼叫了System.gc。這個時間間隔可以通過系統屬性配置：
-Dsun.rmi.dgc.server.gcInterval=7200000

-Dsun.rmi.dgc.client.gcInterval=7200000
複製程式碼
一些長時間GC停頓問題的排查及解決辦法

JDK 1.4.2和5.0的預設值是60000毫秒，即1分鐘；JDK6以及以後的版本，預設值是3600000毫秒，即1個小時。

如果你要關閉通過呼叫System.gc()觸發FullGC，配置JVM引數 -XX:+DisableExplicitGC即可。

那麼如何定位並解決這類問題問題？

  1. 配置JVM引數：-XX:+PrintGCDetails -XX:+PrintHeapAtGC -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps and -XX:+PrintGCApplicationStoppedTime. 如果是CMS，還需要新增-XX:PrintFLSStatistics=2，然後收集GC日誌。因為GC日誌能告訴我們GC頻率，是否長時間停頓等重要資訊。

  2. 使用vmstat, iostat, netstat和mpstat等工具監控系統全方位健康狀況。

  3. 使用GCHisto工具視覺化分析GC日誌，弄明白消耗了很長時間的GC，以及這些GC的出現是否有一定的規律。

  4. 嘗試從GC日誌中能否找出一下JVM堆碎片化的表徵。

  5. 監控指定應用的堆大小是否足夠。

  6. 檢查你執行的JVM版本，是否有與長時間停頓相關的BUG，然後升級到修復問題的最新JDK。

最後

後續會持續更新JVM專題知識及更多架構專題，大家覺得不錯可以點個贊在關注下，以後還會分享更多文章！


相關文章