Apache HttpClient使用不當(dāng)導(dǎo)致的請求超時問題排查

一炭序、背景

近期負(fù)責(zé)的線上應(yīng)用出現(xiàn)調(diào)用失敗的問題，排查后發(fā)現(xiàn)是HttpClient相關(guān)的問題，特此記錄一下空繁。

因?yàn)樯婕熬€上數(shù)據(jù)安全隱私，模擬生產(chǎn)的應(yīng)用寫了demo朱庆，模擬一定的并發(fā)請求復(fù)現(xiàn)該問題盛泡。

1 問題介紹

收到線上告警通知：外部服務(wù)調(diào)用某應(yīng)用A大量報(bào)錯，平均響應(yīng)時常很長娱颊，經(jīng)常有請求超時的情況傲诵。

二、問題排查

1 初步排查

1.1 查連接情況

外部請求是http請求箱硕，所以可以查一下連接的情況拴竹。對應(yīng) java 進(jìn)程的連接數(shù)：

具體的連接情況：

202207311129431.png

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

應(yīng)用的 8080 端口有400個連接。

1.2 查線程情況

平均響應(yīng)時常比較長剧罩，一般是線程長時間在等待某個步驟完成栓拜。查一下應(yīng)用的線程執(zhí)行情況：

執(zhí)行命令 jstack 8433 | less

202207311117556.png

jstack的日志中有很多類似上面圖中的線程，處于 TIME_WAITING狀態(tài)惠昔，而下面的堆棧中幕与，HttpClientUtils.httpGet()是使用 Apache HttpClient 工具封裝的 http 請求函數(shù)，PoolHttpClientConnectionManager.leaseConnection() 看上去是在等待獲取連接镇防。大概分析得出：有很多線程在執(zhí)行過程中啦鸣，等待HttpClient獲取連接。

1.3 查應(yīng)用異常日志

查一下應(yīng)用的日志来氧，尋找線索赏陵，在日志中看到許多下面的異常日志：

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]

1.4 初步結(jié)論

外部有大量請求饼齿，很多請求的處理線程在等待 HttpClient 獲取連接，問題應(yīng)該在 HttpClient 蝙搔。

2 進(jìn)一步排查

2.1 分析 HttpClient

日志里兩個關(guān)鍵信息：

1.是HttpClient內(nèi)部報(bào)錯

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]

對應(yīng)的源碼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是因?yàn)橛|發(fā)了TimeoutException異常，而TimeoutException異常對應(yīng)于entry = future.get(timeout, tunit);

PoolingHttpClientConnectionManager.leaseConnection 是為了獲取連接吃型，分析一下其執(zhí)行流程证鸥，摘錄一下網(wǎng)上博客（https://segmentfault.com/a/1190000012343705） 獲取connection時序圖：

f3927e5b5ad94a949331a28870d49a95_tplv-k3u1fbpfcp-watermark.png

重點(diǎn)的步驟：

1.如果route下有空閑連接，則直接返回空閑連接

2.如果沒有空閑連接勤晚，且該connPerRoute及池中conn數(shù)均沒有達(dá)到最大值枉层，的conn數(shù)沒有達(dá)到最大值，則創(chuàng)建連接赐写，并放入池中鸟蜡，并返回該連接

3.如果沒有空閑連接，且達(dá)到了maxRoute或maxPoolsize挺邀，則阻塞等待揉忘，等待的時常，便是entry = future.get(timeout, tunit);中的 timeout 時長端铛。如果指定的時間沒有 lease 到 connection 泣矛，則 entry = future.get(timeout, tunit); 會拋出 TimeoutException 異常。

一般 pool 設(shè)計(jì)都是和上面的類似禾蚕，我們繼續(xù)分析一下 httpclient pool 的結(jié)構(gòu) ：

6d5ff0d006a2437fa2703d0909cf4198_tplv-k3u1fbpfcp-watermark.png

PoolEntry<HttpRoute, OperatedClientConnection>: 路由和連接的對應(yīng)關(guān)系您朽。

routeToPool: 可以多個（圖中僅示例兩個），圖中各隊(duì)列大小動態(tài)變化换淆，并不相等哗总。

maxTotal: 限制的是外層 httpConnPool 中 leased 集合和 available 隊(duì)列的總和的大小，httpConnPool 的 leased 和 available 的大小沒有單獨(dú)限制倍试。

maxPerRoute: 限制的是每個 routeToPool 中 leased 集合和 available 隊(duì)列的總和的大小讯屈。

一步步跟蹤源碼entry = future.get(timeout, tunit);，定位到核心調(diào)用處 org.apache.http.pool.AbstractConnPool#getPoolEntryBlocking() 易猫，對應(yīng)源碼

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));
    }
    // 首先對當(dāng)前連接池加鎖耻煤，當(dāng)前鎖是可重入鎖ReentrantLockthis.lock.lock();
    this.lock.lock();
    try {
        // 獲得一個當(dāng)前HttpRoute對應(yīng)的連接池具壮，即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;
                }
                // 如果拿到的是過期連接或者已關(guān)閉連接准颓，就釋放資源，繼續(xù)循環(huán)獲取
                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)有效連接就退出循環(huán)棺妓，直接return對應(yīng)連接
            if (entry != null) {
                this.available.remove(entry);
                this.leased.add(entry);
                onReuse(entry);
                return entry;
            }

            // New connection is needed攘已。執(zhí)行到這說明沒有拿到連接，需要新建連接
            final int maxPerRoute = getMax(route);
            // Shrink the pool prior to allocating a new connection
            // pool.getAllocatedCount()=pool.available.size() + pool.leased.size()怜跑，可用的加正在租借的即當(dāng)前池中已有的連接
            // 如果route對應(yīng)的連接池的已有連接數(shù)超過了支持的最大連接數(shù)量(加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對應(yīng)的連接池的已有連接數(shù)未達(dá)到最大最大限制
            if (pool.getAllocatedCount() < maxPerRoute) {
                final int totalUsed = this.leased.size();
                // freeCapacity指大池子里除了已用連接峡眶，最多能容納的空閑連接數(shù)(包括已經(jīng)創(chuàng)建的available連接和后續(xù)還允許創(chuàng)建的available連接)
                final int freeCapacity = Math.max(this.maxTotal - totalUsed, 0);
                if (freeCapacity > 0) {
                    final int totalAvailable = this.available.size();
                    // 此時當(dāng)前route肯定leased已滿剧防，無available，若大池子里已達(dá)到上限辫樱，且大池子里還有available的空閑連接峭拘，那可以清理其他route下的無available連接，為新連接挪出位置狮暑。所以close的是otherpool中l(wèi)astUsed的available連接鸡挠。若大池子沒有達(dá)到上限，則沒必要做清理搬男。
                    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);
                        }
                    }
                    // 創(chuàng)建一個新連接
                    final C conn = this.connFactory.create(route);
                    // 放入route對應(yīng)的池子的leased集合
                    entry = pool.add(conn);
                    // 放入大池子的leased集合
                    this.leased.add(entry);
                    // reutrn該連接
                    return entry;
                }
            }

            // 到這里證明沒有從獲得route池中獲得有效連接拣展，并且想要自己建立連接時當(dāng)前route連接池已經(jīng)到達(dá)最大值，即已經(jīng)有連接在使用缔逛，但是對當(dāng)前線程不可用
            boolean success = false;
            try {
                // 將future放入route池中等待备埃，實(shí)際就是加入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瓜喇，從等待隊(duì)列中移除
                pool.unqueue(future);
                this.pending.remove(future);
            }
            // check for spurious wakeup vs. timeout
            // 如果沒有等到信號量通知并且當(dāng)前時間已經(jīng)超時，則退出循環(huán)
            if (!success && (deadline != null) &&
                (deadline.getTime() <= System.currentTimeMillis())) {
                break;
            }
        }
        // 最終也沒有等到信號量通知歉糜，沒有拿到可用連接乘寒，則拋異常
        throw new TimeoutException("Timeout waiting for connection");
    } finally {
        // 釋放對大池子的鎖
        this.lock.unlock();
    }
}

綜合分析：

• 通過線程池獲取連接要通過 ReetrantLock 加鎖，保證線程安全
• 不論是大連接池還是小連接池匪补，當(dāng)超過數(shù)量的時候伞辛，都要通過LRU釋放一些連接
• 如果拿到了可用連接，則返回給上層使用
• 如果沒有拿到可用連接夯缺，HttpClient 會判斷當(dāng)前 route 連接池是否已經(jīng)超過了最大數(shù)量蚤氏，沒有到上限就會新建一個連接，并放入池中
• 如果到達(dá)了上限踊兜，就排隊(duì)等待竿滨，等到了信號量，就重新獲得一次捏境，等待不到就拋 TimeoutException

思考

池類的設(shè)計(jì)于游，不管是連接池，線程池垫言，一般不夠用的場景贰剥，都是最大數(shù)設(shè)置的不夠大，不足以應(yīng)對并發(fā)獲取連接筷频、線程等蚌成？

2.2 確認(rèn)HttpClient 實(shí)際情況

上面的都是猜想前痘，最終問題定位還是要摸清實(shí)際情況。

應(yīng)用里是如何創(chuàng)建 HttpClient 實(shí)例

下面是應(yīng)用中創(chuàng)建 HttpClient 實(shí)例的地方担忧，我們從變量 HTTP_CLIENT開始定位芹缔。

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

上面代碼可知：

1.沒有設(shè)置 maxPerRoute、maxTotal這類的參數(shù)瓶盛。

2.從連接池獲取連接的超時時間的參數(shù) ConnectionRequestTimeout 乖菱，設(shè)置為30秒。

arthas 定位實(shí)際數(shù)據(jù)

因?yàn)椴皇潜镜丨h(huán)境蓬网，不能方便地 Debug窒所，這時可以用 arthas 來查進(jìn)行內(nèi)存中 HttpClient 的實(shí)際數(shù)據(jù)。

在arthas中執(zhí)行：getstatic com.skyme.HttpClientUtils HTTP_CLIENT -x 4帆锋，結(jié)果如下：

202207311205785.png

routeToPool中吵取，route [https//github.com] 的使用情況是：leased為2，avaibable為0锯厢，pending為198皮官。

leased + avaibable 結(jié)果為2鞋仍，怎么這么少惜犀？難道是 maxPerRoute 參數(shù)設(shè)置的過小把曼？

在arthas結(jié)果中我們找到了 maxPerRoute 相關(guān)的配置剪撬，maxPerRoute 默認(rèn)值只有2摄乒，因?yàn)槲覀儎?chuàng)建 HttpClient 實(shí)例時，沒有設(shè)置maxPerRoute的數(shù)值残黑，所以每個route 的 maxPerRoute 為2馍佑， 這和上面的 leased + avaibable 的結(jié)果對應(yīng)上了。此外梨水，還有一個重要參數(shù) maxToal 為20拭荤。

202207311359531.png

大致結(jié)論：默認(rèn)參數(shù)太小

到這里，問題基本定位清楚了疫诽。因?yàn)閼?yīng)用沒有顯示地設(shè)置 maxPerRoute 和 maxToal 舅世，所以取了默認(rèn)值，默認(rèn)值比較小奇徒，maxPerRoute 為2雏亚， maxToal 為20， 導(dǎo)致并發(fā)獲取連接時逼龟，連接不夠用评凝，導(dǎo)致了獲取連接的線程一直在等待追葡，等待時間為我們創(chuàng)建 HttpClien 實(shí)例時自定義的 30 秒腺律，等待時間過長奕短，導(dǎo)致了外部請求超時。

三匀钧、解決辦法

1 臨時辦法

可以使用 arthas 的 vmtool 命令將內(nèi)存中的 defaultMaxPerRoute 翎碑、maxTotal 參數(shù)修改大一些，該操作過于風(fēng)騷之斯，一般不符合生產(chǎn)環(huán)境的運(yùn)維操作規(guī)范日杈。但是測試環(huán)境或者緊急情況可以嘗試使用。

[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 減少。

202207311358937.png

一段時間后瘫絮，pending為0涨冀，說明沒有阻塞，連接數(shù)已足夠使用麦萤。

202207311359531.png

注意：

1.該修改不需要應(yīng)用重啟鹿鳖，但應(yīng)用重啟后，內(nèi)存的設(shè)置將銷毀壮莹，依然還會存在問題翅帜。

2.非常規(guī)操作，謹(jǐn)慎執(zhí)行命满。

3.vmtool 命令在 arthas 3.5.1 版本之后才有涝滴。

2 長期辦法

修改代碼，配置合理的最大連接數(shù)maxPerRoute胶台、maxTotal狭莱、ConnectionRequestTimeout。

當(dāng)前 HttpClient 版本為 4.5.2概作，其他版本可能代碼有所差異腋妙。

    private final static PoolingHttpClientConnectionManager POOLING_HTTP_CLIENT_CONNECTION_MANAGER
            = new PoolingHttpClientConnectionManager();

    static {
        // 每個route默認(rèn)的最大連接數(shù)
        POOLING_HTTP_CLIENT_CONNECTION_MANAGER.setDefaultMaxPerRoute(100);
        // 總的連接池最大連接數(shù)
        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 設(shè)置為100，maxTotal 設(shè)置為500讯榕，并將 connectionRequestTimeout 從30秒減少到10秒骤素，沒有拿到連接快速失敗，防止過多的線程阻塞導(dǎo)致擠壓愚屁。

四济竹、總結(jié)

1.問題原因是 HttpClient 使用時沒有對參數(shù)足夠了解，對于連接池的框架霎槐，最好設(shè)置最大數(shù)送浊，獲取連接的等待超時時間，以及回收的周期丘跌，連接是否可用的校驗(yàn)等等參數(shù)袭景。其他池類的框架同理唁桩，例如線程池。

2.通過源碼耸棒、日志荒澡、線程、連接等多方面進(jìn)行分析与殃，結(jié)論會更準(zhǔn)確单山。

3.arthas 是神器，可以多嘗試幅疼。

參考：

[Http持久連接與HttpClient連接池]https://juejin.cn/post/6844903986705727495