一裸影、起源

23年元旦期間，大家都沉浸在一片祥和的過(guò)節(jié)氣氛當(dāng)中军熏。

“滴滴滴”轩猩，這頭同事的電話響起，具體說(shuō)些什么我也沒(méi)太在意荡澎，但見(jiàn)同事接完電話之后展現(xiàn)出了一副懊惱夾雜著些許不耐煩的表情均践。

我不解問(wèn)道：“怎么了？”

同事：“剛剛運(yùn)營(yíng)反饋系統(tǒng)開(kāi)始刷白屏了摩幔，所有的請(qǐng)求一直處于pending狀態(tài)彤委。”

此刻我的大腦開(kāi)始飛速旋轉(zhuǎn)或衡，界面白屏焦影？前端是不是有一個(gè)初始化的請(qǐng)求？這個(gè)初始化的請(qǐng)求有問(wèn)題導(dǎo)致前端沒(méi)有往下運(yùn)行并渲染頁(yè)面封断？

我：“已經(jīng)登陸進(jìn)系統(tǒng)的用戶可以正常使用嗎斯辰？”

同事：“也不可以”。

那就不是初始化請(qǐng)求失敗的問(wèn)題了坡疼。

再往下分析椒涯，應(yīng)用進(jìn)程應(yīng)該沒(méi)有宕機(jī)，否則接口會(huì)快速響應(yīng)404回梧。

我：“所有接口都阻塞住了還是單個(gè)接口的問(wèn)題废岂，最近有沒(méi)有項(xiàng)目發(fā)版？”

同事：“運(yùn)營(yíng)反饋是所有接口都有阻塞情況狱意，這段時(shí)間一直沒(méi)有發(fā)版”湖苞。

那就怪了，近期沒(méi)有發(fā)版详囤，而且所有接口均有問(wèn)題财骨。

到此，基本可以判定出藏姐，這個(gè)問(wèn)題與業(yè)務(wù)無(wú)關(guān)隆箩，而是類(lèi)似基礎(chǔ)設(shè)施出現(xiàn)問(wèn)題導(dǎo)致了，比如網(wǎng)絡(luò)問(wèn)題羔杨、Java GC問(wèn)題捌臊、線程池線程短缺出現(xiàn)業(yè)務(wù)饑餓問(wèn)題等。

這種問(wèn)題勾起了我的興趣兜材，我決定自己上手問(wèn)題理澎，開(kāi)始排查…

二、表象

打開(kāi)系統(tǒng)曙寡，發(fā)現(xiàn)瀏覽器發(fā)出的接口確實(shí)都處于“pending”狀態(tài)糠爬。（Ps：pending是瀏覽器發(fā)出請(qǐng)求之后的一種狀態(tài)，代表該請(qǐng)求還未得到服務(wù)器響應(yīng)举庶，如果接口RT延遲高执隧，你就有可能經(jīng)常看到這種狀態(tài)）户侥；

接口處于pending狀態(tài)镀琉，我在本地使用telnet ip port命令連接應(yīng)用服務(wù)器端口也是正常的，到此說(shuō)明網(wǎng)絡(luò)與應(yīng)用進(jìn)程都是完好的添祸。

三滚粟、排查

打開(kāi)監(jiān)控系統(tǒng)查看了Java GC耗時(shí)、次數(shù)兩項(xiàng)指標(biāo)刃泌，發(fā)現(xiàn)和平時(shí)也沒(méi)什么不一樣凡壤。

查看了系統(tǒng)調(diào)用量發(fā)現(xiàn)與往常相似，沒(méi)有什么流量突刺耙替。

同事查看了那段時(shí)間的系統(tǒng)日志也未發(fā)現(xiàn)明顯的錯(cuò)誤亚侠。

我手里的鼠標(biāo)一直向下滑動(dòng)著，我和同事緊張的看著電腦俗扇，緊盯著各項(xiàng)指標(biāo)硝烂，希望能看出些端倪，并能以此為突破口铜幽。

果然滞谢，還是看到了…

下圖是近幾天的TCP連接數(shù)曲線圖：

TCP漲勢(shì)圖.jpeg

發(fā)現(xiàn)TCP連接一直處于只漲不降的趨勢(shì)（除了中間幾次的人為重啟機(jī)器）串稀。

我進(jìn)入服務(wù)器，熟練的敲起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 本機(jī)ip:端口  nginx機(jī)器  CLOSE_WAIT  pid/java
....

觀察了十分鐘狮杨，發(fā)現(xiàn)CLOSE_WAT狀態(tài)的TCP連接數(shù)一直處于增長(zhǎng)的狀態(tài)母截。并且觀察到所有的CLOSE_WAIT狀態(tài)的TCP都是與Nginx建立的，問(wèn)了運(yùn)維同學(xué)橄教，這臺(tái)Nginx是這臺(tái)后端應(yīng)用的代理清寇。

同事：“啊，原來(lái)是TCP連接數(shù)搗鬼护蝶，一直上漲但不釋放”华烟。

這一點(diǎn)和瀏覽器發(fā)出的接口一直處于Pending狀態(tài)剛好吻合起來(lái)了。一定是代碼出現(xiàn)了什么問(wèn)題持灰，導(dǎo)致接口延遲上升盔夜，所有的HTTP請(qǐng)求映射到底層就是TCP連接，應(yīng)用服務(wù)器一直沒(méi)有返回內(nèi)容搅方，那么TCP自然也不會(huì)釋放了（這里我們先不考慮現(xiàn)代HTTP協(xié)議的KeepAlive機(jī)制）比吭。

只見(jiàn)同事為了止血抓緊去重啟機(jī)器了，好讓這些TCP連接被強(qiáng)制關(guān)閉姨涡。

但我還有一點(diǎn)疑問(wèn)衩藤，TCP未能及時(shí)釋放確實(shí)有問(wèn)題不假，但即便是這樣涛漂，區(qū)區(qū)500個(gè)TCP連接赏表，也不至于達(dá)到操作系統(tǒng)的閾值，要知道操作系統(tǒng)對(duì)端口的限制理論上可以達(dá)到65535個(gè)匈仗。

那一定是有一個(gè)短板的中間件因達(dá)到了閾值而限制了整個(gè)系統(tǒng)瓢剿，很快我便想到了Tomcat，因?yàn)門(mén)omcat一定是每個(gè)業(yè)務(wù)接口都繞不過(guò)的中間件悠轩。

雖然機(jī)器已經(jīng)重啟了间狂，但我們有服務(wù)治理相關(guān)的平臺(tái)可以調(diào)出任意一個(gè)時(shí)間點(diǎn)的線程狀態(tài)，不看不知道火架，一看嚇一跳鉴象，所有以“http-nio-xxx”為前綴的線程全部阻塞在方法：SocketInputStream.read0方法中。熟悉這個(gè)前綴線程的人都知道何鸡，這是Tomcat線程池纺弊。

我：”查一下日志，看看接口AOP有沒(méi)有捕捉到請(qǐng)求信息骡男？“

同事：“捕捉到了”

我：“隨機(jī)抽取幾個(gè)請(qǐng)求淆游，看看接口AOP是否捕捉到了接口響應(yīng)信息”

同事抓緊去查了，不一會(huì)兒驚訝的說(shuō)道：“老朱，還真有很多請(qǐng)求接口響應(yīng)AOP沒(méi)有捕獲到犹菱，那就是說(shuō)這些請(qǐng)求一直沒(méi)有處理完”拾稳。

同事又說(shuō)道：“老朱，這個(gè)項(xiàng)目比較特殊已亥，項(xiàng)目中所有的接口基本只做了透?jìng)鞯氖虑樾芾担?xiàng)目只是做簡(jiǎn)單的數(shù)據(jù)加工，然后請(qǐng)求其他系統(tǒng)虑椎，最后針對(duì)結(jié)果集再進(jìn)行過(guò)濾、轉(zhuǎn)換返回給前端”

我：“啊俱笛，原來(lái)是這樣捆姜，目前使用的HTTP客戶端是什么？”

同事：“Apache HttpClient”

我：“Apache HttpClient迎膜？三個(gè)超時(shí)時(shí)間都設(shè)置了吧泥技？“

同事：“嗯，都設(shè)置了磕仅，connectTimeout珊豹、socketTimeout、connectionRequestTimeout都根據(jù)項(xiàng)目的性質(zhì)調(diào)試過(guò)了榕订，并且數(shù)據(jù)流也都妥善處理了”

我有些不解店茶，所有的超時(shí)時(shí)間都設(shè)置好了，那為什么還會(huì)有大量的Tomcat線程阻塞在SocketInputstream.read0方法中呢劫恒，最終導(dǎo)致TCP持續(xù)飆高贩幻。

我和同事都陷入了困境，進(jìn)入兩難處境两嘴，不知道如何繼續(xù)排查丛楚，機(jī)器重啟確實(shí)可以強(qiáng)制釋放TCP但是這方法治標(biāo)不治本。

同事：“啊憔辫，這趣些，怎么會(huì)這樣”

我：“怎么了？贰您！吞吞吐吐”

同事：“我記得之前明明在這些應(yīng)用里都加了接口AOP日志坏平，剛剛看到我們項(xiàng)目有日志，但是其他系統(tǒng)中居然沒(méi)有日志…

至此我有個(gè)大膽的猜測(cè)枉圃，請(qǐng)求進(jìn)入項(xiàng)目之后功茴，項(xiàng)目加工請(qǐng)求并轉(zhuǎn)發(fā)給其他項(xiàng)目，但轉(zhuǎn)發(fā)給系統(tǒng)項(xiàng)目的這段網(wǎng)絡(luò)出現(xiàn)了什么問(wèn)題（因?yàn)槠渌到y(tǒng)并未收到請(qǐng)求）孽亲，又因?yàn)榉N種原因?qū)е鲁瑫r(shí)時(shí)間并未生效坎穿，慢慢的項(xiàng)目中所有Tomcat線程都阻塞在了SocketInputstream中的read0方法中，最后Tomcat無(wú)空閑線程可去處理用戶提交的新的請(qǐng)求。

但是什么情況下Apache HttpClient中的超時(shí)時(shí)間不生效呢玲昧？

直到我看到了一篇JDK官網(wǎng)說(shuō)明：

Bug ID: JDK-8172578 SocketInputStream.socketRead0 can hang even with soTimeout set

SocketInputStream.socketRead0 can hang even with soTimeout set

在第二篇文章中有詳細(xì)描述了SocketTimeOut參數(shù)失效的原因栖茉，大致意思是：因?yàn)镺S select方法存在虛假喚醒的問(wèn)題導(dǎo)致線程提前進(jìn)行讀取，但又因?yàn)椴](méi)有實(shí)際數(shù)據(jù)因此造成了讀取阻塞孵延。

而我們的JDK版本是1.8.0_91吕漂，也就是低于JDK修復(fù)版本，當(dāng)OS發(fā)出虛假喚醒之后尘应，導(dǎo)致Java線程進(jìn)入阻塞讀取狀態(tài)惶凝，最終導(dǎo)致socketTimeout失效。

事情到這就解釋的通了犬钢，我再來(lái)根據(jù)現(xiàn)象與各項(xiàng)指標(biāo)結(jié)合起來(lái)從頭到尾的闡述一波苍鲜。

應(yīng)用拓?fù)鋱D.png

這里先祭出項(xiàng)目的拓?fù)鋱D。

應(yīng)用A是這次案發(fā)地點(diǎn)玷犹，應(yīng)用A的大多數(shù)功能只是做請(qǐng)求透?jìng)鞴ぷ骰焯希瑢⒂脩粽?qǐng)求的參數(shù)做過(guò)濾、篩選歹颓、添油加醋發(fā)送給應(yīng)用B坯屿。

根據(jù)上述的拓?fù)湫再|(zhì)，以應(yīng)用A為中心會(huì)有兩段請(qǐng)求巍扛，這里標(biāo)識(shí)為A段领跛、B段。

案發(fā)時(shí)間前幾個(gè)小時(shí)电湘，起初系統(tǒng)穩(wěn)如老狗隔节。應(yīng)用A穩(wěn)定的處理著Nginx轉(zhuǎn)發(fā)來(lái)的前端請(qǐng)求，并包裝發(fā)送給應(yīng)用B寂呛，然后將應(yīng)用B返回來(lái)的數(shù)據(jù)進(jìn)行篩選怎诫、處理然后返回給用戶。

然而好景不長(zhǎng)贷痪，B段出現(xiàn)了一些網(wǎng)絡(luò)丟包幻妓、抖動(dòng)等情況變得開(kāi)始不穩(wěn)定了，搭配上JDK8U152版本之前可能會(huì)受到操作系統(tǒng)的select虛假喚醒的情況劫拢，慢慢的Tomcat很多線程都阻塞在了SocketInputstream的read0方法上肉津，這一點(diǎn)和之前看到的線程Dump信息一致。

看了眼項(xiàng)目對(duì)Tomcat的線程數(shù)配置：server.tomcat.max-threads=**400**舱沧，而線程Dump出的信息中剛好有400個(gè)線程阻塞在了read0方法中妹沙。

嗯，沒(méi)錯(cuò)熟吏，就是這樣距糖，最后Tomcat成為了整個(gè)項(xiàng)目的瓶頸玄窝。

四、解決

知道了悍引，問(wèn)題就非常方便解決了恩脂，我主要采取了三個(gè)措施：

1. 將項(xiàng)目中使用的BIO HttpClient化成NIO的方式：HttpAsyncClient
2. 升級(jí)JDK為JDK8u152版本
3. 添加耗時(shí)兜底方案，若超過(guò)SocketTimeout時(shí)間趣斤，應(yīng)用A請(qǐng)求B應(yīng)用還未結(jié)束俩块，則手動(dòng)關(guān)閉TCP連接，Tomcat主線程繼續(xù)向下運(yùn)行

其中第二點(diǎn)不用說(shuō)浓领，我通過(guò)一段偽代碼來(lái)說(shuō)明一下1和3.

public static String getHttpClientResult(CloseableHttpAsyncClient asyncHttpClient, HttpRequestBase httpMethod) throws IOException {
                String content = "";        
                // TCP強(qiáng)制斷開(kāi)標(biāo)志
        boolean abortFlag = true;
                HttpResponse response = null;
        // 執(zhí)行請(qǐng)求
        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è)置標(biāo)志并且向下運(yùn)行
            Thread.currentThread().interrupt();
        } catch (ExecutionException e) {
            // http執(zhí)行異常，包括readTimeOut联贩、connectTimeOut
            log.error("當(dāng)前線程:{},請(qǐng)求異常,發(fā)送TCP RST包強(qiáng)制斷開(kāi)", Thread.currentThread().getName());
        } catch (TimeoutException e) {
            /**
             * future get 超時(shí) 兜底方案壮啊，避免主線程阻塞在read方法中
             * @see java.net.SocketInputStream#socketRead0(java.io.FileDescriptor, byte[], int, int, int)
             * 若超時(shí)則發(fā)送RST包以強(qiáng)制連接雙方斷開(kāi)TCP
             */
            log.error("當(dāng)前線程:{},超時(shí):{}秒,仍未獲取到數(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ā)版撑蒜，目前我的這位同事在也沒(méi)有被運(yùn)維‘騷擾’過(guò)了，目前TCP升降趨勢(shì)穩(wěn)定喜人 玄渗，如下：

修復(fù)后的TCP漲勢(shì)圖.jpeg