零. 簡介

垃圾收集器長時間停頓，表現在 Web 頁面上可能是頁面響應碼 500 之類的服務器錯誤問題，如果是個支付過程可能會導致支付失敗，將造成公司的直接經濟損失，程序員要盡量避免或者說減少此類情況發生。

一. 并發模式失敗（concurrent mode failure）

并發模式失敗日志：

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60

2016-02-21T13:53:07.974+0800: 171467.254: [GC [1 CMS-initial-mark: 1436199K(1560576K)] 1512927K(2504320K), 0.0618140 secs] [Times: user=0.06 sys=0.00, real=0.07 secs]? 2016-02-21T13:53:08.036+0800: 171467.316: [CMS-concurrent-mark-start]? 2016-02-21T13:53:08.377+0800: 171467.657: [CMS-concurrent-mark: 0.340/0.340 secs] [Times: user=2.11 sys=0.15, real=0.34 secs]? 2016-02-21T13:53:08.377+0800: 171467.657: [CMS-concurrent-preclean-start]? 2016-02-21T13:53:08.385+0800: 171467.665: [CMS-concurrent-preclean: 0.008/0.008 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]? 2016-02-21T13:53:08.385+0800: 171467.665: [CMS-concurrent-abortable-preclean-start]? {Heap before GC invocations=88667 (full 45):? ?par new generation?? total 943744K, used 914399K [0x0000000757000000, 0x0000000797000000, 0x0000000797000000)? ??eden space 838912K, 100% used [0x0000000757000000, 0x000000078a340000, 0x000000078a340000)? ??from space 104832K,? 72% used [0x000000078a340000, 0x000000078ecf7d98, 0x00000007909a0000)? ??to?? space 104832K,?? 0% used [0x00000007909a0000, 0x00000007909a0000, 0x0000000797000000)? ?concurrent mark-sweep generation total 1560576K, used 1436199K [0x0000000797000000, 0x00000007f6400000, 0x00000007f6400000)? ?concurrent-mark-sweep perm gen total 159744K, used 78413K [0x00000007f6400000, 0x0000000800000000, 0x0000000800000000)? 2016-02-21T13:53:09.535+0800: 171468.815: [GC2016-02-21T13:53:09.535+0800: 171468.815: [ParNew? Desired survivor size 53673984 bytes, new threshold 6 (max 6)? - age?? 1:??? 7100568 bytes,??? 7100568 total? - age?? 2:??? 4676456 bytes,?? 11777024 total? - age?? 3:??? 8773736 bytes,?? 20550760 total? - age?? 4:??? 7709744 bytes,?? 28260504 total? - age?? 5:?? 10891960 bytes,?? 39152464 total? - age?? 6:?? 11735032 bytes,?? 50887496 total? : 914399K->75616K(943744K), 0.0414860 secs] 2350599K->1517225K(2504320K), 0.0417710 secs] [Times: user=0.32 sys=0.05, real=0.05 secs]? Heap after GC invocations=88668 (full 45):? ?par new generation?? total 943744K, used 75616K [0x0000000757000000, 0x0000000797000000, 0x0000000797000000)? ??eden space 838912K,?? 0% used [0x0000000757000000, 0x0000000757000000, 0x000000078a340000)? ??from space 104832K,? 72% used [0x00000007909a0000, 0x0000000795378128, 0x0000000797000000)? ??to?? space 104832K,?? 0% used [0x000000078a340000, 0x000000078a340000, 0x00000007909a0000)? ?concurrent mark-sweep generation total 1560576K, used 1441609K [0x0000000797000000, 0x00000007f6400000, 0x00000007f6400000)? ?concurrent-mark-sweep perm gen total 159744K, used 78413K [0x00000007f6400000, 0x0000000800000000, 0x0000000800000000)? }? 2016-02-21T13:53:10.202+0800: 171469.482: [CMS-concurrent-abortable-preclean: 1.772/1.817 secs] [Times: user=4.94 sys=0.06, real=1.81 secs]? 2016-02-21T13:53:10.204+0800: 171469.483: [GC[YG occupancy: 497152 K (943744 K)]2016-02-21T13:53:10.204+0800: 171469.483: [Rescan (parallel) , 1.3691900 secs]2016-02-21T13:53:11.573+0800: 171470.853: [weak refs processing, 0.1009300 secs]2016-02-21T13:53:11.674+0800: 1714? 70.954: [class unloading, 0.0153470 secs]2016-02-21T13:53:11.689+0800: 171470.969: [scrub symbol table, 0.0110770 secs]2016-02-21T13:53:11.700+0800: 171470.980: [scrub string table, 0.0016360 secs] [1 CMS-remark: 1441609K(1560576K)] 1938761K(2504320K), 1.5079530 secs] [Ti? mes: user=13.01 sys=0.08, real=1.51 secs]? 2016-02-21T13:53:11.712+0800: 171470.992: [CMS-concurrent-sweep-start]? {Heap before GC invocations=88668 (full 45):? ?par new generation?? total 943744K, used 914528K [0x0000000757000000, 0x0000000797000000, 0x0000000797000000)? ??eden space 838912K, 100% used [0x0000000757000000, 0x000000078a340000, 0x000000078a340000)? ??from space 104832K,? 72% used [0x00000007909a0000, 0x0000000795378128, 0x0000000797000000)? ??to?? space 104832K,?? 0% used [0x000000078a340000, 0x000000078a340000, 0x00000007909a0000)? ?concurrent mark-sweep generation total 1560576K, used 1441606K [0x0000000797000000, 0x00000007f6400000, 0x00000007f6400000)? ?concurrent-mark-sweep perm gen total 159744K, used 78413K [0x00000007f6400000, 0x0000000800000000, 0x0000000800000000)? 2016-02-21T13:53:11.775+0800: 171471.055: [GC2016-02-21T13:53:11.775+0800: 171471.055: [ParNew (promotion failed)? Desired survivor size 53673984 bytes, new threshold 6 (max 6)? - age?? 1:??? 4030872 bytes,??? 4030872 total? - age?? 2:??? 5959704 bytes,??? 9990576 total? - age?? 3:??? 4628680 bytes,?? 14619256 total? - age?? 4:??? 8773080 bytes,?? 23392336 total? - age?? 5:??? 7707144 bytes,?? 31099480 total? - age?? 6:?? 10890224 bytes,?? 41989704 total? : 914528K->907344K(943744K), 1.0312010 secs]2016-02-21T13:53:12.807+0800: 171472.086: [CMS2016-02-21T13:53:14.455+0800: 171473.735: [CMS-concurrent-sweep: 1.684/2.743 secs] [Times: user=3.69 sys=0.36, real=2.74 secs]? ?(concurrent mode failure): 1451903K->475795K(1560576K), 3.9644230 secs] 2356134K->475795K(2504320K), [CMS Perm : 78413K->78413K(159744K)], 4.9959570 secs] [Times: user=5.65 sys=0.34, real=5.00 secs]? Heap after GC invocations=88669 (full 46):? ?par new generation?? total 943744K, used 0K [0x0000000757000000, 0x0000000797000000, 0x0000000797000000)? ??eden space 838912K,?? 0% used [0x0000000757000000, 0x0000000757000000, 0x000000078a340000)? ??from space 104832K,?? 0% used [0x000000078a340000, 0x000000078a340000, 0x00000007909a0000)? ??to?? space 104832K,?? 0% used [0x00000007909a0000, 0x00000007909a0000, 0x0000000797000000)? ?concurrent mark-sweep generation total 1560576K, used 475795K [0x0000000797000000, 0x00000007f6400000, 0x00000007f6400000)? ?concurrent-mark-sweep perm gen total 159744K, used 78413K [0x00000007f6400000, 0x0000000800000000, 0x0000000800000000)? }

兩個原因：

• 在 CMS 啟動過程中，新生代提升速度過快，老年代收集速度趕不上新生代提升速度
• 在 CMS 啟動過程中，老年代碎片化嚴重，無法容納新生代提升上來的大對象

發送這種情況，應用線程將會全部停止（相當于網站這段時間無法響應用戶請求），進行壓縮式垃圾收集（回退到 Serial Old 算法） 解決辦法：

• 新生代提升過快問題：（1）如果頻率太快的話，說明空間不足，首先可以嘗試調大新生代空間和晉升閾值。（2）如果內存有限，可以設置 CMS 垃圾收集在老年代占比達到多少時啟動來減少問題發生頻率（越早啟動問題發生頻率越低，但是會降低吞吐量，具體得多調整幾次找到平衡點），參數如下：如果沒有第二個參數，會隨著 JVM 動態調節 CMS 啟動時間

-XX:CMSInitiatingOccupancyFraction=68 （默認是 68） -XX:+UseCMSInitiatingOccupancyOnly

• 老年代碎片嚴重問題：（1）如果頻率太快或者 Full GC 后空間釋放不多的話，說明空間不足，首先可以嘗試調大老年代空間（2）如果內存不足，可以設置進行 n 次 CMS 后進行一次壓縮式 Full GC，參數如下：

-XX:+UseCMSCompactAtFullCollection：允許在 Full GC 時，啟用壓縮式 GC -XX:CMSFullGCBeforeCompaction=n? ? ?在進行 n 次，CMS 后，進行一次壓縮的 Full GC，用以減少 CMS 產生的碎片

二. 提升失敗（promotion failed）

在 Minor GC 過程中，Survivor Unused?可能不足以容納 Eden 和另一個 Survivor 中的存活對象， 那么多余的將被移到老年代， 稱為過早提升（Premature Promotion）。 這會導致老年代中短期存活對象的增長， 可能會引發嚴重的性能問題。 ?再進一步， 如果老年代滿了， Minor GC 后會進行 Full GC， 這將導致遍歷整個堆， 稱為提升失敗（Promotion Failure）。 提升失敗日志：

1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21

2016-01-07T18:54:26.948+0800: 18782.967: [GC2016-04-07T18:54:26.948+0800: 18782.967: [ParNew (promotion failed)? Desired survivor size 117833728 bytes, new threshold 10 (max 10)? - age?? 1:??? 6141680 bytes,??? 6141680 total? - age?? 2:??? 6337936 bytes,?? 12479616 total? - age?? 3:???? 549120 bytes,?? 13028736 total? - age?? 4:????? 87768 bytes,?? 13116504 total? - age?? 5:???? 221384 bytes,?? 13337888 total? - age?? 6:???? 934168 bytes,?? 14272056 total? - age?? 7:???? 146072 bytes,?? 14418128 total? - age?? 8:???? 626064 bytes,?? 15044192 total? - age?? 9:???? 398000 bytes,?? 15442192 total? - age? 10:???? 429616 bytes,?? 15871808 total? : 1969227K->1929200K(2071808K), 0.7452140 secs]2016-01-07T18:54:27.693+0800: 18783.713: [CMS: 1394703K->632845K(2097152K), 4.0993640 secs] 3301676K->632845K(4168960K), [CMS Perm : 77485K->77473K(159744K)], 4.8450240 secs] [Times: user=5.18 sys=0.56, real=4.84 secs]? Heap after GC invocations=5847 (full 7):? ?par new generation?? total 2071808K, used 0K [0x00000006e9c00000, 0x0000000776400000, 0x0000000776400000)? ??eden space 1841664K,?? 0% used [0x00000006e9c00000, 0x00000006e9c00000, 0x000000075a280000)? ??from space 230144K,?? 0% used [0x0000000768340000, 0x0000000768340000, 0x0000000776400000)? ??to?? space 230144K,?? 0% used [0x000000075a280000, 0x000000075a280000, 0x0000000768340000)? ?concurrent mark-sweep generation total 2097152K, used 632845K [0x0000000776400000, 0x00000007f6400000, 0x00000007f6400000)? ?concurrent-mark-sweep perm gen total 159744K, used 77473K [0x00000007f6400000, 0x0000000800000000, 0x0000000800000000)? }

提升失敗原因：Minor GC 時發現 Survivor 空間放不下，而老年代的空閑也不夠

• 新生代提升太快
• 老年代碎片太多，放不下大對象提升（表現為老年代還有很多空間但是，出現了 promotion failed）

解決方法： 兩條和上面 concurrent mode failure 一樣 另一條，是因為?Survivor Unused 不足，那么可以嘗試調大 Survivor 來嘗試下

三. 在 GC 的時候其他系統活動影響

有些時候系統活動諸如內存換入換出（vmstat）、網絡活動（netstat）、I/O （iostat）在 GC 過程中發生會使 GC 時間變長。 前提是你的服務器上是有 SWAP 區域（用 top、 vmstat 等命令可以看出）用于內存的換入換出，那么操作系統可能會將 JVM 中不活躍的內存頁換到 SWAP 區域用以釋放內存給線程使用（這也透露出內存開始不夠用了）。內存換入換出是一個開銷巨大的磁盤操作，比內存訪問慢好幾個數量級。 看一段 GC 日志：耗時 29.47 秒

1 2 3 4 5 6 7 8

{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]

再看看此時的 vmstat 命令中 si、so 列的數值，如果數值大說明換入換出嚴重，這是內存不足的表現。 解決方法：減少線程，這樣可以降低內存換入換出；增加內存；如果是 JVM 內存設置過大導致線程所用內存不足，則適當調低 -Xmx 和 -Xms。

四. JVM 的 bug

這種原因就根據自己使用的 JDK 版本去查一下，如果是 JVM 的 bug，升級到解決的版本一般就能解決。

五. 總結

? ? ???長時間停頓問題的排查及解決首先需要一定的信息和方法論：

• 詳細的 GC 日志
• 借助 Linux 平臺下的 iostat、vmstat、netstat、mpstat 等命令監控系統情況
• 使用 GCHisto 這個 GC 圖形用戶界面工具，可以統計出 Minor GC 及 Full GC 頻率及時長分布，可參考:http://blog.csdn.net/wenniuwuren/article/details/50760259
• 查看 GC 日志中是否出現了上述的典型內存異常問題（promotion failed, concurrent mode failure），整體來說把上述兩個典型內存異常情況控制在可接受的發生頻率即可，對 CMS 碎片問題來說杜絕以上問題似乎不太可能，只能靠 G1 來解決了
• 是不是 JVM 本身的 bug 導致的
• 如果程序沒問題，參數調了幾次還是不能解決，可能說明流量太大，需要加機器把壓力分散到更多 JVM 上

六. 參考資料

《Java 性能優化權威指南》 https://blogs.oracle.com/poonam/entry/troubleshooting_long_gc_pauses
原文出處：?文牛武人
from:?http://www.importnew.com/22886.html

總結

以上是生活随笔為你收集整理的JVM 调优 —— GC 长时间停顿问题及解决方法的全部內容，希望文章能夠幫你解決所遇到的問題。

如果覺得生活随笔網站內容還不錯，歡迎將生活随笔推薦給好友。