服務間呼叫httpclient連線池異常

阿新 • • 發佈：2018-12-29

本文轉自：https://blog.csdn.net/hry2015/article/details/78965690

1. 問題描述

客戶端A –> Ngnix –> 服務B
Ngnix做服務B的負載，客戶端訪問服務B時，客戶端偶爾會有丟擲TimeoutException異常。

舉個例子：如A在09:59:48訪問B，則服務B在09:59:53收到請求，併成功執行業務並返回。但是A會在10:00:05左右丟擲TimeoutException。此時客戶端A認為本次呼叫失敗，然後走失敗的業務邏輯。但是查詢服務端的日誌，發現實際業務在服務B上正常執行了，並正常返回。這樣出現客戶端和服務端兩邊資料不一致的問題。

這個問題是難點：

兩邊是通過公網呼叫，公網網路的複雜性會導致問題更復雜
無法直接定位是服務端還是客戶端的問題
兩邊的程式不是同一個所寫，由不同人維護。自己維護服務端程式碼，客戶端程式碼是其它人維護
需要理解TCP/IP的通訊協議
需要理解httplclent和ngnix的超時配置相關的知識

下面我按照以下順序一一排查問題：

網路問題
超時配置引數的問題
GC的問題
使用tcpdump抓包，分析網路包
修正程式碼問題
上線驗證

2. 問題分析處理的過程

2.1. 網路問題

由於客戶端A和服務B是使用公網訪問，最開始認為是網路抖動引起，並沒有馬上處理。但是執行一段時間後且這段時間伺服器的流量不是很大，這個問題仍然每天不定時出現，所以猜測可能不是網路的問題。

2.2. 超時配置引數的問題

又猜測可能是超時引數配置的問題。整理服務端和客戶端配置如下：
客戶端httpclient
客戶端httpclient的關於連線的配置相關的引數和意義如下：

SocketTimeout 是 5s
- 連線建立時間，即三次握手完成時間
ConnectTimeout 是 3s
- 連線建立後，資料傳輸過程中資料包之間間隔的最大時間
ConnectionRequestTimeout 是預設值
- httpclient使用連線池來管理連線，這個時間就是從連線池獲取連線的超時時間

這3個屬性的關係如下：下圖來自網路
這裡寫圖片描述
雖然報文(“abc”)返回總共用了6秒，如果SocketTimeout設定成5秒，實際程式執行的時候是不會丟擲java.net.SocketTimeoutException: Read timed out異常的。
因為SocketTimeout的值表示的是“a”、”b”、”c”這三個報文，每兩個相鄰的報文的間隔時間沒有能超過SocketTimeout。

ngnix端
ngnix端的超時相關的配置如下

keepalive_timeout 10;
send_timeout 60;

經過對以上配置引數的深入理解，再加上即使異常的請求服務端也有收到請求並正常執行業務，且每個請求處理完畢的時間都在100ms左右。總之即使以上的配置引數異常導致超時也跟這個問題的現象不同，所以初步排除配置異常的問題

2.3. GC的問題

請教組內的同事，可能是GC的問題，可能是GC的關係使服務暫停執行沒有及時處理業務
在服務端B執行如下命令，發現沒有執行過FGC，YGC的時間也是在合理範圍內
jstat -gc pid 2000 20
這裡寫圖片描述

在客戶端A執行如下命令，發現其頻繁執行FCG，YGC
jstat -gc pid 2000 20
使用”jmap -heap pid” 檢視客戶端A的堆的分配情況，發現其記憶體分配非常小，老年期的已用空間在96%以上。
綜上，我們認為是在httpclient建立連線後，堆記憶體不足引發頻繁的FGC，使得httpclient的無法在及時將資料傳送請求到服務端，偶爾出現在5s臨界點才傳送資料到服務端成功
修改堆記憶體後，GC的問題解決了，但是很遺憾，這個問題沒有被修正。

2.4. 使用tcpdump抓包，分析網路包

最後使出大招，在服務端172.23.4.33端使用tcpdump抓包，內容如下：
這裡寫圖片描述

藍色框的部分：之前有一個正常的請求，通訊完畢後10s，ngnix由於keep-alive=10s時間到了，傳送請求通知關閉連線 close notify信令。但是這裡有個問題，這裡服務端傳送FIN信令，而客戶端沒有傳送FIN信令，不符合標準的TCP的四次揮手協議。即連線在服務端已經關閉，而客戶端沒有關閉。

這裡的Alert (level warning description close notify)：表示傳送方會關閉這個連線，不會在這個連線上傳送任何資料

紅色框的部分
紅色的部分和黃色的部分正好相隔5s：

紅色的部分的包的時間，和我們定位的異常請求開始的時間相同，這裡的操作可以理解為客戶端和服務端相互關閉連結。加上這裡的埠和上面藍色部分的包的埠組相同，所有這兩部分是對相同的連線執行操作，這裡就比較奇怪。為什麼資料傳輸完畢後，要經過19s才執行連線關閉推行。貌似這個關閉操作是由下一個請求觸發的。

後面閱讀httpclient的原始碼發現，httpclient連線池在執行新的請求，如果發現連線異常時，會呼叫releaseconnection操作，會先執行釋放之前連線操作

黃色框的部分
和紅色框的部分正好相隔5s
這裡是通過3次握手建立連線，然後再執行https進行加密傳輸。對https的後面的Application Data的解密我們發現這個的確是客戶端傳送到服務端的資料。現象好像是第一次請求執行失敗，httpclient重新發起新的請求

所以以上的包和異常現象正好吻合，我們猜測如下：
客戶端A在09:59:48想重用上一次使用的TCP連線，但是發現連線已經關閉。服務端傳送RST信令，通話雙方重置連線。但是不知道什麼原因客戶端沒有馬上重置連線，而在等待5s超時後，然後才向服務端重新建立新的連線，併發送資料，服務端收到資料並執行請求。但是此時客戶端發現整個連線時間已經超過5s，丟擲TimeoutException。

2.5. 檢查程式碼問題

檢視客戶端程式碼，發現有兩個問題
一是：httpclient設定（.setRetryHandler(new HttpRetryHandler(3))）重試3次，已知httpclient的connectiontime是最多是5s,但是future.get(5000, TimeUnit.MILLISECONDS)只等待5s，所有如果發生第一次請求失敗，則這個肯定會失敗。這裡客戶端的請求服務端的操作和處理返回結果是非同步，整個完成請求最多需要20s，而對返回結果的處理是5s之內，如果5s內沒有返回，則丟擲TimeoutException。但是httpclient的請求並沒有被中斷，繼續執行。這也解釋了為什麼請求在服務端正常執行，而客戶端丟擲TimeoutException異常。

// 定義httpClient 
httpClient = HttpClients.custom().setConnectionManager(connectionManager)
    .setDefaultRequestConfig(defaultRequestConfig)
     // 設定重試3次
    .setRetryHandler(new HttpRetryHandler(3))
    .setMaxConnPerRoute(500).build();
//利用future管理回撥
Future<Object> future = executorService.submit(new CmdTask(sId, manageCenter.getService(provide), cmd, command.entry, provide, manageCenter.queryProvide(provide)));
//等待5秒超時
Object resp = future.get(5000, TimeUnit.MILLISECONDS);
Pair<Integer, String> pairResp = null;

二是：httpclient使用了PoolingHttpClientConnectionManager連線池，使用PoolingHttpClientConnectionManager需要注意，詳細見官方文件：簡單地說PoolingHttpClientConnectionManager裡儲存的連線，如果連線被伺服器端關閉了，客戶端監測不到連線的狀態變化。在httpclient中，當連線空閒超過10s後，服務端會關閉本端連線。但是客戶端的連線一直保持連線，即使服務端關閉連線，客戶端也不會關閉連線。所以下次使用連線，程式從連線中獲取一個連線（即使這個連線已經被服務端），也需要進行確認，如果發現連線異常，則服務端會發送RST信令，雙方重新建立新的連線。

為了解決這個問題HttpClient會在使用某個連線前，監測這個連線是否已經過時，如果伺服器端關閉了連線，那麼會重現建立一個連線。但是這種過時檢查並不是100%有效。所以建立建立一個監控程序來專門回收由於長時間不活動而被判定為失效的連線：

Timer timer = new Timer();
    timer.schedule(new TimerTask() {
        @Override
        public void run() {
            System.out.println("=====closeIdleConnections===");
            connectionManager.closeExpiredConnections();
            connectionManager.closeIdleConnections(5, TimeUnit.SECONDS);
        }
    }, 0, 5 * 1000);

PoolingHttpClientConnectionManager裡異常連線沒有及時釋放，這也解釋了之前的抓包中為什麼每次請求會先使用舊的連線，發現連線關閉後，又重新建立新的連線的現象。

修改程式碼：
1. 建立定時任務關閉PoolingHttpClientConnectionManager的異常連線，釋放連線和連線相關的資源
2. 關閉重試操作

2.6 修改程式碼後上線驗證

修改程式碼，上線，觀察4天，問題沒有再出現，捕獲新的包檢視新的雙互動包
這裡寫圖片描述

紅框部分是：客戶端和服務端有正常的請求
黃框部分是：之前的連線使用後，服務端過10s釋放連線，是因為ngnix的keepalive的時間是10s，172.23.4.43通知106.2.33.40關閉請求，106.2.33.40傳送FIN,ACK信令到172.23.4.43，表示自己已經連線，並通知對方關閉連線. 172.23.4.43收到信令後，關閉連線，併發送FIN,ACK信令，
以上是完整的連線斷開四次揮手，整個會話連線完全關閉。

綠框部分：客戶端和服務端發啟新的請求，此時第一步是客戶端和服務端是三次握手建立建立

服務間呼叫httpclient連線池異常

本文轉自：https://blog.csdn.net/hry2015/article/details/78965690

1. 問題描述