⭐⭐⭐ Spring Boot 项目实战	⭐⭐⭐ Spring Cloud 项目实战
《Dubbo 实现原理与源码解析 —— 精品合集》	《Netty 实现原理与源码解析 —— 精品合集》
《Spring 实现原理与源码解析 —— 精品合集》	《MyBatis 实现原理与源码解析 —— 精品合集》
《Spring MVC 实现原理与源码解析 —— 精品合集》	《数据库实体设计合集》
《Spring Boot 实现原理与源码解析 —— 精品合集》	《Java 面试题 + Java 学习指南》

摘要: 原创出处 juejin.cn/post/7124317267407405070 「Spurs蒋」欢迎转载，保留摘要，谢谢！

🙂🙂🙂关注微信公众号：【芋道源码】有福利：

RocketMQ / MyCAT / Sharding-JDBC 所有源码分析文章列表

RocketMQ / MyCAT / Sharding-JDBC 中文注释源码 GitHub 地址

您对于源码的疑问每条留言都将得到认真回复。甚至不知道如何读源码也可以请教噢。

新的源码解析文章实时收到通知。每周更新一篇左右。

认真的源码交流微信群。

背景

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

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

问题介绍

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

问题排查

查连接情况

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

具体的连接情况：

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

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

查线程情况

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

执行命令 jstack 8433 | less。

image-20220731111745397

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

日志里两个关键信息：

是 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 时序图如下：

httpclient获取connection的时序图

重点的步骤：

如果 route 下有空闲连接，则直接返回空闲连接
如果没有空闲连接，且该 connPerRoute 及池中 conn 数均没有达到最大值，的 conn 数没有达到最大值，则创建连接，并放入池中，并返回该连接
如果没有空闲连接，且达到了 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();

上面代码可知：

没有设置 maxPerRoute、maxTotal这类的参数。
从连接池获取连接的超时时间的参数 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，说明没有阻塞，连接数已足够使用。

注意：

该修改不需要应用重启，但应用重启后，内存的设置将销毁，依然还会存在问题。
非常规操作，谨慎执行。
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 秒，没有拿到连接快速失败，防止过多的线程阻塞导致挤压。

总结

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

芋道源码 —— 纯源码解析博客

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

背景