故障背景
线上批量发服务下线的告警邮件,偶发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问题的组合拳导致的此次故障。
需要优化的点
- YGC和FGC过于频繁,需要降低频率
- CPU占用率过高
- sba服务心跳检测时间短了点
解决方案
- 针对FGC频率过高问题,调整nacos的启动脚本,新增配置-XX:-UseAdaptiveSizePolicy,禁用AdaptiveSizePolicy策略
- 迁移es到单独的服务器上运行
- 调整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,如下:此次调整过后YGC间隔时间由10s变成了40s,运行3.5天未发生FGC,老年代使用率66%。按这个速度,大约5天多一点会发生一次FGC,这个频率就还算正常。
总结
- ParallelGC垃圾回收器默认开启AdaptiveSizePolicy有点坑,需要注意一下
- es这种服务最好使用单独的机器部署,比较吃CPU和内存。这里es的CPU占用率这么高还有一个坑,这里就不赘述了,下次再聊
- YGC和FGC频率不能太高,过高时需要调整JVM参数来降低频率,这个过程可能会比较繁琐,因为调整之后还要持续观察之后再次进行调整
- 还是有必要部署针对JVM的监控服务(比如Prometheus),不然每次都需要手动执行命令观察JVM变化,有可能会错过关键信息
参考链接
https://blog.csdn.net/Sqdmn/article/details/106986762
https://blog.csdn.net/dhj199181/article/details/108415771
免责声明:如果侵犯了您的权益,请联系站长,我们会及时删除侵权内容,谢谢合作! |