记一次Apache HttpClient使用不当导致的请求超时问题分享排查过程

记一次Apache HttpClient使用不当导致的请求超时问题分享排查过程

背景

近期负责的线上应用出现调用失败的问题，排查后发现是 HttpClient 相关的问题，特此记录一下。

因为涉及线上数据安全隐私，模拟生产的应用写了 demo，模拟一定的并发请求复现该问题。

问题介绍

收到线上告警通知：外部服务调用某应用 A 大量报错，平均响应时常很长，经常有请求超时的情况。

问题排查

查连接情况

外部请求是 http 请求，所以可以查一下连接的情况。对应 java 进程的连接数：

具体的连接情况：

[root@sky ~]# netstat -tanp | grep 8433 | grep 8080 | wc -l
400

应用的 8080 端口有 400 个连接。

查线程情况

平均响应时常比较长，一般是线程长时间在等待某个步骤完成。查一下应用的线程执行情况：

执行命令 jstack 8433 | less。

jstack 的日志中有很多类似上面图中的线程，处于 TIME_WAITING状态，而下面的堆栈中，HttpClientUtils.httpGet()是使用 Apache HttpClient 工具封装的 http 请求函数，PoolHttpClientConnectionManager.leaseConnection()看上去是在等待获取连接。大概分析得出：有很多线程在执行过程中，等待HttpClient获取连接。

查应用异常日志

查一下应用的日志，寻找线索，在日志中看到许多下面的异常日志：

2022-07-24 21:47:44.765 ERROR 82381 --- [pool-2-thread-7] com.skyme.TestController                 : error:

org.apache.http.conn.ConnectionPoolTimeoutException: Timeout waiting for connection from pool
 at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(PoolingHttpClientConnectionManager.java:286) ~[httpclient-4.5.2.jar:4.5.2]
 at org.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.get(PoolingHttpClientConnectionManager.java:263) ~[httpclient-4.5.2.jar:4.5.2]
 at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:190) ~[httpclient-4.5.2.jar:4.5.2]
 at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:184) ~[httpclient-4.5.2.jar:4.5.2]
 at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:88) ~[httpclient-4.5.2.jar:4.5.2]
 at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110) ~[httpclient-4.5.2.jar:4.5.2]
 at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:184) ~[httpclient-4.5.2.jar:4.5.2]
 at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82) ~[httpclient-4.5.2.jar:4.5.2]
 at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:107) ~[httpclient-4.5.2.jar:4.5.2]
 at com.skyme.HttpClientUtils.httpGet(HttpClientUtils.java:31) ~[classes/:na]
 at com.skyme.TestController.lambda$batchHttpCall$0(TestController.java:47) ~[classes/:na]
 at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142) ~[na:1.8.0_73]
 at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617) ~[na:1.8.0_73]
 at java.lang.Thread.run(Thread.java:745) ~[na:1.8.0_73]

初步结论

外部有大量请求，很多请求的处理线程在等待 HttpClient 获取连接，问题应该在 HttpClient。

进一步排查

分析 HttpClient

日志里两个关键信息：

1. 是 HttpClient 内部报错

org.apache.http.conn.ConnectionPoolTimeoutException: Timeout waiting for connection from pool
 at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(PoolingHttpClientConnectionManager.java:286) ~[httpclient-4.5.2.jar:4.5.2]

对应的源码org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(PoolingHttpClientConnectionManager.java:286)：

protected HttpClientConnection leaseConnection(
        final Future<CPoolEntry> future,
        final long timeout,
        final TimeUnit tunit) throws InterruptedException, ExecutionException, ConnectionPoolTimeoutException {
    final CPoolEntry entry;
    try {
        entry = future.get(timeout, tunit); // 该处会抛出TimeoutException
        if (entry == null || future.isCancelled()) {
            throw new InterruptedException();
        }
        Asserts.check(entry.getConnection() != null, "Pool entry with no connection");
        if (this.log.isDebugEnabled()) {
            this.log.debug("Connection leased: " + format(entry) + formatStats(entry.getRoute()));
        }
        return CPoolProxy.newProxy(entry);
    } catch (final TimeoutException ex) {
        // 捕获TimeoutException异常，再抛出ConnectionPoolTimeoutException
        throw new ConnectionPoolTimeoutException("Timeout waiting for connection from pool");
    }
}    

抛出ConnectionPoolTimeoutException是因为触发了TimeoutException异常，而TimeoutException异常对应于entry = future.get(timeout, tunit);

PoolingHttpClientConnectionManager.leaseConnection 是为了获取连接，分析一下其执行流程，获取 connection 时序图如下：

重点的步骤：

1. 如果 route 下有空闲连接，则直接返回空闲连接
2. 如果没有空闲连接，且该 connPerRoute 及池中 conn 数均没有达到最大值，的 conn 数没有达到最大值，则创建连接，并放入池中，并返回该连接
3. 如果没有空闲连接，且达到了 maxRoute 或 maxPoolsize，则阻塞等待，等待的时常，便是entry = future.get(timeout, tunit);中的timeout时长。如果指定的时间没有 lease 到 connection ，则 entry = future.get(timeout, tunit); 会抛出 TimeoutException 异常。

一般 pool 设计都是和上面的类似，我们继续分析一下 httpclient pool 的结构 ：

PoolEntry<HttpRoute, OperatedClientConnection>: 路由和连接的对应关系。

routeToPool: 可以多个（图中仅示例两个），图中各队列大小动态变化，并不相等。

maxTotal: 限制的是外层 httpConnPool 中 leased 集合和 available 队列的总和的大小，httpConnPool 的 leased 和 available 的大小没有单独限制。

maxPerRoute: 限制的是每个 routeToPool 中 leased 集合和 available 队列的总和的大小。

一步步跟踪源码entry = future.get(timeout, tunit);，定位到核心调用处 org.apache.http.pool.AbstractConnPool#getPoolEntryBlocking() ，对应源码

private E getPoolEntryBlocking(
        final T route, final Object state,
        final long timeout, final TimeUnit tunit,
        final PoolEntryFuture<E> future)
            throws IOException, InterruptedException, TimeoutException {

    Date deadline = null; // 阻塞等待的截止时间
    if (timeout > 0) { 
        deadline = new Date
            (System.currentTimeMillis() + tunit.toMillis(timeout));
    }
    // 首先对当前连接池加锁，当前锁是可重入锁ReentrantLockthis.lock.lock();
    this.lock.lock();
    try {
        // 获得一个当前HttpRoute对应的连接池，即routeToPool
        final RouteSpecificPool<T, C, E> pool = getPool(route);
        E entry = null;
        while (entry == null) {
            Asserts.check(!this.isShutDown, "Connection pool shut down");
            for (;;) {
                entry = pool.getFree(state);
                if (entry == null) {
                    break;
                }
                // 如果拿到的是过期连接或者已关闭连接，就释放资源，继续循环获取
                if (entry.isExpired(System.currentTimeMillis())) {
                    entry.close();
                } else if (this.validateAfterInactivity > 0) {
                    if (entry.getUpdated() + this.validateAfterInactivity <= System.currentTimeMillis()) {
                        if (!validate(entry)) {
                            entry.close();
                        }
                    }
                }
                if (entry.isClosed()) {
                    this.available.remove(entry);
                    pool.free(entry, false);
                } else {
                    break;
                }
            }
            // 拿到未在使用中的(available)有效连接就退出循环，直接return对应连接
            if (entry != null) {
                this.available.remove(entry);
                this.leased.add(entry);
                onReuse(entry);
                return entry;
            }

            // New connection is needed。执行到这说明没有拿到连接，需要新建连接
            final int maxPerRoute = getMax(route);
            // Shrink the pool prior to allocating a new connection
            // pool.getAllocatedCount()=pool.available.size() + pool.leased.size()，可用的加正在租借的即当前池中已有的连接
            // 如果route对应的连接池的已有连接数超过了支持的最大连接数量(加1的目的？)，则通过LRU清理掉一些连接。
            final int excess = Math.max(0, pool.getAllocatedCount() + 1 - maxPerRoute);
            if (excess > 0) {
                for (int i = 0; i < excess; i++) {
                    final E lastUsed = pool.getLastUsed();
                    if (lastUsed == null) {
                        break;
                    }
                    lastUsed.close();
                    this.available.remove(lastUsed);
                    pool.remove(lastUsed);
                }
            }

            // 如果route对应的连接池的已有连接数未达到最大最大限制
            if (pool.getAllocatedCount() < maxPerRoute) {
                final int totalUsed = this.leased.size();
                // freeCapacity指大池子里除了已用连接，最多能容纳的空闲连接数(包括已经创建的available连接和后续还允许创建的available连接)
                final int freeCapacity = Math.max(this.maxTotal - totalUsed, 0);
                if (freeCapacity > 0) {
                    final int totalAvailable = this.available.size();
                    // 此时当前route肯定leased已满，无available，若大池子里已达到上限，且大池子里还有available的空闲连接，那可以清理其他route下的无available连接，为新连接挪出位置。所以close的是otherpool中lastUsed的available连接。若大池子没有达到上限，则没必要做清理。
                    if (totalAvailable > freeCapacity - 1) {
                        if (!this.available.isEmpty()) {
                            final E lastUsed = this.available.removeLast();
                            lastUsed.close();
                            final RouteSpecificPool<T, C, E> otherpool = getPool(lastUsed.getRoute());
                            otherpool.remove(lastUsed);
                        }
                    }
                    // 创建一个新连接
                    final C conn = this.connFactory.create(route);
                    // 放入route对应的池子的leased集合
                    entry = pool.add(conn);
                    // 放入大池子的leased集合
                    this.leased.add(entry);
                    // reutrn该连接
                    return entry;
                }
            }

            // 到这里证明没有从获得route池中获得有效连接，并且想要自己建立连接时当前route连接池已经到达最大值，即已经有连接在使用，但是对当前线程不可用
            boolean success = false;
            try {
                // 将future放入route池中等待，实际就是加入route池的pending集合
                pool.queue(future);
                // 放入大池子的pending集合
                this.pending.add(future);
                // 如果等待到了信号量的通知,success为true。如果到截止时间还未等到，则success为false
                success = future.await(deadline);
            } finally {
                // In case of 'success', we were woken up by the
                // connection pool and should now have a connection
                // waiting for us, or else we're shutting down.
                // Just continue in the loop, both cases are checked.
                // fanally，从等待队列中移除
                pool.unqueue(future);
                this.pending.remove(future);
            }
            // check for spurious wakeup vs. timeout
            // 如果没有等到信号量通知并且当前时间已经超时，则退出循环
            if (!success && (deadline != null) &&
                (deadline.getTime() <= System.currentTimeMillis())) {
                break;
            }
        }
        // 最终也没有等到信号量通知，没有拿到可用连接，则抛异常
        throw new TimeoutException("Timeout waiting for connection");
    } finally {
        // 释放对大池子的锁
        this.lock.unlock();
    }
}

综合分析：

• 通过线程池获取连接要通过 ReetrantLock 加锁，保证线程安全
• 不论是大连接池还是小连接池，当超过数量的时候，都要通过LRU释放一些连接
• 如果拿到了可用连接，则返回给上层使用
• 如果没有拿到可用连接，HttpClient 会判断当前 route 连接池是否已经超过了最大数量，没有到上限就会新建一个连接，并放入池中
• 如果到达了上限，就排队等待，等到了信号量，就重新获得一次，等待不到就抛 TimeoutException

思考

池类的设计，不管是连接池，线程池，一般不够用的场景，都是最大数设置的不够大，不足以应对并发获取连接、线程等？

确认HttpClient实际情况

上面的都是猜想，最终问题定位还是要摸清实际情况。

应用里是如何创建 HttpClient 实例

下面是应用中创建 HttpClient 实例的地方，我们从变量 HTTP_CLIENT开始定位。

private static final CloseableHttpClient HTTP_CLIENT = HttpClients
    .custom()
    .setDefaultRequestConfig(
            RequestConfig.custom()
            .setCookieSpec(CookieSpecs.IGNORE_COOKIES)
            .setConnectionRequestTimeout(30000)
            .build()
    ).build();

上面代码可知：

1. 没有设置 maxPerRoute、maxTotal这类的参数。
2. 从连接池获取连接的超时时间的参数 ConnectionRequestTimeout ，设置为30秒。

arthas 定位实际数据

因为不是本地环境，不能方便地 Debug，这时可以用 arthas 来查进行内存中 HttpClient 的实际数据。

在 arthas 中执行：getstatic com.skyme.HttpClientUtils HTTP_CLIENT -x 4，结果如下：

routeToPool中，route [https//github.com] 的使用情况是：leased 为 2，avaibable 为 0，pending 为 198。

leased + avaibable 结果为 2，怎么这么少？难道是 maxPerRoute 参数设置的过小？

在 arthas 结果中我们找到了 maxPerRoute 相关的配置，maxPerRoute 默认值只有2，因为我们创建 HttpClient 实例时，没有设置maxPerRoute的数值，所以每个route 的 maxPerRoute 为2， 这和上面的 leased + avaibable 的结果对应上了。此外，还有一个重要参数 maxToal 为 20。

大致结论：默认参数太小

到这里，问题基本定位清楚了。因为应用没有显示地设置 maxPerRoute 和 maxToal ，所以取了默认值，默认值比较小，maxPerRoute 为2， maxToal 为20， 导致并发获取连接时，连接不够用，导致了获取连接的线程一直在等待，等待时间为我们创建 HttpClien 实例时自定义的 30 秒，等待时间过长，导致了外部请求超时。

解决办法

临时办法

可以使用 arthas 的 vmtool 命令将内存中的 defaultMaxPerRoute 、maxTotal 参数修改大一些，该操作过于风骚，一般不符合生产环境的运维操作规范。但是测试环境或者紧急情况可以尝试使用。

[arthas@8433]$ vmtool --action getInstances --className org.apache.http.impl.client.CloseableHttpClient --express 'instances[0].connManager.pool.defaultMaxPerRoute=100'
@Integer[100]
[arthas@8433]$ vmtool --action getInstances --className org.apache.http.impl.client.CloseableHttpClient --express 'instances[0].connManager.pool.maxTotal=500'

修改后，连接池中 leased 明显增多，pending 减少。

一段时间后，pending 为 0，说明没有阻塞，连接数已足够使用。

注意：

1. 该修改不需要应用重启，但应用重启后，内存的设置将销毁，依然还会存在问题。
2. 非常规操作，谨慎执行。
3. vmtool 命令在 arthas 3.5.1 版本之后才有。

长期办法

修改代码，配置合理的最大连接数 maxPerRoute、maxTotal、ConnectionRequestTimeout。

当前 HttpClient 版本为 4.5.2，其他版本可能代码有所差异。

private final static PoolingHttpClientConnectionManager POOLING_HTTP_CLIENT_CONNECTION_MANAGER
        = new PoolingHttpClientConnectionManager();

static {
    // 每个route默认的最大连接数
    POOLING_HTTP_CLIENT_CONNECTION_MANAGER.setDefaultMaxPerRoute(100);
    // 总的连接池最大连接数
    POOLING_HTTP_CLIENT_CONNECTION_MANAGER.setMaxTotal(500);
}

private static final CloseableHttpClient HTTP_CLIENT = HttpClients
    .custom()
    .setConnectionManager(POOLING_HTTP_CLIENT_CONNECTION_MANAGER)
    .setDefaultRequestConfig(
            RequestConfig.custom()
            .setCookieSpec(CookieSpecs.IGNORE_COOKIES)//
            // 从连接池获取连接的超时时间
            .setConnectionRequestTimeout(10000)
            .build()
    ).build();

defaultMaxPerRoute 设置为 100，maxTotal 设置为 500，并将 connectionRequestTimeout 从 30 秒减少到 10 秒，没有拿到连接快速失败，防止过多的线程阻塞导致挤压。

总结

1. 问题原因是 HttpClient 使用时没有对参数足够了解，对于连接池的框架，最好设置最大数，获取连接的等待超时时间，以及回收的周期，连接是否可用的校验等等参数。其他池类的框架同理，例如线程池。
2. 通过源码、日志、线程、连接等多方面进行分析，结论会更准确。
3. arthas 是神器，可以多尝试。