JVM調優筆記（一）--Nacos GC引發的服務批次下線問題

雨葉微楓發表於2023-04-23
JVM筆記GC

故障背景

線上批次發服務下線的告警郵件，偶發nacos連線超時。採用了spring boot admin（以下稱sba）進行服務監控。

原因分析

因為sba服務是基於nacos對其它服務進行監控，所以遇到這個問題，第一懷疑物件是nacos發生問題，但不清楚具體是什麼問題。由於服務過一段事件會恢復，所以nacos肯定是沒有掛掉的，那麼排查方向應該是針對nacos的配置，或者是伺服器效能。

排查過程

首先檢視nacos的堆情況，使用命令jmap -heap PID，得到如下資訊：

Heap Configuration:
   MinHeapFreeRatio         = 0
   MaxHeapFreeRatio         = 100
   MaxHeapSize              = 2147483648 (2048.0MB)
   NewSize                  = 1073741824 (1024.0MB)
   MaxNewSize               = 1073741824 (1024.0MB)
   OldSize                  = 1073741824 (1024.0MB)
   NewRatio                 = 2 
   SurvivorRatio            = 8    
   MetaspaceSize            = 134217728 (128.0MB)
   CompressedClassSpaceSize = 327155712 (312.0MB)
   MaxMetaspaceSize         = 335544320 (320.0MB)
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
PS Young Generation
Eden Space:
   capacity = 1058013184 (1009.0MB)
   used     = 660154960 (629.5728302001953MB)
   free     = 397858224 (379.4271697998047MB)
   62.39572152628298% used
From Space:
   capacity = 7864320 (7.5MB)
   used     = 6914048 (6.59375MB)
   free     = 950272 (0.90625MB)
   87.91666666666667% used
To Space:
   capacity = 7864320 (7.5MB)
   used     = 0 (0.0MB)
   free     = 7864320 (7.5MB)
   0.0% used
PS Old Generation
   capacity = 1073741824 (1024.0MB)
   used     = 455548152 (434.44457244873047MB)
   free     = 618193672 (589.5554275512695MB)
   42.426227778196335% used

可以看到Heap Configuration部分還是比較正常的，最大堆記憶體是2G，新生代和老年代各1G。Eden區和Survivor的比例是預設的8:2。但是觀察Heap Usage發現了不對勁的部分，From和To區怎麼只有7.5M，這點很奇怪，按道理來說是102M才對。於是發動搜尋大法，找到一篇文章，描述如下：

JDK 1.8 預設使用 UseParallelGC 垃圾回收器，該垃圾回收器預設啟動了 AdaptiveSizePolicy。
AdaptiveSizePolicy(自適應大小策略) 是 JVM GC Ergonomics(自適應調節策略) 的一部分。
如果開啟 AdaptiveSizePolicy，則每次 GC 後會重新計算 Eden、From 和 To 區的大小，計算依據是 GC 過程中統計的 GC 時間、吞吐量、記憶體佔用量。

於是馬上檢視使用的是什麼垃圾回收器，使用命令jinfo -flags PID檢視JVM的啟動引數配置：

JVM version is 25.331-b09
Non-default VM flags: -XX:CICompilerCount=3 -XX:CompressedClassSpaceSize=327155712 -XX:GCLogFileSize=104857600 -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=null -XX:InitialHeapSize=2147483648 -XX:MaxHeapSize=2147483648 -XX:MaxMetaspaceSize=335544320 -XX:MaxNewSize=1073741824 -XX:MetaspaceSize=134217728 -XX:MinHeapDeltaBytes=524288 -XX:NewSize=1073741824 -XX:NumberOfGCLogFiles=10 -XX:OldSize=1073741824 -XX:-OmitStackTraceInFastThrow -XX:+PrintGC -XX:+PrintGCDateStamps -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+UseCompressedClassPointers -XX:+UseCompressedOops -XX:+UseFastUnorderedTimeStamps -XX:+UseGCLogFileRotation -XX:-UseLargePages -XX:+UseParallelGC 
Command line:  -Xms2g -Xmx2g -Xmn1g -XX:MetaspaceSize=128m -XX:MaxMetaspaceSize=320m -XX:-OmitStackTraceInFastThrow -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/nacos/logs/java_heapdump.hprof -XX:-UseLargePages -Dnacos.member.list= -Djava.ext.dirs=/jdk1.8.0_331/jre/lib/ext:/jdk1.8.0_331/lib/ext -Xloggc:/nacos/logs/nacos_gc.log -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCDateStamps -XX:+PrintGCTimeStamps -XX:+UseGCLogFileRotation -XX:NumberOfGCLogFiles=10 -XX:GCLogFileSize=100M -Dloader.path=/nacos/plugins/health,/nacos/plugins/cmdb -Dnacos.home=/nacos

以上資訊可以看到確實使用的是UseParallelGC垃圾回收器。問題解決了嗎？並沒有哦，真是隻是AdaptiveSizePolicy配置的問題麼？

Tips:
由於From和To區只有7.5M，當每次新生代GC時，如果在這一次GC中存活下來的物件記憶體大於7.5M那麼會將存不下的那部分將直接放入老年代，就會導致老年代快速增長，觸發Full GC。

由於From和To區太小可能會導致Full GC過於頻繁，於是我去檢視了一下nacos的GC日誌，發現YGC之間的間隔時間只有10s左右（非原伺服器資料）：

16:08:31.801+0800: 478.123: [GC (Allocation Failure) [PSYoungGen: 256704K->2784K(258048K)] 381385K->127497K(520192K), 0.0057120 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
16:08:41.812+0800: 488.133: [GC (Allocation Failure) [PSYoungGen: 256736K->2720K(258048K)] 381449K->127457K(520192K), 0.0074081 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]

再執行jstat -gc PID命令，得到如下資訊（執行6天的GC情況）：

 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU       CCSC     CCSU    YGC     YGCT    FGC    FGCT     GCT   
7680.0 7680.0  0.0   6176.0 1033216.0 834105.2 1048576.0   564595.0  87936.0 83749.9 10624.0  9990.6  29316  835.838    25    148.564  984.403

引數解釋：

S0C：第一個倖存區的大小
S1C：第二個倖存區的大小
S0U：第一個倖存區的使用大小
S1U：第二個倖存區的使用大小
EC：伊甸園區的大小
EU：伊甸園區的使用大小
OC：老年代大小
OU：老年代使用大小
MC：方法區大小
MU：方法區使用大小
CCSC:壓縮類空間大小
CCSU:壓縮類空間使用大小
YGC：年輕代垃圾回收次數
YGCT：年輕代垃圾回收消耗時間
FGC：老年代垃圾回收次數
FGCT：老年代垃圾回收消耗時間
GCT：垃圾回收消耗總時間

平均一天需要進行4次FGC，每次FGC大約需要6s，這很不正常哦。sba配置的是5s收不到心跳就觸發告警，平均FGC卻需要6s，這裡問題的關鍵已經比較明顯了，有可能就是Full GC導致的nacos停頓時間過長，導致sba服務收不到其他服務的心跳，於是發生服務批次下線問題。
那為什麼FGC會需要這麼久？我把主意打到了伺服器身上，執行top命令，觀察伺服器的CPU使用情況，還真讓我發現了一個問題，CPU使用率會突然飆升到300%，一看發現是es服務。
到這裡問題比較清晰了，es服務飆升的CPU使用率導致佔滿了伺服器的執行緒，nacos的FGC獲取不到執行緒來執行就需要等待，所以造成了長時間的服務停頓，於是發生了服務批次下線和nacos不可用問題。後來我在收到告警郵件之後，立馬上伺服器看CPU佔用情況，果然CPU佔用率高達300%，然後查詢nacos的GC日誌，發現有FGC時間長達45s（以下非原伺服器資料）：

14:06:09.452+0800: 3794735.773: [Full GC (Ergonomics) [PSYoungGen: 215040K->81154K(218112K)] [ParOldGen: 261606K->261605K(262144K)] 476646K->342760K(480256K), [Metaspace: 83823K->83823K(1126400K)], 45.4329403 secs] [Times: user=125.24 sys=0.58, real=45.43 secs]

到這兒，已經可以確定是由於nacos的JVM配置問題+es問題的組合拳導致的此次故障。

需要最佳化的點

  1. YGC和FGC過於頻繁，需要降低頻率
  2. CPU佔用率過高
  3. sba服務心跳檢測時間短了點

解決方案

  1. 針對FGC頻率過高問題，調整nacos的啟動指令碼，新增配置-XX:-UseAdaptiveSizePolicy，禁用AdaptiveSizePolicy策略
  2. 遷移es到單獨的伺服器上執行
  3. 調整sba的配置，將服務下線的心跳配置為60s

JVM最佳化過程

禁用AdaptiveSizePolicy之後，繼續觀察nacos的記憶體使用情況和GC情況，堆記憶體的From和To區已經正常，但是YGC和FGC的頻率並沒有下降多少。
懷疑是每次YGC之後活下來的物件太多了，From區100M也不夠，於是每次執行完jmap -heap PID命令之後，立馬再執行一次該命令，觀察堆記憶體的增長速度。發現每次新生代大概增長200-300M，老年代增長3%左右。新生代僅有1G，每次增長卻有200-300M，老年代增長速度過快，From區還是小了點，於是調整JVM的啟動引數，調整Xms和Xmx為4g，指定Xmn為3g，如下：

-Xms4g -Xmx4g -Xmn3g

此次調整過後YGC間隔時間由10s變成了40s，執行3.5天未發生FGC，老年代使用率66%。按這個速度，大約5天多一點會發生一次FGC，這個頻率就還算正常。

總結

  1. ParallelGC垃圾回收器預設開啟AdaptiveSizePolicy有點坑，需要注意一下
  2. es這種服務最好使用單獨的機器部署，比較吃CPU和記憶體。這裡es的CPU佔用率這麼高還有一個坑，這裡就不贅述了，下次再聊
  3. YGC和FGC頻率不能太高，過高時需要調整JVM引數來降低頻率，這個過程可能會比較繁瑣，因為調整之後還要持續觀察之後再次進行調整
  4. 還是有必要部署針對JVM的監控服務（比如Prometheus），不然每次都需要手動執行命令觀察JVM變化，有可能會錯過關鍵資訊

參考連結

https://blog.csdn.net/Sqdmn/article/details/106986762
https://blog.csdn.net/dhj199181/article/details/108415771

相關文章