前言

本文將通過(guò)一個(gè)真實(shí)的生產(chǎn)環(huán)境案例，詳細(xì)展示如何系統(tǒng)性地排查和解決JVM垃圾收集問(wèn)題。這個(gè)案例涵蓋了從問(wèn)題發(fā)現(xiàn)、分析診斷到最終解決的完整過(guò)程，對(duì)于理解JVM調(diào)優(yōu)實(shí)戰(zhàn)具有重要的參考價(jià)值。

系統(tǒng)背景

我們的服務(wù)是一個(gè)高并發(fā)的微服務(wù)應(yīng)用，技術(shù)棧如下：

• 應(yīng)用框架：Spring Boot
• 指標(biāo)采集：Micrometer
• 監(jiān)控系統(tǒng)：Datadog

說(shuō)明：Micrometer 作為應(yīng)用監(jiān)控的門(mén)面庫(kù)，支持多種監(jiān)控系統(tǒng)，包括：AppOptics、Atlas、Datadog、Dynatrace、Elastic、Ganglia、Graphite、Humio、Influx、Instana、JMX、KairosDB、New Relic、Prometheus、SignalFx、Stackdriver、StatsD、Wavefront 等。
詳細(xì)信息請(qǐng)參考： https://micrometer.io/docs

問(wèn)題現(xiàn)象

問(wèn)題描述

在日常監(jiān)控中，我們發(fā)現(xiàn)一個(gè)服務(wù)節(jié)點(diǎn)出現(xiàn)了嚴(yán)重的GC性能問(wèn)題：

• 最大GC暫停時(shí)間：經(jīng)常超過(guò)400ms
• 峰值暫停時(shí)間：達(dá)到546ms（發(fā)生時(shí)間：02月04日 09:20:00）

GC暫停時(shí)間監(jiān)控圖

業(yè)務(wù)影響

這種GC暫停時(shí)間嚴(yán)重影響了業(yè)務(wù)運(yùn)行：

• 服務(wù)超時(shí)：服務(wù)調(diào)用超時(shí)時(shí)間為1秒，GC暫停過(guò)長(zhǎng)導(dǎo)致超時(shí)風(fēng)險(xiǎn)
• 性能要求：
  • 最大GC暫停時(shí)間 < 200ms
  • 平均暫停時(shí)間 < 100ms
• 業(yè)務(wù)沖擊：對(duì)客戶(hù)的交易策略產(chǎn)生了嚴(yán)重影響，亟需解決

問(wèn)題排查過(guò)程

第一步：系統(tǒng)資源使用分析

CPU負(fù)載分析

首先檢查CPU使用情況，監(jiān)控?cái)?shù)據(jù)如下：

CPU負(fù)載監(jiān)控圖

觀察結(jié)果：

• 系統(tǒng)負(fù)載：4.92
• CPU使用率：約7%

重要提示：這個(gè)監(jiān)控圖中實(shí)際隱含了重要線索（CPU核心數(shù)與GC線程數(shù)的不匹配），但當(dāng)時(shí)并未察覺(jué)異常。

GC 內(nèi)存使用情況

然后我們排查了這段時(shí)間的內(nèi)存使用情況：

從圖中可以看到，大約 09:25 左右 old_gen 使用量大幅下跌，確實(shí)是發(fā)生了 FullGC。

但 09:20 前后，老年代空間的使用量在緩慢上升，并沒(méi)有下降，也就是說(shuō)引發(fā)最大暫停時(shí)間的這個(gè)點(diǎn)并沒(méi)有發(fā)生 FullGC。

當(dāng)然，這些是事后復(fù)盤(pán)分析得出的結(jié)論。當(dāng)時(shí)對(duì)監(jiān)控所反饋的信息并不是特別信任，懷疑就是觸發(fā)了 FullGC 導(dǎo)致的長(zhǎng)時(shí)間 GC 暫停。

為什么有懷疑呢，因?yàn)?Datadog 這個(gè)監(jiān)控系統(tǒng)，默認(rèn) 10s 上報(bào)一次數(shù)據(jù)。有可能在這 10s 內(nèi)發(fā)生些什么事情但是被漏報(bào)了（當(dāng)然，這是不可能的，如果上報(bào)失敗會(huì)在日志系統(tǒng)中打印相關(guān)的錯(cuò)誤）。

再分析上面這個(gè)圖，可以看到老年代對(duì)應(yīng)的內(nèi)存池是 “ps_old_gen”，通過(guò)前面的學(xué)習(xí)，我們知道，ps 代表的是 ParallelGC 垃圾收集器。

第三步：JVM配置分析

啟動(dòng)參數(shù)檢查

檢查JVM啟動(dòng)參數(shù)配置：

-Xmx4g -Xms4g

配置分析：

• JDK版本：JDK 8
• GC選擇：未指定，使用默認(rèn)的ParallelGC
• 堆內(nèi)存：最大和初始堆內(nèi)存均為4GB

初步問(wèn)題假設(shè)

懷疑點(diǎn)：ParallelGC可能是問(wèn)題根源

• 設(shè)計(jì)目標(biāo)：ParallelGC主要追求系統(tǒng)最大吞吐量
• 權(quán)衡策略：為了吞吐量?jī)?yōu)化，會(huì)犧牲單次GC的暫停時(shí)間
• 推測(cè)結(jié)論：可能因此導(dǎo)致暫停時(shí)間過(guò)長(zhǎng)

第一次優(yōu)化嘗試：切換到G1GC

優(yōu)化策略選擇

選擇G1垃圾收集器的理由：

• 穩(wěn)定性：在JDK 8的新版本中，G1已經(jīng)相當(dāng)穩(wěn)定
• 性能表現(xiàn)：具有良好的延遲控制能力
• 適用場(chǎng)景：更適合低延遲要求的應(yīng)用

配置過(guò)程

初次配置（失敗）

# 參數(shù)配置錯(cuò)誤，導(dǎo)致啟動(dòng)失敗
-Xmx4g -Xms4g -XX:+UseG1GC -XX:MaxGCPauseMills=50ms

錯(cuò)誤分析：

• 參數(shù)名拼寫(xiě)錯(cuò)誤：MaxGCPauseMills?→?MaxGCPauseMillis
• 參數(shù)值格式錯(cuò)誤：50ms?→?50

修正后配置

-Xmx4g -Xms4g -XX:+UseG1GC -XX:MaxGCPauseMillis=50

初步效果驗(yàn)證

服務(wù)啟動(dòng)成功，通過(guò)健康檢測(cè)切換到新節(jié)點(diǎn)后，監(jiān)控顯示：

G1GC初期效果監(jiān)控圖

效果評(píng)估：

• ??GC暫停時(shí)間：基本控制在50ms以?xún)?nèi)
• ??符合預(yù)期：達(dá)到了初期的優(yōu)化目標(biāo)

但是，問(wèn)題遠(yuǎn)未結(jié)束.....

“彩蛋”驚喜

過(guò)了一段時(shí)間，我們發(fā)現(xiàn)了個(gè)下面這個(gè)驚喜（也許是驚嚇），如下圖所示：

中獎(jiǎng)了，運(yùn)行一段時(shí)間后，最大 GC 暫停時(shí)間達(dá)到了 1300ms。

情況似乎更惡劣了。

繼續(xù)觀察，發(fā)現(xiàn)不是個(gè)別現(xiàn)象：

內(nèi)心是懵的，覺(jué)得可能是指標(biāo)算錯(cuò)了，比如把 10s 內(nèi)的暫停時(shí)間全部加到了一起。

注冊(cè) GC 事件監(jiān)聽(tīng)

于是想了個(gè)辦法，通過(guò) JMX 注冊(cè) GC 事件監(jiān)聽(tīng)，把相關(guān)的信息直接打印出來(lái)。

關(guān)鍵代碼如下所示：

// 每個(gè)內(nèi)存池都注冊(cè)監(jiān)聽(tīng)
for (GarbageCollectorMXBean mbean : ManagementFactory.getGarbageCollectorMXBeans()) {if (!(mbean instanceof NotificationEmitter)) {continue; // 假如不支持監(jiān)聽(tīng)...}final NotificationEmitter emitter = (NotificationEmitter) mbean;// 添加監(jiān)聽(tīng)final NotificationListener listener = getNewListener(mbean);emitter.addNotificationListener(listener, null, null);
}

通過(guò)這種方式，我們可以在程序中監(jiān)聽(tīng) GC 事件，并將相關(guān)信息匯總或者輸出到日志。

再啟動(dòng)一次，運(yùn)行一段時(shí)間后，看到下面這樣的日志信息：

{
"duration":1869,
"maxPauseMillis":1869,
"promotedBytes":"139MB",
"gcCause":"G1 Evacuation Pause",
"collectionTime":27281,
"gcAction":"end of minor GC",
"afterUsage":{
"G1 Old Gen":"1745MB",
"Code Cache":"53MB",
"G1 Survivor Space":"254MB",
"Compressed Class Space":"9MB",
"Metaspace":"81MB",
"G1 Eden Space":"0"},
"gcId":326,
"collectionCount":326,
"gcName":"G1 Young Generation",
"type":"jvm.gc.pause"
}

情況確實(shí)有點(diǎn)不妙。

這次實(shí)錘了，不是 FullGC，而是年輕代 GC，而且暫停時(shí)間達(dá)到了 1869ms。 一點(diǎn)道理都不講，我認(rèn)為這種情況不合理，而且觀察 CPU 使用量也不高。

找了一大堆資料，試圖證明這個(gè) 1869ms 不是暫停時(shí)間，而只是 GC 事件的結(jié)束時(shí)間減去開(kāi)始時(shí)間。

打印 GC 日志

既然這些手段不靠譜，那就只有祭出我們的終極手段：打印 GC 日志。

修改啟動(dòng)參數(shù)如下：

-Xmx4g -Xms4g -XX:+UseG1GC -XX:MaxGCPauseMillis=50 
-Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps

重新啟動(dòng)，希望這次能排查出問(wèn)題的原因。

運(yùn)行一段時(shí)間，又發(fā)現(xiàn)了超長(zhǎng)的暫停時(shí)間。

分析 GC 日志

因?yàn)椴簧婕懊舾袛?shù)據(jù)，那么我們把 GC 日志下載到本地進(jìn)行分析。

定位到這次暫停時(shí)間超長(zhǎng)的 GC 事件，關(guān)鍵的信息如下所示：

Java HotSpot(TM) 64-Bit Server VM (25.162-b12) for linux-amd64 JRE (1.8.0_162-b12),built on Dec 19 2017 21:15:48 by "java_re" with gcc 4.3.0 20080428 (Red Hat 4.3.0-8)
Memory: 4k page, physical 144145548k(58207948k free), swap 0k(0k free)
CommandLine flags: -XX:InitialHeapSize=4294967296 -XX:MaxGCPauseMillis=50 -XX:MaxHeapSize=4294967296-XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseG1GC 2020-02-24T18:02:31.853+0800: 2411.124: [GC pause (G1 Evacuation Pause) (young), 1.8683418 secs][Parallel Time: 1861.0 ms, GC Workers: 48][GC Worker Start (ms): Min: 2411124.3, Avg: 2411125.4, Max: 2411126.2, Diff: 1.9][Ext Root Scanning (ms): Min: 0.0, Avg: 0.3, Max: 2.7, Diff: 2.7, Sum: 16.8][Update RS (ms): Min: 0.0, Avg: 3.6, Max: 6.8, Diff: 6.8, Sum: 172.9][Processed Buffers: Min: 0, Avg: 2.3, Max: 8, Diff: 8, Sum: 111][Scan RS (ms): Min: 0.0, Avg: 0.2, Max: 0.5, Diff: 0.5, Sum: 7.7][Code Root Scanning (ms): Min: 0.0, Avg: 0.0, Max: 0.1, Diff: 0.1, Sum: 0.3][Object Copy (ms): Min: 1851.6, Avg: 1854.6, Max: 1857.4, Diff: 5.8, Sum: 89020.4][Termination (ms): Min: 0.0, Avg: 0.0, Max: 0.0, Diff: 0.0, Sum: 0.6][Termination Attempts: Min: 1, Avg: 1.0, Max: 1, Diff: 0, Sum: 48][GC Worker Other (ms): Min: 0.0, Avg: 0.3, Max: 0.7, Diff: 0.6, Sum: 14.7][GC Worker Total (ms): Min: 1858.0, Avg: 1859.0, Max: 1860.3, Diff: 2.3, Sum: 89233.3][GC Worker End (ms): Min: 2412984.1, Avg: 2412984.4, Max: 2412984.6, Diff: 0.5][Code Root Fixup: 0.0 ms][Code Root Purge: 0.0 ms][Clear CT: 1.5 ms][Other: 5.8 ms][Choose CSet: 0.0 ms][Ref Proc: 1.7 ms][Ref Enq: 0.0 ms][Redirty Cards: 1.1 ms][Humongous Register: 0.1 ms][Humongous Reclaim: 0.0 ms][Free CSet: 2.3 ms][Eden: 2024.0M(2024.0M)->0.0B(2048.0K) Survivors: 2048.0K->254.0M Heap: 3633.6M(4096.0M)->1999.3M(4096.0M)][Times: user=1.67 sys=14.00, real=1.87 secs] 

前后的 GC 事件都很正常，也沒(méi)發(fā)現(xiàn) FullGC 或者并發(fā)標(biāo)記周期，但找到了幾個(gè)可疑的點(diǎn)。

• physical 144145548k(58207948k free)：JVM 啟動(dòng)時(shí)，物理內(nèi)存 137GB，空閑內(nèi)存 55GB。
• [Parallel Time: 1861.0 ms, GC Workers: 48]：垃圾收集器工作線程 48 個(gè)。

GC 日志中揭露了幾個(gè)關(guān)鍵信息，

• user=1.67：用戶(hù)線程耗時(shí) 1.67s；
• sys=14.00：系統(tǒng)調(diào)用和系統(tǒng)等待時(shí)間 14s；
• real=1.87 secs：實(shí)際暫停時(shí)間 1.87s；
• GC 之前，年輕代使用量 2GB，堆內(nèi)存使用量 3.6GB，存活區(qū) 2MB，可推斷出老年代使用量 1.6GB；
• GC 之后，年輕代使用量為 0，堆內(nèi)存使用量 2GB，存活區(qū) 254MB，那么老年代大約 1.8GB，那么“內(nèi)存提升量為 200MB 左右”。

這樣分析之后，可以得出結(jié)論：

• 年輕代轉(zhuǎn)移暫停，復(fù)制了 400MB 左右的對(duì)象，卻消耗了 1.8s，系統(tǒng)調(diào)用和系統(tǒng)等待的時(shí)間達(dá)到了 14s。
• JVM 看到的物理內(nèi)存 137GB。
• 推算出 JVM 看到的 CPU 內(nèi)核數(shù)量 72個(gè)，因?yàn)?GC 工作線程?72* 5/8 ~= 48?個(gè)。

看到這么多的 GC 工作線程我就開(kāi)始警惕了，畢竟堆內(nèi)存才指定了 4GB。

按照一般的 CPU 和內(nèi)存資源配比，常見(jiàn)的比例差不多是 4 核 4GB、4 核 8GB 這樣的。

看看對(duì)應(yīng)的 CPU 負(fù)載監(jiān)控信息：

通過(guò)和運(yùn)維同學(xué)的溝通，得到這個(gè)節(jié)點(diǎn)的配置被限制為 4 核 8GB。

這樣一來(lái)，GC 暫停時(shí)間過(guò)長(zhǎng)的原因就定位到了：

• K8S 的資源隔離和 JVM 未協(xié)調(diào)好，導(dǎo)致 JVM 看見(jiàn)了 72 個(gè) CPU 內(nèi)核，默認(rèn)的并行 GC 線程設(shè)置為?72* 5/8 ~= 48 個(gè)，但是 K8S 限制了這個(gè) Pod 只能使用 4 個(gè) CPU 內(nèi)核的計(jì)算量，致使 GC 發(fā)生時(shí)，48 個(gè)線程在 4 個(gè) CPU 核心上發(fā)生資源競(jìng)爭(zhēng)，導(dǎo)致大量的上下文切換。

處置措施為：

• 限制 GC 的并行線程數(shù)量

事實(shí)證明，打印 GC 日志確實(shí)是一個(gè)很有用的排查分析方法。

限制 GC 的并行線程數(shù)量

下面是新的啟動(dòng)參數(shù)配置：

 -Xmx4g -Xms4g-XX:+UseG1GC -XX:MaxGCPauseMillis=50 -XX:ParallelGCThreads=4-Xloggc:gc.log -XX:+PrintGCDetails -XX:+PrintGCDateStamps

這里指定了?-XX:ParallelGCThreads=4，為什么這么配呢？我們看看這個(gè)參數(shù)的說(shuō)明。

-XX:ParallelGCThreads=n

設(shè)置 STW 階段的并行 worker 線程數(shù)量。 如果邏輯處理器小于等于 8 個(gè)，則默認(rèn)值 n 等于邏輯處理器的數(shù)量。

如果邏輯處理器大于 8 個(gè)，則默認(rèn)值 n 大約等于處理器數(shù)量的 5/8。在大多數(shù)情況下都是個(gè)比較合理的值。如果是高配置的 SPARC 系統(tǒng)，則默認(rèn)值 n 大約等于邏輯處理器數(shù)量的 5/16。

-XX:ConcGCThreads=n

設(shè)置并發(fā)標(biāo)記的 GC 線程數(shù)量。默認(rèn)值大約是 ParallelGCThreads 的四分之一。

一般來(lái)說(shuō)不用指定并發(fā)標(biāo)記的 GC 線程數(shù)量，只用指定并行的即可。

重新啟動(dòng)之后，看看 GC 暫停時(shí)間指標(biāo)：

紅色箭頭所指示的點(diǎn)就是重啟的時(shí)間點(diǎn)，可以發(fā)現(xiàn)，暫停時(shí)間基本上都處于 50ms 范圍內(nèi)。

后續(xù)的監(jiān)控發(fā)現(xiàn)，這個(gè)參數(shù)確實(shí)解決了問(wèn)題。

案例總結(jié)與思考

核心經(jīng)驗(yàn)

通過(guò)這個(gè)完整的排查案例，我們可以得到以下重要經(jīng)驗(yàn)：沒(méi)有量化，就沒(méi)有改進(jìn)。JVM問(wèn)題排查和性能調(diào)優(yōu)必須基于具體的監(jiān)控?cái)?shù)據(jù)進(jìn)行。

使用的排查手段

本案例運(yùn)用了以下關(guān)鍵技術(shù)手段：

1. 指標(biāo)監(jiān)控：通過(guò)Micrometer + Datadog建立完整的監(jiān)控體系
2. ?? JVM參數(shù)調(diào)優(yōu)：合理配置啟動(dòng)內(nèi)存和垃圾收集器
3. GC日志分析：深入分析GC日志定位根本原因
4. JMX事件監(jiān)聽(tīng)：通過(guò)編程方式獲取詳細(xì)的GC事件信息

GC性能維度評(píng)估

延遲維度：

• 主要關(guān)注GC暫停時(shí)間
• 目標(biāo)：最大暫停時(shí)間 < 200ms，平均暫停時(shí)間 < 100ms

吞吐量維度：

• 業(yè)務(wù)線程CPU資源占用百分比
• GC影響因素：暫停時(shí)間 + 并發(fā)GC的CPU消耗

系統(tǒng)容量維度：

• 硬件配置合理性
• 服務(wù)處理能力匹配度

關(guān)鍵技術(shù)洞察

容器化環(huán)境的特殊挑戰(zhàn)：

• 容器資源限制與JVM感知的不匹配
• GC線程數(shù)配置需要與實(shí)際可用CPU核心數(shù)對(duì)齊
• K8s資源隔離機(jī)制需要與JVM參數(shù)協(xié)調(diào)配置

問(wèn)題排查的系統(tǒng)性方法：

1. 現(xiàn)象觀察?→ 通過(guò)監(jiān)控發(fā)現(xiàn)異常
2. 假設(shè)驗(yàn)證?→ 基于經(jīng)驗(yàn)提出問(wèn)題假設(shè)
3. 深入分析?→ 通過(guò)日志等手段驗(yàn)證假設(shè)
4. 解決方案?→ 針對(duì)根因制定解決措施
5. 效果驗(yàn)證?→ 持續(xù)監(jiān)控驗(yàn)證解決效果

只要確保各項(xiàng)性能指標(biāo)滿(mǎn)足業(yè)務(wù)需求，資源占用保持在合理范圍內(nèi)，就達(dá)到了JVM調(diào)優(yōu)的預(yù)期目標(biāo)。