问题发现原因:
应用接入过异常日志告警,因为收到了告警通知,所以进行问题排查
问题描述如下:
A应用通过http方式同步调用B应用,时间线如下:
2022-06-22 14:07:12 >> 【A应用】打印出已经向B应用发起http请求的日志
2022-06-22 14:07:17 >> 【A应用】打印出调用B应用超时日志(read time out)
2022-06-22 14:07:18 >> 【B应用】打印接收到A请求日志
问题排查过程:
根据日志发现,B应用处理请求时间晚于A应用请求时间5s钟,正常情况这两处的时间差应该非常接近。
- 首先登录到应用监控大盘,查看对应时间端应用的流量情况,JVM使用情况,GC情况,CPU情况
- 观察后发现在这个时间点附近,系统发生过FullGC。(知识点:我们知道系统在发生FullGC时会有STW的情况)
- 登录到B应用实例服务上,通过grep命令,查询出2022-06-22 14:07:10这个时间点附近的GC日志情况(如下图,简称图1),命令如:grep -C 100 "2022-06-22T14:07:1" gc.log
- 根据GC日志分析,发现CMS在2022-06-22T14:07:11时刻开始remark,耗时7.08秒,而CMS的remark阶段会发生STW(即不会处理用户请求),所以就能解释了A应用调用超时的原因。
- 而在2022-06-22T14:07:18,CMS开始并发处理sweep,这个时候系统可以处理用户请求,因此在这个时间点,B应用打印出日志了,问题现象都得到了合理的解释。
进一步排查
系统运行581654.255秒(大概有6.7天),相关情况如下:
1、执行 jstat -gcutil pid查看GC情况
[root@za-castle-zeus-common-r5446-66d448784d-qhh9r logs]# jstat -gcutil 1
S0 S1 E O M CCS YGC YGCT FGC FGCT GCT
40.98 0.00 80.32 78.54 81.62 72.86 7184 276.885 77 55.579 332.464
2、grep过滤gc日志文件,查看所有FullGC中CMS Final Remark阶段real耗时超过1秒的情况,如下图:
系统JVM参数配置(当前)
执行jsp -lv信息如下:
[root@xxx-r5446-66d448784d-qhh9r logs]# jps -lv 1 app.jar -Xms4000m -Xmx4000m -Xss512k -XX:MetaspaceSize=500m -Xmn1500m -XX:PretenureSizeThreshold=1000000 -XX:MaxTenuringThreshold=10 -XX:NativeMemoryTracking=summary -XX:+UseConcMarkSweepGC -XX:+UseCMSInitiatingOccupancyOnly -XX:CMSInitiatingOccupancyFraction=90 -XX:+UseCMSCompactAtFullCollection -XX:CMSFullGCsBeforeCompaction=2 -XX:+CMSParallelInitialMarkEnabled -XX:+CMSParallelRemarkEnabled -XX:+PrintTenuringDistribution -XX:+HeapDumpOnOutOfMemoryError -XX:HeapDumpPath=/logs/app.hprof -verbose:gc -XX:+PrintGCDetails -XX:+PrintGCTimeStamps -XX:+PrintGCDateStamps -XX:+PrintHeapAtGC -Xloggc:/logs/gc-.log
解决思路
1、调大http read time的超时时间
2、优化JVM参数。
思路:在大部分情况下CMS的remark阶段耗时都在1秒内,偶尔几次会出现耗时很长的情况。因此目标是要减少remark阶段的耗时。
准备尝试调整下面两个参数:
-XX:ParallelCMSThreads=6 :定义并发CMS过程运⾏时的线程数,让更多的线程参与GC工作,会消耗更多CPU,而根据六翼监控来看,我们的CPU剩余充足。
-XX:+CMSScavengeBeforeRemark:在CMS GC前启动⼀次ygc,⽬的在于减少old gen对ygc gen的引⽤,降低remark时的开销(⼀般CMS的GC耗时 80%都在remark阶段)
最后结论,在原有JVM参数配置上,新增如下参数:
- -XX:ParallelCMSThreads=6
- -XX:+CMSScavengeBeforeRemark
后续跟踪
优化后尚未出现read timed out超时异常,下图显示在"Rescan (parallel)"阶段,其中“CMS-remark”耗时只有0.4055177s,整个Rescan (parallel)阶段也只有0.41s,目前效果理想,待后面继续观察看是否会出现异常情况。