[[398458]]

在內(nèi)網(wǎng)環(huán)境中，超時(shí)問題，網(wǎng)絡(luò)表示這個(gè)鍋我不背。

筆者對于超時(shí)的理解，隨著在工作中不斷實(shí)踐，其理解也越來越深刻，RocketMQ在生產(chǎn)環(huán)境遇到的超時(shí)問題，已經(jīng)困擾了我將近半年，現(xiàn)在終于取得了比較好的成果，和大家來做一個(gè)分享。

本次技術(shù)分享，由于涉及到網(wǎng)絡(luò)等諸多筆者不太熟悉的領(lǐng)域，如果存在錯(cuò)誤，請大家及時(shí)糾正，實(shí)現(xiàn)共同成長與進(jìn)步。

1、網(wǎng)絡(luò)超時(shí)現(xiàn)象

時(shí)不時(shí)總是接到項(xiàng)目組反饋說生產(chǎn)環(huán)境MQ發(fā)送超時(shí)，客戶端相關(guān)的日志截圖如下：

今天的故事將從張圖開始。

2、問題排查

2.1 初步分析

上圖中有兩條非常關(guān)鍵日志：

• invokeSync：wait response timeout exception

網(wǎng)絡(luò)調(diào)用超時(shí)

• recive response,but not matched any request

這條日志非常之關(guān)鍵，表示盡管客戶端在獲取服務(wù)端返回結(jié)果時(shí)超時(shí)了，但客戶端最終還是能收到服務(wù)端的響應(yīng)結(jié)果，只是此時(shí)客戶端已經(jīng)等待足夠時(shí)間后放棄處理了。

關(guān)于第二條日志，我再詳細(xì)闡述一下其運(yùn)作機(jī)制，其實(shí)也是用一條鏈接發(fā)送多個(gè)請求的編程套路。一條長連接，向服務(wù)端先后發(fā)送2個(gè)請求，客戶端在收到服務(wù)端響應(yīng)結(jié)果時(shí)，怎么判斷這個(gè)響應(yīng)結(jié)果對應(yīng)的是哪個(gè)請求呢?如下圖所示：

客戶端多個(gè)線程，通過一條連接發(fā)送了req1,req2兩個(gè)請求，但在服務(wù)端通常都是多線程處理，返回結(jié)果時(shí)可能會先收到req2的響應(yīng)，那客戶端如何識別服務(wù)端返回的數(shù)據(jù)是對應(yīng)哪個(gè)請求的呢?

解決辦法是客戶端在發(fā)送請求之前，會為該請求生成一個(gè)本機(jī)器唯一的請求id(requestId)，并且會采用Future模式，將requestId與Future對象放入一個(gè)Map中，然后將reqestId放入請求體中，服務(wù)端在返回響應(yīng)結(jié)果時(shí)將請求ID原封不動的放入到響應(yīng)結(jié)果中，當(dāng)客戶端收到響應(yīng)時(shí)，先界面出requestId，然后從緩存中找到對應(yīng)的Future對象，喚醒業(yè)務(wù)線程，將返回結(jié)構(gòu)通知給調(diào)用方，完成整個(gè)通信。

故從這里能看到，客戶端在指定時(shí)間內(nèi)沒有收到服務(wù)端的請求，但最終還是能收到，矛頭直接指向Broker端，是不是Broker有瓶頸，處理很慢導(dǎo)致的。

2.2 Broker端處理瓶頸分析

在我的“經(jīng)驗(yàn)”中，RocketMQ消息發(fā)送如果出現(xiàn)瓶頸，通常會返回各種各樣的Broker Busy，而且可以通過跟蹤Broker端寫入PageCache的數(shù)據(jù)指標(biāo)來判斷Broker是否遇到了瓶頸。

grep "PAGECACHERT" store.log 

得到的結(jié)果類似如下截圖：

圖片

溫馨提示:上圖是我本機(jī)中的截圖，當(dāng)時(shí)分析問題的時(shí)候，MQ集群中各個(gè)Broker中這些數(shù)據(jù)，寫入PageCache的時(shí)間沒有超過100ms的。

正是由于良好的pagecache寫入數(shù)據(jù)，根據(jù)如下粗糙的網(wǎng)絡(luò)交互特性，我提出將矛盾點(diǎn)轉(zhuǎn)移到網(wǎng)絡(luò)方面：

并且我還和業(yè)務(wù)方確定，雖然消息發(fā)送返回超時(shí)，但消息是被持久化到MQ中的，消費(fèi)端也能正常消費(fèi)，網(wǎng)絡(luò)組同事雖然從理論上來說局域網(wǎng)不會有什么問題，但鑒于上述現(xiàn)象，網(wǎng)絡(luò)組還是開啟了網(wǎng)絡(luò)方面的排查。

溫馨提示：最后證明是被我?guī)恕?/p>

2.3 網(wǎng)絡(luò)分析

通常網(wǎng)絡(luò)分析有兩種手段，netstat 與網(wǎng)絡(luò)抓包。

2.3.1 netstat查看Recv-Q與Send-Q

我們可以通過netstat重點(diǎn)觀察兩個(gè)指標(biāo)Recv-Q、Send-Q。

• Recv-Q

tcp通道的接受緩存區(qū)

• Send-Q

tcp通道的發(fā)送緩存區(qū)

在TCP中，Recv-Q與Send-Q的作用如下圖所示：

• 客戶端調(diào)用網(wǎng)絡(luò)通道，例如NIO的Channel寫入數(shù)據(jù)，數(shù)據(jù)首先是寫入到TCP的發(fā)送緩存區(qū)，如果發(fā)送發(fā)送區(qū)已滿，客戶端無法繼續(xù)向該通道發(fā)送請求，從NIO層面調(diào)用Channel底層的write方法，會返回0，表示發(fā)送緩沖區(qū)已滿，需要注冊寫事件，待發(fā)送緩存區(qū)有空閑時(shí)再通知上層應(yīng)用程序可以發(fā)消息。
• 數(shù)據(jù)進(jìn)入到發(fā)送緩存區(qū)后，接下來數(shù)據(jù)會隨網(wǎng)絡(luò)到達(dá)目標(biāo)端，首先進(jìn)入的是目標(biāo)端的接收緩存區(qū)，如果與NIO掛鉤的化，通道的讀事件會繼續(xù)，應(yīng)用從接收緩存區(qū)中成功讀取到字節(jié)后，會發(fā)送ACK給發(fā)送方。
• 發(fā)送方在收到ACK后，會刪除發(fā)送緩沖區(qū)中的數(shù)據(jù)，如果接收方一直不讀取數(shù)據(jù)，那發(fā)送方也無法發(fā)送數(shù)據(jù)。

網(wǎng)絡(luò)同事分布在客戶端、MQ服務(wù)器上通過每500ms采集一次netstat ，經(jīng)過對采集結(jié)果進(jìn)行匯總，出現(xiàn)如下圖所示：

從客戶端來看，客戶端的Recv-Q中會出現(xiàn)大量積壓，對應(yīng)的是MQ的Send-Q中出現(xiàn)大量積壓。

從上面的通訊模型來看，再次推斷是否是因?yàn)榭蛻舳藦木W(wǎng)絡(luò)中讀取字節(jié)太慢導(dǎo)致的，因?yàn)榭蛻舳藶樘摂M機(jī)，從netstat 結(jié)果來看，疑似是客戶端的問題(備注，其實(shí)最后并不是客戶端的問題，請別走神)。

2.3.2 網(wǎng)絡(luò)抓包

網(wǎng)絡(luò)組同事為了更加嚴(yán)謹(jǐn)，還發(fā)現(xiàn)了如下的包：

這里有一個(gè)問題非常值得懷疑，就是客戶端與服務(wù)端的滑動窗口只有190個(gè)字節(jié)，一個(gè)MQ消息發(fā)送返回包大概有250個(gè)字節(jié)左右，這樣會已響應(yīng)包需要傳輸兩次才能被接收，一開始以為這里是主要原因，但通過其他對比，發(fā)現(xiàn)不是滑動窗口大于250的客戶端也存在超時(shí)，從而判斷這個(gè)不是主要原因，后面網(wǎng)絡(luò)同事利用各種工具得出結(jié)論，網(wǎng)絡(luò)不存在問題，是應(yīng)用方面的問題。

想想也是，畢竟是局域網(wǎng)，那接下來我們根據(jù)netstat的結(jié)果，將目光放到了客戶端的讀性能上。

2.4 客戶端網(wǎng)絡(luò)讀性能瓶頸分析

為此，我為了證明讀寫方面的性能，我修改了RocketMQ CLient相關(guān)的包，加入了Netty性能采集方面的代碼，其代碼截圖如下：

我的主要思路是判斷客戶端對于一個(gè)通道，每一次讀事件觸發(fā)，一個(gè)通道會進(jìn)行多少次讀取操作，如果一次讀事件觸發(fā)，需要觸發(fā)很多次的讀取，說明一個(gè)通道中確實(shí)積壓了很多數(shù)據(jù)，網(wǎng)絡(luò)讀存在瓶頸。

但令人失望的是客戶端的網(wǎng)絡(luò)讀并不存在瓶頸，部分采集數(shù)據(jù)如下所示：

通過awk命令對其進(jìn)行分析，發(fā)現(xiàn)一次讀事件觸發(fā)，大部分通道讀兩次即可將讀緩存區(qū)中的數(shù)據(jù)抽取成功，讀方面并不存在瓶頸，對awk執(zhí)行的統(tǒng)計(jì)分析如下圖所示：

那矛頭又將指向Broker，是不是寫到緩存區(qū)中比較慢呢?

2.5 Broker端網(wǎng)絡(luò)層面瓶頸

經(jīng)過上面的分析，Broker服務(wù)端寫入pagecache很快，維度將響應(yīng)結(jié)果寫入網(wǎng)絡(luò)這個(gè)環(huán)節(jié)并未監(jiān)控，是不是寫入響應(yīng)結(jié)果并不及時(shí)，大量積壓在Netty的寫緩存區(qū)，從而導(dǎo)致并未及時(shí)寫入到TCP的發(fā)送緩沖區(qū)，從而造成超時(shí)。

筆者本來想也對其代碼進(jìn)行改造，從Netty層面去監(jiān)控服務(wù)端的寫性能，但考慮到風(fēng)險(xiǎn)較大，暫時(shí)沒有去修改代碼，而是再次認(rèn)真讀取了RocketMQ封裝Netty的代碼，在此次讀取源碼之前，我一直以為RocketMQ的網(wǎng)絡(luò)層基本不需要進(jìn)行參數(shù)優(yōu)化，因?yàn)楣镜姆?wù)器都是64核心的，而Netty的IO線程默認(rèn)都是CPU的核數(shù)，但在閱讀源碼發(fā)現(xiàn)，在RocketMQ中與IO相關(guān)的線程參數(shù)有如下兩個(gè)：

• serverSelectorThreads

默認(rèn)值為3。

• serverWorkerThreads

默認(rèn)值為8。

serverSelectorThreads，在Netty中，就是WorkGroup，即所謂的IO線程池，每一個(gè)線程池會持有一個(gè)NIO中的Selector對象用來進(jìn)行事件選擇，所有的通道會輪流注冊在這3個(gè)線程中，綁定在一個(gè)線程中的所有Channel，會串行進(jìn)行讀寫操作，即所有通道從TCP讀緩存區(qū)，將數(shù)據(jù)寫到發(fā)送緩存區(qū)都在這個(gè)線程中執(zhí)行。

我們的MQ服務(wù)器的配置，CPU的核屬都在64C及以上，用3個(gè)線程來做這個(gè)事情，顯然有點(diǎn)太“小家子氣”，該參數(shù)可以調(diào)優(yōu)。

serverWorkerThreads，在Netty的線程模型中，默認(rèn)情況下事件的傳播(編碼、解碼)都在IO線程中，即在上文中提到的Selector對象所在的線程，為了降低IO線程的壓力，RocketMQ單獨(dú)定義一個(gè)線程池，用于事件的傳播，即IO線程只負(fù)責(zé)網(wǎng)絡(luò)讀、寫，讀取的數(shù)據(jù)進(jìn)行解碼、寫入的數(shù)據(jù)進(jìn)行編碼等操作，單獨(dú)放在一個(gè)獨(dú)立的線程池，線程池線程數(shù)量由serverWorkerThreads指定。

看到這里，終于讓我心潮澎湃，感覺離真相越來越近了。參考Netty將IO線程設(shè)置為CPU核數(shù)的兩倍，我第一波參數(shù)優(yōu)化設(shè)置為serverSelectorThreads=16，serverWorkerThreads=32，在生產(chǎn)環(huán)境進(jìn)行一波驗(yàn)證。

經(jīng)過1個(gè)多月的驗(yàn)證，在集群機(jī)器數(shù)量減少(雙十一之后縮容)，只出現(xiàn)過極少數(shù)的消息發(fā)送超時(shí)，基本可以忽略不計(jì)。

3、總結(jié)

本文詳細(xì)介紹了筆者排查MQ發(fā)送超時(shí)的精力，最終定位到的是RocketMQ服務(wù)端關(guān)于網(wǎng)絡(luò)通信線程模型參數(shù)設(shè)置不合理。

之所以耗費(fèi)這么長時(shí)間，其實(shí)有值得反思的地方，我被我的“經(jīng)驗(yàn)”誤導(dǎo)了，其實(shí)以前我對超時(shí)的原因直接歸根于網(wǎng)絡(luò)，理由是RocketMQ的寫入PageCache數(shù)據(jù)非常好，基本都沒有超過100ms的寫入請求，以為RocketMQ服務(wù)端沒有性能瓶頸，并沒有從整個(gè)網(wǎng)絡(luò)通信層考慮。

本文轉(zhuǎn)載自微信公眾號「中間件興趣圈」，可以通過以下二維碼關(guān)注。轉(zhuǎn)載本文請聯(lián)系中間件興趣圈公眾號。