一、起源
23年元旦期間，大家都沉浸在一片祥和的過節(jié)氣氛當中。
“滴滴滴”，這頭同事的電話響起，具體說些什么我也沒太在意，但見同事接完電話之后展現(xiàn)出了一副懊惱夾雜著些許不耐煩的表情。
我不解問道：“怎么了？”
同事：“剛剛運營反饋系統(tǒng)開始刷白屏了，所有的請求一直處于pending狀態(tài)。”
此刻我的大腦開始飛速旋轉(zhuǎn)，界面白屏？前端是不是有一個初始化的請求？這個初始化的請求有問題導致前端沒有往下運行并渲染頁面？
我：“已經(jīng)登陸進系統(tǒng)的用戶可以正常使用嗎？”
同事：“也不可以”。
那就不是初始化請求失敗的問題了。
再往下分析，應用進程應該沒有宕機，否則接口會快速響應404。
我：“所有接口都阻塞住了還是單個接口的問題，最近有沒有項目發(fā)版？”
同事：“運營反饋是所有接口都有阻塞情況，這段時間一直沒有發(fā)版”。
那就怪了，近期沒有發(fā)版，而且所有接口均有問題。
到此，基本可以判定出，這個問題與業(yè)務無關(guān)，而是類似基礎(chǔ)設(shè)施出現(xiàn)問題導致了，比如網(wǎng)絡(luò)問題、Java GC問題、線程池線程短缺出現(xiàn)業(yè)務饑餓問題等。
這種問題勾起了我的興趣，我決定自己上手問題，開始排查…
二、表象
打開系統(tǒng)，發(fā)現(xiàn)瀏覽器發(fā)出的接口確實都處于“pending”狀態(tài)。（Ps：pending是瀏覽器發(fā)出請求之后的一種狀態(tài)，代表該請求還未得到服務器響應，如果接口RT延遲高，你就有可能經(jīng)?？吹竭@種狀態(tài)）；
接口處于pending狀態(tài)，我在本地使用telnet ip port命令連接應用服務器端口也是正常的，到此說明網(wǎng)絡(luò)與應用進程都是完好的。
三、排查
打開監(jiān)控系統(tǒng)查看了Java GC耗時、次數(shù)兩項指標，發(fā)現(xiàn)和平時也沒什么不一樣。
查看了系統(tǒng)調(diào)用量發(fā)現(xiàn)與往常相似，沒有什么流量突刺。
同事查看了那段時間的系統(tǒng)日志也未發(fā)現(xiàn)明顯的錯誤。
我手里的鼠標一直向下滑動著，我和同事緊張的看著電腦，緊盯著各項指標，希望能看出些端倪，并能以此為突破口。
果然，還是看到了…
下圖是近幾天的TCP連接數(shù)曲線圖：
發(fā)現(xiàn)TCP連接一直處于只漲不降的趨勢（除了中間幾次的人為重啟機器）。
我進入服務器，熟練的敲起Linux命令：
[root] $ **netstat -na | grep '8089' | awk '/^tcp/ {++S[$NF]} END {for(a in S) print a, S[a]}'
LISTEN 8
CLOSE_WAIT 35
ESTABLISHED 108
SYN_SENT 1
TIME_WAIT 9**
[root] $ netstat -ntp | grep 'CLOSE_WAIT'
tcp 1 0 本機ip:端口 nginx機器 CLOSE_WAIT pid/java
....
觀察了十分鐘，發(fā)現(xiàn)CLOSE_WAT狀態(tài)的TCP連接數(shù)一直處于增長的狀態(tài)。并且觀察到所有的CLOSE_WAIT狀態(tài)的TCP都是與Nginx建立的，問了運維同學，這臺Nginx是這臺后端應用的代理。
同事：“啊，原來是TCP連接數(shù)搗鬼，一直上漲但不釋放”。
這一點和瀏覽器發(fā)出的接口一直處于Pending狀態(tài)剛好吻合起來了。一定是代碼出現(xiàn)了什么問題，導致接口延遲上升，所有的HTTP請求映射到底層就是TCP連接，應用服務器一直沒有返回內(nèi)容，那么TCP自然也不會釋放了（這里我們先不考慮現(xiàn)代HTTP協(xié)議的KeepAlive機制）。
只見同事為了止血抓緊去重啟機器了，好讓這些TCP連接被強制關(guān)閉。
但我還有一點疑問，TCP未能及時釋放確實有問題不假，但即便是這樣，區(qū)區(qū)500個TCP連接，也不至于達到操作系統(tǒng)的閾值，要知道操作系統(tǒng)對端口的限制理論上可以達到65535個。
那一定是有一個短板的中間件因達到了閾值而限制了整個系統(tǒng)，很快我便想到了Tomcat，因為Tomcat一定是每個業(yè)務接口都繞不過的中間件。
雖然機器已經(jīng)重啟了，但我們有服務治理相關(guān)的平臺可以調(diào)出任意一個時間點的線程狀態(tài)，不看不知道，一看嚇一跳，所有以“http-nio-xxx”為前綴的線程全部阻塞在方法：SocketInputStream.read0方法中。熟悉這個前綴線程的人都知道，這是Tomcat線程池。
我：”查一下日志，看看接口AOP有沒有捕捉到請求信息？“
同事：“捕捉到了”
我：“隨機抽取幾個請求，看看接口AOP是否捕捉到了接口響應信息”
同事抓緊去查了，不一會兒驚訝的說道：“老朱，還真有很多請求接口響應AOP沒有捕獲到，那就是說這些請求一直沒有處理完”。
同事又說道：“老朱，這個項目比較特殊，項目中所有的接口基本只做了透傳的事情，項目只是做簡單的數(shù)據(jù)加工，然后請求其他系統(tǒng)，最后針對結(jié)果集再進行過濾、轉(zhuǎn)換返回給前端”
我：“啊，原來是這樣，目前使用的HTTP客戶端是什么？”
同事：“Apache HttpClient”
我：“Apache HttpClient？三個超時時間都設(shè)置了吧？“
同事：“嗯，都設(shè)置了，connectTimeout、socketTimeout、connectionRequestTimeout都根據(jù)項目的性質(zhì)調(diào)試過了，并且數(shù)據(jù)流也都妥善處理了”
我有些不解，所有的超時時間都設(shè)置好了，那為什么還會有大量的Tomcat線程阻塞在SocketInputstream.read0方法中呢，最終導致TCP持續(xù)飆高。
我和同事都陷入了困境，進入兩難處境，不知道如何繼續(xù)排查，機器重啟確實可以強制釋放TCP但是這方法治標不治本。
同事：“啊，這，怎么會這樣”
我：“怎么了？！吞吞吐吐”
同事：“我記得之前明明在這些應用里都加了接口AOP日志，剛剛看到我們項目有日志，但是其他系統(tǒng)中居然沒有日志…
至此我有個大膽的猜測，請求進入項目之后，項目加工請求并轉(zhuǎn)發(fā)給其他項目，但轉(zhuǎn)發(fā)給系統(tǒng)項目的這段網(wǎng)絡(luò)出現(xiàn)了什么問題（因為其他系統(tǒng)并未收到請求），又因為種種原因?qū)е鲁瑫r時間并未生效，慢慢的項目中所有Tomcat線程都阻塞在了SocketInputstream中的read0方法中，最后Tomcat無空閑線程可去處理用戶提交的新的請求。
但是什么情況下Apache HttpClient中的超時時間不生效呢？
直到我看到了一篇JDK官網(wǎng)說明：
Bug ID: JDK-8172578 SocketInputStream.socketRead0 can hang even with soTimeout set
SocketInputStream.socketRead0 can hang even with soTimeout set
在第二篇文章中有詳細描述了SocketTimeOut參數(shù)失效的原因，大致意思是：因為OS select方法存在虛假喚醒的問題導致線程提前進行讀取，但又因為并沒有實際數(shù)據(jù)因此造成了讀取阻塞。
而我們的JDK版本是1.8.0_91，也就是低于JDK修復版本，當OS發(fā)出虛假喚醒之后，導致Java線程進入阻塞讀取狀態(tài)，最終導致socketTimeout失效。
事情到這就解釋的通了，我再來根據(jù)現(xiàn)象與各項指標結(jié)合起來從頭到尾的闡述一波。
這里先祭出項目的拓撲圖。
應用A是這次案發(fā)地點，應用A的大多數(shù)功能只是做請求透傳工作，將用戶請求的參數(shù)做過濾、篩選、添油加醋發(fā)送給應用B。
根據(jù)上述的拓撲性質(zhì)，以應用A為中心會有兩段請求，這里標識為A段、B段。
案發(fā)時間前幾個小時，起初系統(tǒng)穩(wěn)如老狗。應用A穩(wěn)定的處理著Nginx轉(zhuǎn)發(fā)來的前端請求，并包裝發(fā)送給應用B，然后將應用B返回來的數(shù)據(jù)進行篩選、處理然后返回給用戶。
然而好景不長，B段出現(xiàn)了一些網(wǎng)絡(luò)丟包、抖動等情況變得開始不穩(wěn)定了，搭配上JDK8U152版本之前可能會受到操作系統(tǒng)的select虛假喚醒的情況，慢慢的Tomcat很多線程都阻塞在了SocketInputstream的read0方法上，這一點和之前看到的線程Dump信息一致。
看了眼項目對Tomcat的線程數(shù)配置：server.tomcat.max-threads=**400**，而線程Dump出的信息中剛好有400個線程阻塞在了read0方法中。
嗯，沒錯，就是這樣，最后Tomcat成為了整個項目的瓶頸。
四、解決
知道了，問題就非常方便解決了，我主要采取了三個措施：
- 將項目中使用的BIO HttpClient化成NIO的方式：HttpAsyncClient
- 升級JDK為JDK8u152版本
- 添加耗時兜底方案，若超過SocketTimeout時間，應用A請求B應用還未結(jié)束，則手動關(guān)閉TCP連接，Tomcat主線程繼續(xù)向下運行
其中第二點不用說，我通過一段偽代碼來說明一下1和3.
public static String getHttpClientResult(CloseableHttpAsyncClient asyncHttpClient, HttpRequestBase httpMethod) throws IOException {
String content = "";
// TCP強制斷開標志
boolean abortFlag = true;
HttpResponse response = null;
// 執(zhí)行請求
Future<HttpResponse> httpResponseFuture = asyncHttpClient.execute(httpMethod, null);
try {
httpResponse = httpResponseFuture.get(SOCKET_TIMEOUT, TimeUnit.MILLISECONDS);
abortFlag = false;
// 獲取返回結(jié)果
if (httpResponse.getEntity() != null) {
content = EntityUtils.toString(httpResponse.getEntity(), ENCODING);
}
} catch (InterruptedException e) {
// 線程被打斷，重新設(shè)置標志并且向下運行
Thread.currentThread().interrupt();
} catch (ExecutionException e) {
// http執(zhí)行異常，包括readTimeOut、connectTimeOut
log.error("當前線程:{},請求異常,發(fā)送TCP RST包強制斷開", Thread.currentThread().getName());
} catch (TimeoutException e) {
/**
* future get 超時 兜底方案，避免主線程阻塞在read方法中
* @see java.net.SocketInputStream#socketRead0(java.io.FileDescriptor, byte[], int, int, int)
* 若超時則發(fā)送RST包以強制連接雙方斷開TCP
*/
log.error("當前線程:{},超時:{}秒,仍未獲取到數(shù)據(jù),發(fā)送RST包", Thread.currentThread().getName(), SOCKET_TIMEOUT);
} finally {
if (abortFlag) {
httpMethod.abort();
}
// 釋放資源
if (!Objects.isNull(httpResponse)
&& !Objects.isNull(httpResponse.getEntity())
&& !Objects.isNull(httpResponse.getEntity().getContent())) {
httpResponse.getEntity().getContent().close();
}
}
return abortFlag ? null : content;
}
代碼優(yōu)化完畢，趕緊發(fā)版，目前我的這位同事在也沒有被運維‘騷擾’過了，目前TCP升降趨勢穩(wěn)定喜人 ，如下：
