HttpAsyncClient 频繁出现 Connection lease request time out 问题原因排查

1、问题描述

前段时间（囤了很久文章，当时是 22 年）把生产的支付结果通知改为使用 HttpAsyncClient 之后，虽然没出现生产事故，可事情也并没有想象中的那么简单。观察日志我们发现每天都存在一些（随着交易量变化的） 获取 Http 连接池连接超时的异常， 如下图所示：

可以看到出现取连接超时后，我们会加入到重试队列中，等待下一次调度执行。这不仅仅会给我们重试队列造成没必要的压力，重要的是会给企业端带来这么一个问题：客户已经付完钱了，但是由于我们系统的问题，企业端收到支付成功结果通知延迟，造成延迟出单，甚至有可能会存在掉单。

2、问题排查

获取连接超时自然而然想到的是：是项目内连接池配置的大小问题？ 由于我们配的太小在某一刻连接池耗尽 导致后续的请求迟迟拿不到连接。经检查项目实际生产配置如下：

// CPU 核心线程数
int workerCnt = Runtime.getRuntime().availableProcessors();
// HTTP 连接超时时间
defaultConnectTimeOut = 3000;
// 读取超时时间
defaultReadTimeOut = 15000;
// 获取连接超时时间，HTTP 连接池里面获取连接等待时间
defaultConnectionRequestingTimeout = 3000;
// 连接池最大连接数 -> 过期策略（Tomcat 一分钟断开）-> KeepAlive -> 无限存活
int maxConnTal = 1000;
// 单个主机最大连接数，Route -> HOST:PORT
int maxConnPerRoute = 80;

在这里，单个 Route(域名+端口) 配置的最大连接数是 80。有了第一个猜想：难道我们生产上某个时刻达到了 80 个并发的通知请求？（好像听起来不太可能）为验证这点猜想，立刻就去生产数据库求证了这一点，结果当然是没有这么高。

那难道是框架内部有 Bug？ 分配连接时，对连接池的大小判断有误,  为求证这个猜想只能去看框架源码了。因为之前看过一些这个框架源码，所以大概知道是哪里产生的异常，我们略过这一步直接来到问题发生的地方：AbstractNIOConnPool#processPendingRequest

红框部分就是问题产生的起点。此方法也是 请求连接池分配 Http 连接的主逻辑。

因为连接池分配连接肯定涉及到几个关键数字变量，如：当前已分配、当前空闲、最大连接池数等，而当前项目 没输出框架内部日志，也就无法推演当时生产的实际运行情况，所以第一步还是先要将框架内部日志输出。框架内部是在哪里会输出日志呢？

观察发现 PoolingNHttpClientConnectionManager 类是分配连接时的 关键逻辑调度类，输出了一些必要的信息，如进入分配逻辑前、分配逻辑后

如何把这单个类的 DEBUG 日志输出并且不影响整个项目的日志等级？这时候就需要对日志框架有所了解，配置如下：（这里我们使用的是 logback）

小知识点 1：假如此时你的 appender 设置了 filter 且过滤 level 为 INFO，这里还是会输出不了日志。 filter 的 level 一定要小于等于 logger 的 level，这里设置为 TRACE、DEBUG 皆可

小知识点 2：需要明确好当前框架用的是什么日志门面 api，假如根据项目内使用的不同，我们需要引入 对应的桥接包 才行。例如：当前框架用的是 JCL，我们项目用的是 SLFJ，所以我们必须引入 jcl-over-slf4j 依赖

做完日志输出准备，运维重启完系统，确认过已经能拿到框架输出的日志。这时候我们满怀兴奋地以为有了日志肯定能排查并解决这个问题….可事情也并没有那么简单，它竟然奇迹般的不出现了（ps：好家伙！量子力学是吧，薛定谔的 Bug 是吧）。

念念不忘，必有回响！直到重启完系统后的第 6 天，它终于再度出现，日志如下：

我们可以清楚地看到，从开始请求分配连接开始到抛出异常中间耗时 5 秒，我们配置的超时时间是 3 秒，所以当在检查 now > deadline 失败抛出超时异常。

route allocated: 1 of 80; total allocated: 29 of 1000

加上还打出当时线程池的一些关键参数，可无论是总连接数，和当前 route 下的已分配连接都是远远没达到设置的最大值的。那是不是逻辑判断有误呢？接着我就把打印出的连接池参数值，代入到代码中进行推演，发现按照道理是应该走到这个逻辑（AbstractNIOConnPool#processPendingRequest）

但实际貌似并没有走到，于是又从头到尾又检查了一遍用户线程执行流程，会不会是前面流程卡主了，然而也没有发现有特别耗时的地方（IO 操作）。要说有可能，在判断完需要新建 Http 连接后，会存在 解析本地和公网地址逻辑，  但这是在报错之后的逻辑，当前线程根本不会执行到，也就没有继续深入思考。

转念一想，这报错难道是由框架内部回调产生的（线程池内没有现成的连接，在 上一个连接建立 连接完成后，由框架内部回调执行时报错），这中间耗时了 5 秒。

还真有可能！因为建立 Http 连接的动作是由 单线程的 Reactor 完成，而我们的 Http 连接超时时间为 3 秒，加上请求是放到队列中的，串行依次处理，假如上一个请求处理超时，极有可能导致当前请求处理超时。

于是我们再来看建立连接动作那块代码，就在熟悉的老朋友 AbstractMultiworkerIOReactor 类中，建立链接的方法在 processSessionRequests 中：

不看不知道，原来 Http 连接建立的动作也是异步的 …这个假设也不成立。

ps：后面才反应过来，假如是建立 Http 连接慢导致的，那报错方法应该是异步调用，日志中的线程名应该是 I/O Worker-xx 才对，而现实日志线程打印的是我们的用户线程名…额，查问题陷进去了，犯低级错误

没办法，只能再次回到用户线程执行流程上，这次看的更加仔细，终于有了收获！原来 用户逻辑中 还存在 一把锁， AbstractNIOConnPool#lease 方法如下

分析下：这个加锁的地方是在 调用获取连接之前，不同的线程在进入到这个逻辑，由于当前对象是单例，加锁就变成了串行。所以！虽然这个逻辑是在调用获取之前，但是由于前一个线程迟迟未释放，下一个线程再进去非常有可能导致超时！

再联想到之前解析公网地址逻辑。于是做出合理假设： 那时出现了并发，当前报错线程在等这把锁，而持有锁的一方进行耗时操作，而这个操作就是解析地址。

现在我们需要查看上下文日志，看那个点是否出现了并发（另一个线程正在进行获取连接操作）

一看还真有！红框线程几乎同时在 41 秒和绿框（当前报错线程）开始获取 Http 连接，抢先了拿到了锁，成功的进入获取逻辑在一顿逻辑后终于在 46 秒成功拿到了连接，并释放了锁。这时候小红终于拿到了锁，可为时已晚，一检查直接超时。

为验证解析公网耗时的猜想，写了段简单的 Test 来证明（与 resolveRemoteAddress 方法底层调用一致）。如下：

public static void main(String[] args) {
    try {
        Long start = System.currentTimeMillis();
        java.net.InetAddress.getAllByName("出问题的域名");
        Long end = System.currentTimeMillis();
        System.out.println("耗时：" + (end - start));
    }
    catch (Exception e) {
        e.printStackTrace();
    }
}

为保证环境一致，让运维上传到对应生产服务器运行。结果为如下图

难以置信！就这么一行话，竟是硬生生地花了 15 秒！  排查继续，因为考虑到 getAllByName 是 jdk 底层方法，几乎可以确定是不存在问题的。于是自然而然地去检查了服务器 dns 的配置，如下：

nameserver 114.114.114.114
nameserver 223.5.5.5
nameserver 202.101.172.46

试着把最后的 202.101.172.46（杭州电信）注释掉，再次运行 demo 发现还是很慢。于是将 223.5.5.5（阿里云）置于 114.114.114.114(电信) 前面，奇迹出现了

到这里问题总算是排查清楚，且解决方法也很明确

3、一些想法

1. 网上有很多人推荐 114 做 dns 首选服务，事实证明真不如阿里云，后面建议运维组内宣导，统一首选阿里云
2. 纵观全文，笔者是在从源码倒推现象，加上一些失误导致有些艰辛。其实换种方式会更加 直接高效。比如，在 已经知道可能存在耗时操作的方法（AbstractNIOConnPool#processPendingRequest）上或一些关键方法上。直接使用一些外置手段，如 arthas 的 trace 命令进行观察，实际上笔者也是通过这个方法来观察修改 dns 是否生效
3. 看源码时，线程切换、加|解锁 等关键地方要着重注意

彩蛋！  修改完 DNS 对于正在运行的 Java 程序不会实时生效，需要重启！