CSDN

JVM调优笔记（一）--Nacos GC引发的服务批量下线问题

2023-04-23 12:02 由 雨叶微枫 发表于 #后端开发

故障背景

线上批量发服务下线的告警邮件，偶发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

热门相关：斗神战帝   刺客之王   网游之逆天飞扬   薄先生，情不由己   惊世毒妃：轻狂大小姐