性能文章>记一次微服务间调用超时排查>

记一次微服务间调用超时排查原创

372438

背景

新需求开发提测,应用部署到测试服务器(1C2G虚拟机)通过接口调用服务,发现通过OpenFeign调用服务提供方的接口处理超过了断路器设定的5秒超时时间,被熔断了。问题就这样产生了,这也是我接到这个问题反馈的第一手信息。

问题排查:

1、先是查看了两个应用的日志,暂且先将服务消费方应用定义为A服务,把服务提供方定义为B服务方便后面阐述。通过日志的查看,发现B服务在接收到A服务的请求日志时间戳要比A服务发出请求时的日志时间戳要晚。举例:A服务2022-05-28 10:08:05.324 发送出去的请求,B服务2022-05-28 10:13:05.424 接收到请求。这样B服务在处理A服务发出的请求时,A服务已经达到了超时的阈值,这样就出现了超时熔断的现象。这个现象曾经在生产的环境也发生过类似的情况,是Linux网络参数导致的。于是通过`sysctl -a |grep net.ipv4.tcp` 命令查看了`net.ipv4.tcp_timestamps` 和 `net.ipv4.tcp_tw_recycle`两个参数均为0,排除了系统参数问题导致。

 

2. 有同事提醒日志是用的Log4j2组件全异步化实现日志写入,日志里打印的时间很可能为写入文件的系统时间,会存在一定的偏差。这个比较好排除,通过两个应用的其他接口发起请求,然后观察日志的打印时间戳。通过测试排除了异步日志时间戳的假象。询问了开发同事在自己的电脑(4C16G)上跑这个业务接口调用是否存在问题,同事给出的结论是本地没有问题,没有复现超时现象。

 

3. GC停顿?应用开发运行在JDK17的ZGC下,JVM启动堆栈大小为1G。曾经有过生产环境发生过的,线程停顿导致的耗时较长,与这次场景不同的是该服务不涉及外部调用,内部处理的总时长较长情况。于是查看了gc的日志并未发现线程停顿的日志输出。也得到了排查。

 

4. 抓包分析,联系运维同事在两台服务器上安装了tcpdump工具,通过在A服务运行`tcpdump host B服务IP -w aaaa.pcap` 和 B服务运行 `tcpdump host A服务IP -w bbbb.pcap`  ,然后执行请求获取到两个pcap文件。拉取到本地通过Wireshark工具打开进行对比,能够通过http的内容通过发送的uuid属性作为唯一标识确定两台服务器的流量包的抓取时间,通过观察存在A服务push消息的包时间与日志时间是不能匹配。开始怀疑到网络延时问题。运维同事给了一台与B服务在同一台宿主机上的虚拟机,但整体的配置(8C16G)要比A服务好很多。将A应用部署上去,开始测试接口。发现所有的请求均成功了,没有复现超时的问题。至此以为看到了希望。开始对A服务原来的虚拟机进行迁移,与B服务同在一台宿主机上。发起请求,查看日志结果还是大量的熔断超时。然后再分析差异就是配置了,开始对A服务的虚拟机进行升级配置,由1C2G升到2C4G调整JVM参数重启应用,进行再次的接口测试,仍然是大量超时。

 

5. 开始反思,通过源码开始分析业务逻辑,大致了解了代码执行顺序。通过异步方式并行处理两个不同的任务。两个异步任务共用了一个线程池。即通过@Async注解执行了同一个线程池,在第一个异步任务的逻辑里使用了CountDownLatch.await() 这样线程会处于WAITING状态不能被其他任务锁使用,这样第二个任务的线程使用上就会比预期的要少一部分。在不超出最大线程数的情况下,任务会先入队列,然后创建新的线程去执行任务。线程的创建也是有性能损耗的。于是将两个异步任务的线程池进行拆分,分开为两个线程池后代码提交、部署、测试,问题依然存在。

 

6. 再次反思,回到断路器(resilience4j)上来,既然的断路器超时,抓包反应消息发送滞后与应用。于是通过官方的网站,查看通过源代码分析,原来断路器通过门面模式进行对FeignClient进行包装,内部同样是在一个线程池内进行异步的处理,这个线程池默认是按照当前服务器的CPU数量进行初始化。这是一个多么痛的教训,一下从这么几行代码就变的清晰了。 回头再分析日志看,在没有其他业务运行时,确实存在1-2次请求成功的记录。包括服务器配置高出现的请求没有超时问题,都联系起来了。

 

解决问题:

修改配置解决问题,通过以接口维度进行线程池隔离,设定与异步平行任务数量相同的线程数量。然后部署测试环境(2C4G),进行验证。查看日志所有接口请求均成功处理。

 

总结:

回想起来这个过程感觉挺漫长的,但当问题定位清楚之后,解决起来还是很轻松的。通过这次问题的排查也重新认识了resilience4j断路器组件,大多的问题都是对组件的不了解和使用不当导致的。没有遇到问题之前仅从理论的角度理解,通过实践、问题解决也积累了使用的经验,给以后的应用开发提供了依据和指导经验。

点赞收藏
heroyeah_293541
请先登录,查看3条精彩评论吧
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步

为你推荐

JDBC PreparedStatement 字段值为null导致TBase带宽飙升的案例分析

JDBC PreparedStatement 字段值为null导致TBase带宽飙升的案例分析

随机一门技术分享之Netty

随机一门技术分享之Netty

MappedByteBuffer VS FileChannel:从内核层面对比两者的性能差异

MappedByteBuffer VS FileChannel:从内核层面对比两者的性能差异

8
3