一次JVM GC長(zhǎng)暫停的排查過(guò)程

作者 | 京東云開(kāi)發(fā)者-京東科技徐傳樂(lè)

背景

在高并發(fā)下，Java 程序的 GC 問(wèn)題屬于很典型的一類(lèi)問(wèn)題，帶來(lái)的影響往往會(huì)被進(jìn)一步放大。不管是「GC 頻率過(guò)快」還是「GC 耗時(shí)太長(zhǎng)」，由于 GC 期間都存在 Stop The World 問(wèn)題，因此很容易導(dǎo)致服務(wù)超時(shí)，引發(fā)性能問(wèn)題。

事情最初是線(xiàn)上某應(yīng)用垃圾收集出現(xiàn) Full GC 異常的現(xiàn)象，應(yīng)用中個(gè)別實(shí)例 Full GC 時(shí)間特別長(zhǎng)，持續(xù)時(shí)間約為 15~30 秒，平均每 2 周左右觸發(fā)一次；



JVM 參數(shù)配置 “-Xms2048M –Xmx2048M –Xmn1024M –XX:MaxPermSize=512M”

排查過(guò)程

?分析 GC 日志

GC 日志它記錄了每一次的 GC 的執(zhí)行時(shí)間和執(zhí)行結(jié)果，通過(guò)分析 GC 日志可以調(diào)優(yōu)堆設(shè)置和 GC 設(shè)置，或者改進(jìn)應(yīng)用程序的對(duì)象分配模式。

這里 Full GC 的 reason 是 Ergonomics，是因?yàn)殚_(kāi)啟了 UseAdaptiveSizePolicy，jvm 自己進(jìn)行自適應(yīng)調(diào)整引發(fā)的 Full GC。

這份日志主要體現(xiàn) GC 前后的變化，目前為止看不出個(gè)所以然來(lái)。



開(kāi)啟 GC 日志，需要添加如下 JVM 啟動(dòng)參數(shù)：


-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/export/log/risk_pillar/gc.log

常見(jiàn)的 Young GC、Full GC 日志含義如下：


?進(jìn)一步查看服務(wù)器性能指標(biāo)


獲取到了 GC 耗時(shí)的時(shí)間后，通過(guò)監(jiān)控平臺(tái)獲取到各個(gè)監(jiān)控項(xiàng)，開(kāi)始排查這個(gè)時(shí)點(diǎn)有異常的指標(biāo)，最終分析發(fā)現(xiàn)，在 5.06 分左右（GC 的時(shí)點(diǎn)），CPU 占用顯著提升，而 SWAP 出現(xiàn)了釋放資源、memory 資源增長(zhǎng)出現(xiàn)拐點(diǎn)的情況（詳見(jiàn)下圖紅色框，橙色框中的變化是因修改配置導(dǎo)致，后面會(huì)介紹，暫且可忽略）


JVM 用到了swap？是因?yàn)?GC 導(dǎo)致的 CPU 突然飆升，并且釋放了 swap 交換區(qū)這部分內(nèi)存到 memory？


為了驗(yàn)證 JVM 是否用到 swap，我們通過(guò)檢查 proc 下的進(jìn)程內(nèi)存資源占用情況


| for i in $(cd /proc;ls |grep "^[0-9]"|awk ' $0 >100') ;do awk '/Swap:/{a=a+$2} END {print '"$i"',a/1024"M"}' /proc/$i/smaps 2>/dev/null ; done | sort -k2nr | head -10 # head -10 表示 取出 前 10 個(gè)內(nèi)存占用高的進(jìn)程 # 取出的第一列為進(jìn)程的 id 第二列進(jìn)程占用 swap 大小 | | ------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------ |
看到確實(shí)有用到 305MB 的 swap


這里簡(jiǎn)單介紹下什么是swap?


swap 指的是一個(gè)交換分區(qū)或文件，主要是在內(nèi)存使用存在壓力時(shí)，觸發(fā)內(nèi)存回收，這時(shí)可能會(huì)將部分內(nèi)存的數(shù)據(jù)交換到 swap 空間，以便讓系統(tǒng)不會(huì)因?yàn)閮?nèi)存不夠用而導(dǎo)致 oom 或者更致命的情況出現(xiàn)。


當(dāng)某進(jìn)程向 OS 請(qǐng)求內(nèi)存發(fā)現(xiàn)不足時(shí)，OS 會(huì)把內(nèi)存中暫時(shí)不用的數(shù)據(jù)交換出去，放在 swap 分區(qū)中，這個(gè)過(guò)程稱(chēng)為 swap out。


當(dāng)某進(jìn)程又需要這些數(shù)據(jù)且 OS 發(fā)現(xiàn)還有空閑物理內(nèi)存時(shí)，又會(huì)把 swap 分區(qū)中的數(shù)據(jù)交換回物理內(nèi)存中，這個(gè)過(guò)程稱(chēng)為 swap in。


為了驗(yàn)證 GC 耗時(shí)與 swap 操作有必然關(guān)系，我抽查了十幾臺(tái)機(jī)器，重點(diǎn)關(guān)注耗時(shí)長(zhǎng)的 GC 日志，通過(guò)時(shí)間點(diǎn)確認(rèn)到 GC 耗時(shí)的時(shí)間點(diǎn)與 swap 操作的時(shí)間點(diǎn)確實(shí)是一致的。




進(jìn)一步查看虛擬機(jī)各實(shí)例 swappiness 參數(shù)，一個(gè)普遍現(xiàn)象是，凡是發(fā)生較長(zhǎng) Full GC 的實(shí)例都配置了參數(shù) vm.swappiness = 30（值越大表示越傾向于使用 swap）；而 GC 時(shí)間相對(duì)正常的實(shí)例配置參數(shù) vm.swappiness = 0（最大限度地降低使用 swap）。


swappiness 可以設(shè)置為 0 到 100 之間的值，它是 Linux 的一個(gè)內(nèi)核參數(shù)，控制系統(tǒng)在進(jìn) 行 swap 時(shí)，內(nèi)存使用的相對(duì)權(quán)重。


? swappiness=0: 表示最大限度使用物理內(nèi)存，然后才是 swap 空間


? swappiness=100: 表示積極的使用 swap 分區(qū)，并且把內(nèi)存上的數(shù)據(jù)及時(shí)的交換到 swap 空間里面

對(duì)應(yīng)的物理內(nèi)存使用率和 swap 使用情況如下


至此，矛頭似乎都指向了 swap。


?問(wèn)題分析


當(dāng)內(nèi)存使用率達(dá)到水位線(xiàn) (vm.swappiness) 時(shí)，linux 會(huì)把一部分暫時(shí)不使用的內(nèi)存數(shù)據(jù)放到磁盤(pán) swap 去，以便騰出更多可用內(nèi)存空間；


當(dāng)需要使用位于 swap 區(qū)的數(shù)據(jù)時(shí)，再將其換回內(nèi)存中，當(dāng) JVM 進(jìn)行 GC 時(shí)，需要對(duì)相應(yīng)堆分區(qū)的已用內(nèi)存進(jìn)行遍歷；


假如 GC 的時(shí)候，有堆的一部分內(nèi)容被交換到 swap 空間中，遍歷到這部分的時(shí)候就需要將其交換回內(nèi)存，由于需要訪(fǎng)問(wèn)磁盤(pán)，所以相比物理內(nèi)存，它的速度肯定慢的令人發(fā)指，GC 停頓的時(shí)間一定會(huì)非常非常恐怖；


進(jìn)而導(dǎo)致 Linux 對(duì) swap 分區(qū)的回收滯后（內(nèi)存到磁盤(pán)換入換出操作十分占用 CPU 與系統(tǒng) IO），在高并發(fā) / QPS 服務(wù)中，這種滯后帶來(lái)的結(jié)果是致命的 (STW)。


?問(wèn)題解決


至此，答案似乎很清晰，我們只需嘗試把 swap 關(guān)閉或釋放掉，看看能否解決問(wèn)題？


如何釋放 swap?

設(shè)置 vm.swappiness=0（重啟應(yīng)用釋放 swap 后生效），表示盡可能不使用交換內(nèi)存

a、 臨時(shí)設(shè)置方案，重啟后不生效

設(shè)置 vm.swappiness 為 0

sysctl vm.swappiness=0

查看 swappiness 值

cat /proc/sys/vm/swappiness

b、 永久設(shè)置方案，重啟后仍然生效

vi /etc/sysctl.conf

添加

vm.swappiness=0

關(guān)閉交換分區(qū) swapoff –a

前提：首先要保證內(nèi)存剩余要大于等于 swap 使用量，否則會(huì)報(bào) Cannot allocate memory！swap 分區(qū)一旦釋放，所有存放在 swap 分區(qū)的文件都會(huì)轉(zhuǎn)存到物理內(nèi)存上，可能會(huì)引發(fā)系統(tǒng) IO 或者其他問(wèn)題。

a、 查看當(dāng)前 swap 分區(qū)掛載在哪？



b、 關(guān)停分區(qū)



關(guān)閉 swap 交換區(qū)后的內(nèi)存變化見(jiàn)下圖橙色框，此時(shí) swap 分區(qū)的文件都轉(zhuǎn)存到了物理內(nèi)存上



關(guān)閉 Swap 交換區(qū)后，于 2.23 再次發(fā)生 Full GC，耗時(shí) 190ms，問(wèn)題得到解決。



?疑惑

1、 是不是只要開(kāi)啟了 swap 交換區(qū)的 JVM，在 GC 的時(shí)候都會(huì)耗時(shí)較長(zhǎng)呢？



2、 既然 JVM 對(duì) swap 如此不待見(jiàn)，為何 JVM 不明令禁止使用呢？


3、 swap 工作機(jī)制是怎樣的？這臺(tái)物理內(nèi)存為 8g 的 server，使用了交換區(qū)內(nèi)存（swap），說(shuō)明物理內(nèi)存不夠使用了，但是通過(guò) free 命令查看內(nèi)存使用情況，實(shí)際物理內(nèi)存似乎并沒(méi)有占用那么多，反而 Swap 已占近 1G？


free：除了 buff/cache 剩余了多少內(nèi)存

shared：共享內(nèi)存

buff/cache：緩沖、緩存區(qū)內(nèi)存數(shù)（使用過(guò)高通常是程序頻繁存取文件）

available：真實(shí)剩余的可用內(nèi)存數(shù)

大家可以想想，關(guān)閉交換磁盤(pán)緩存意味著什么？

其實(shí)大可不必如此激進(jìn)，要知道這個(gè)世界永遠(yuǎn)不是非 0 即 1 的，大家都會(huì)或多或少選擇走在中間，不過(guò)有些偏向 0，有些偏向 1 而已。

很顯然，在 swap 這個(gè)問(wèn)題上，JVM 可以選擇偏向盡量少用，從而降低 swap 影響，要降低 swap 影響有必要弄清楚 Linux 內(nèi)存回收是怎么工作的，這樣才能不遺漏任何可能的疑點(diǎn)。

先來(lái)看看 swap 是如何觸發(fā)的？

Linux 會(huì)在兩種場(chǎng)景下觸發(fā)內(nèi)存回收，一種是在內(nèi)存分配時(shí)發(fā)現(xiàn)沒(méi)有足夠空閑內(nèi)存時(shí)會(huì)立刻觸發(fā)內(nèi)存回收；另一種是開(kāi)啟了一個(gè)守護(hù)進(jìn)程（kswapd 進(jìn)程）周期性對(duì)系統(tǒng)內(nèi)存進(jìn)行檢查，在可用內(nèi)存降低到特定閾值之后主動(dòng)觸發(fā)內(nèi)存回收。

通過(guò)如下圖示可以很容易理解，詳細(xì)信息參見(jiàn)。


解答是不是只要開(kāi)啟了 swap 交換區(qū)的 JVM，在 GC 的時(shí)候都會(huì)耗時(shí)較長(zhǎng)

筆者去查了一下另外的一個(gè)應(yīng)用，相關(guān)指標(biāo)信息請(qǐng)見(jiàn)下圖。

實(shí)名服務(wù)的 QPS 是非常高的，同樣能看到應(yīng)用了 swap，GC 平均耗時(shí) 576ms，這是為什么呢？




通過(guò)把時(shí)間范圍聚焦到發(fā)生 GC 的某一時(shí)間段，從監(jiān)控指標(biāo)圖可以看到 swapUsed 沒(méi)有任何變化，也就是說(shuō)沒(méi)有 swap 活動(dòng)，進(jìn)而沒(méi)有影響到垃級(jí)回收的總耗時(shí)。


通過(guò)如下命令列舉出各進(jìn)程 swap 空間占用情況，很清楚的看到實(shí)名這個(gè)服務(wù) swap 空間占用的較少（僅 54.2MB）

另一個(gè)顯著的現(xiàn)象是實(shí)名服務(wù) Full GC 間隔較短（幾個(gè)小時(shí)一次），而我的服務(wù)平均間隔 2 周一次 Full GC


基于以上推測(cè)

1、 實(shí)名服務(wù)由于 GC 間隔較短，內(nèi)存中的東西根本沒(méi)有機(jī)會(huì)置換到 swap 中就被回收了，GC 的時(shí)候不需要將 swap 分區(qū)中的數(shù)據(jù)交換回物理內(nèi)存中，完全基于內(nèi)存計(jì)算，所以要快很多
2、 將哪些內(nèi)存數(shù)據(jù)置換進(jìn) swap 交換區(qū)的篩選策略應(yīng)該是類(lèi)似于 LRU 算法（最近最少使用原則）

為了證實(shí)上述猜測(cè)，我們只需跟蹤 swap 變更日志，監(jiān)控?cái)?shù)據(jù)變化即可得到答案，這里采用一段 shell 腳本實(shí)現(xiàn)

#!/bin/bash 
echo -e `date +%y%m%d%H%M%S` 
echo -e "PID		Swap		Proc_Name" 

#拿出/proc目錄下所有以數(shù)字為名的目錄（進(jìn)程名是數(shù)字才是進(jìn)程，其他如sys,net等存放的是其他信息） 
for pid in `ls -l /proc | grep ^d | awk '{ print $9 }'| grep -v [^0-9]` 
do 
    if [ $pid -eq 1 ];then continue;fi 
    grep -q "Swap" /proc/$pid/smaps 2>/dev/null 
    if [ $? -eq 0 ];then 
        swap=$(gawk '/Swap/{ sum+=$2;} END{ print sum }' /proc/$pid/smaps) #統(tǒng)計(jì)占用的swap分區(qū)的 大小 單位是KB 
        proc_name=$(ps aux | grep -w "$pid" | awk '!/grep/{ for(i=11;i<=NF;i++){ printf("%s ",$i); }}') #取出進(jìn)程的名字 
        if [ $swap -gt 0 ];then #判斷是否占用swap 只有占用才會(huì)輸出 
            echo -e "${pid}	${swap}	${proc_name100}" 
    fi 
   fi
done | sort -k2nr | head -10 | gawk -F'	' '{ #排序取前 10 
    pid[NR]=$1; 
    size[NR]=$2; 
    name[NR]=$3; 
} 
END{ 
    for(id=1;id<=length(pid);id++) 
    { 
    if(size[id]<1024) 
        printf("%-10s	%15sKB	%s
",pid[id],size[id],name[id]); 
    else if(size[id]<1048576) 
        printf("%-10s	%15.2fMB	%s
",pid[id],size[id]/1024,name[id]);
    else 
    printf("%-10s	%15.2fGB	%s
",pid[id],size[id]/1048576,name[id]); 
    } 
}'

由于上面圖中 2022.3.2 1900 至 2022.3.2 1900 發(fā)生了一次 Full GC，我們重點(diǎn)關(guān)注下這一分鐘內(nèi) swap 交換區(qū)的變化即可，我這里每 10s 做一次信息采集，可以看到在 GC 時(shí)點(diǎn)前后，swap 確實(shí)沒(méi)有變化


通過(guò)上述分析，回歸本文核心問(wèn)題上，現(xiàn)在看來(lái)我的處理方式過(guò)于激進(jìn)了，其實(shí)也可以不用關(guān)閉 swap，通過(guò)適當(dāng)降低堆大小，也是能夠解決問(wèn)題的。

這也側(cè)面的說(shuō)明，部署 Java 服務(wù)的 Linux 系統(tǒng)，在內(nèi)存分配上并不是無(wú)腦大而全，需要綜合考慮不同場(chǎng)景下 JVM 對(duì) Java 永久代 、Java 堆 (新生代和老年代)、線(xiàn)程棧、Java NIO 所使用內(nèi)存的需求。

總結(jié)

綜上，我們得出結(jié)論，swap 和 GC 同一時(shí)候發(fā)生會(huì)導(dǎo)致 GC 時(shí)間非常長(zhǎng)，JVM 嚴(yán)重卡頓，極端的情況下會(huì)導(dǎo)致服務(wù)崩潰。


主要原因是：JVM 進(jìn)行 GC 時(shí)，需要對(duì)對(duì)應(yīng)堆分區(qū)的已用內(nèi)存進(jìn)行遍歷，假如 GC 的時(shí)候，有堆的一部分內(nèi)容被交換到 swap 中，遍歷到這部分的時(shí)候就須要將其交換回內(nèi)存；更極端情況同一時(shí)刻因?yàn)閮?nèi)存空間不足，就需要把內(nèi)存中堆的另外一部分換到 SWAP 中去，于是在遍歷堆分區(qū)的過(guò)程中，會(huì)把整個(gè)堆分區(qū)輪流往 SWAP 寫(xiě)一遍，導(dǎo)致 GC 時(shí)間超長(zhǎng)。線(xiàn)上應(yīng)該限制 swap 區(qū)的大小，如果 swap 占用比例較高應(yīng)該進(jìn)行排查和解決，適當(dāng)?shù)臅r(shí)候可以通過(guò)降低堆大小，或者添加物理內(nèi)存。

因此，部署 Java 服務(wù)的 Linux 系統(tǒng)，在內(nèi)存分配上要慎重。


以上內(nèi)容希望可以起到拋轉(zhuǎn)引玉的作用，如有理解不到位的地方煩請(qǐng)指出。