调用超时问题跟踪及解决

朱凯个人博客

已于 2022-07-05 10:20:20 修改

阅读量587

点赞数

文章标签： jvm

于 2022-07-04 20:56:22 首次发布

本文链接：https://blog.csdn.net/zhukai_boke/article/details/125608486

版权

问题发现原因：

应用接入过异常日志告警，因为收到了告警通知，所以进行问题排查

问题描述如下：

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