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

背景

新需求开发提测，应用部署到测试服务器（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次请求成功的记录。包括服务器配置高出现的请求没有超时问题，都联系起来了。