如何解決dubbo流量上線時(shí)的非平滑問題
如何解決dubbo流量上線時(shí)的非平滑問題，很多新手對此不是很清楚，為了幫助大家解決這個(gè)難題，下面小編將為大家詳細(xì)講解，有這方面需求的人可以來學(xué)習(xí)下，希望你能有所收獲。
公司主營業(yè)務(wù)：網(wǎng)站設(shè)計(jì)制作、成都網(wǎng)站制作、移動(dòng)網(wǎng)站開發(fā)等業(yè)務(wù)。幫助企業(yè)客戶真正實(shí)現(xiàn)互聯(lián)網(wǎng)宣傳，提高企業(yè)的競爭能力。創(chuàng)新互聯(lián)是一支青春激揚(yáng)、勤奮敬業(yè)、活力青春激揚(yáng)、勤奮敬業(yè)、活力澎湃、和諧高效的團(tuán)隊(duì)。公司秉承以“開放、自由、嚴(yán)謹(jǐn)、自律”為核心的企業(yè)文化，感謝他們對我們的高要求，感謝他們從不同領(lǐng)域給我們帶來的挑戰(zhàn)，讓我們激情的團(tuán)隊(duì)有機(jī)會(huì)用頭腦與智慧不斷的給客戶帶來驚喜。創(chuàng)新互聯(lián)推出旅順口免費(fèi)做網(wǎng)站回饋大家。
前言
筆者最近解決了一個(gè)困擾了業(yè)務(wù)系統(tǒng)很久的問題。這個(gè)問題只在發(fā)布時(shí)出現(xiàn)，每次只影響一兩次調(diào)用，相較于其它的問題來說，這個(gè)問題有點(diǎn)不夠受重視。由于種種原因，使得這個(gè)問題到了業(yè)務(wù)必須解決的程度，于是就到了筆者的手上。
問題現(xiàn)場
我們采用的是dubbo服務(wù)，這是個(gè)穩(wěn)定成熟的RPC框架。但是我們在某些應(yīng)用中會(huì)發(fā)現(xiàn)，只要這個(gè)應(yīng)用一發(fā)布(或者重啟),就會(huì)出現(xiàn)請求超時(shí)的問題，如下圖所示: 
而且都是第一筆請求會(huì)報(bào)錯(cuò)，之后就再也沒有問題了。
排查日志
好了，現(xiàn)象我們知道了，于是開始排查那個(gè)時(shí)間點(diǎn)的日志。Server端沒有任何日志，而Client(App1)端報(bào)錯(cuò)超時(shí)。報(bào)錯(cuò)如下所示:
2019-08-22 20:33:50.798 com.alibaba.dubbo.rpc.RpcException: Failed to invoke the method set in the servce XXXFacade, tries 1 times ...... start time: 2019-08-22 20:32:50.474 end time: 2019-08-22 30:33:50.767 timeout=60000,channel:/1.1.1.1:44502->2.2.2.2:20880
看日志報(bào)錯(cuò)是這個(gè)tcp五元組(1.1.1.1:44502->2.2.2.2:20880)有問題。于是筆者netstat了一下，查看當(dāng)前此連接的狀態(tài):
netstat -anp | grep 44502 1.1.1.1:44502 2.2.2.2:20880 ESTABLISHED
這個(gè)連接處于正常的ESTABLISHED狀態(tài)，而且調(diào)用2.2.2.2這個(gè)server的連接只有這一個(gè),那后續(xù)這臺(tái)機(jī)器調(diào)用2.2.2.2這個(gè)server肯定只用到了這個(gè)連接，查看日志發(fā)現(xiàn)除了這一筆，其它調(diào)用一切正常。
思路1:Server端處理超時(shí)
按照上面的報(bào)錯(cuò)，肯定這個(gè)連接有問題，按照正常思路，是否是第一筆調(diào)用的時(shí)候各種初始化過程(以及jit)導(dǎo)致server處理請求過慢?如下圖所示: 
但這個(gè)問題很快被第二筆請求(和第一筆請求間隔只有一秒)給否決了。也就是說第一筆請求花了60s還超時(shí)，而第二筆請求在第一筆請求發(fā)出后的一秒后發(fā)出就成功了(而且耗時(shí)是毫秒級(jí)的)。如果按照上述思路，第二筆請求也應(yīng)該等各種初始化完成之后再處理，也應(yīng)該卡相當(dāng)長的一段時(shí)間才對。再加上server端沒有任何日志，就感覺好像沒有收到請求。
思路2:Client端沒有發(fā)送成功
于是我們開始了思路2，Client端沒有發(fā)送成功。由于Dubbo是基于Netty的，其請求傳輸?shù)奶幚磉^程是個(gè)NIO的異步化過程(只不過通過使用future機(jī)制對業(yè)務(wù)來說是同步的)。首先我們看下dubbo的超時(shí)檢測機(jī)制,如下圖所示: 
當(dāng)然，還有future的超時(shí)機(jī)制,這邊我就不列舉出來了。從這個(gè)機(jī)制可以看出，就算Client端發(fā)送的時(shí)候(因?yàn)閷懯菍懙絪ocket的writebuffer里面，一般不會(huì)滿，所以不會(huì)報(bào)錯(cuò))沒有發(fā)送出去,也不會(huì)在發(fā)的那一刻報(bào)出錯(cuò)誤，而是要等定時(shí)掃描。為了驗(yàn)證這個(gè)猜想，筆者就開始著手排查連接的日志。
連接日志
因?yàn)橐?guī)律是第一筆失敗，那么筆者開始懷疑連接創(chuàng)建的有問題,但后面的請求成功又表明連接創(chuàng)建是沒有問題的。那么，是否是連接還沒有創(chuàng)建好就發(fā)送了第一筆請求呢？帶著這樣的疑問，筆者找到了如下的日志:
2019-08-22 20:32:51.876 （DubboClientReconnectTimer-thread-1) Successed connect to server /1.1.1.1:20880 ... channel is NettyChannel /1.1.1.1:44502 => /2.2.2.2:20880
由日志所示,1.1.1.1:44502這個(gè)連接串是在2019-08-22 20:32:51.876連接成功的，而上面出錯(cuò)的日志起始時(shí)間為
請求發(fā)送時(shí)間:2019-08-22 20:32:50.474 連接開始建立時(shí)間:2019-08-22 20:32:51.876 連接成功建立時(shí)間:2019-08-22 20:32:51.876
請求在連接成功建立之前，感覺非常符合筆者上述的猜想。但細(xì)想又不對，上述日志表示的是在2019-08-22 20:32:51.876開始建立連接并在1ms內(nèi)建立成功連接。而請求確是50s發(fā)出的，dubbo本身代碼不可能在連接還沒做出創(chuàng)建動(dòng)作的時(shí)候就開始發(fā)送請求(因?yàn)?4502是由kernel分配的，沒到創(chuàng)建連接動(dòng)作之前是不可能知道這個(gè)端口號(hào)的,但它卻在日志里面打印出來了),如下圖所示： 
思考了一段時(shí)間，筆者覺得這種情況很有可能是日志是不準(zhǔn)確的，它僅僅打印當(dāng)前連接包裝類中的信息，之前那個(gè)出錯(cuò)的連接已經(jīng)被新建的連接掩蓋了(在日志中)。我們看下dubbo中對應(yīng)的打印日志代碼:
private String getTimeoutMessage(boolean scan) {
long nowTimestamp = System.currentTimeMillis();
return (sent > 0 ? "Waiting server-side response timeout" : "Sending request timeout in client-side")
+ (scan ? " by scan timer" : "") + ". start time: "
+ (new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS").format(new Date(start))) + ", end time: "
+ (new SimpleDateFormat("yyyy-MM-dd HH:mm:ss.SSS").format(new Date())) + ","
+ (sent > 0 ? " client elapsed: " + (sent - start)
+ " ms, server elapsed: " + (nowTimestamp - sent)
: " elapsed: " + (nowTimestamp - start)) + " ms, timeout: "
+ timeout + " ms, request: " + request + ", channel: " + channel.getLocalAddress()
+ " -> " + channel.getRemoteAddress();
}這個(gè)1.1.1.1:44502是由channel.getLocalAddress()得出的,我們看下調(diào)用鏈:
channel.getLocalAddress() |->nettyClient.channel.getLocalAddress()
筆者看了下代碼，dubbo在reconnect(重新連接的時(shí)候)會(huì)把nettyClient.channel換掉，從而可能打印出來和發(fā)送請求時(shí)不同的client端口信息。再加上日志里面打印出來的線程號(hào)DubboClientReconnectTimer-thread-1就幾乎可以確定，之前還有一個(gè)連接，只不過這個(gè)連接失敗了，新建的連接為1.1.1.1f :44502。再仔細(xì)的找了下日志，發(fā)現(xiàn)了下面這條日志:
------------------日志分割線---------------- 2019-08-22 20:32:51,876（DubboClientReconnectTimer-thread-1) Close old Netty channel /1.1.1.1:44471 :> 2.2.2.2:20880 on create new netty channel /1.1.1.1:44502 => /2.2.2.2:20880 ------------------日志分割線---------------- 2019-08-22 20:32:51.876 （DubboClientReconnectTimer-thread-1) Successed connect to server /1.1.1.1:20880 ... channel is NettyChannel /1.1.1.1:44502 => /2.2.2.2:20880
即是說dubbo在把1.1.1.1:44471關(guān)閉后，立馬創(chuàng)建了2.2.2.2:44502 那么整體過程如下圖所示: 
我們看下1.1.1.1:44471是什么時(shí)候創(chuàng)建的,繼續(xù)搜尋日志:
zgrep '1.1.1.1:44471' dubbo.log.1.zip 2019-08-22 20:31:59.871 (ZkClient-EventThread-23) Successed connect to server /2.2.2.2:20880 ... channel is NettyChannel /1.1.1.1: 44471 => /2.2.2.2:20880 ------------------日志分割線---------------- 2019-08-22 20:32:51,876（DubboClientReconnectTimer-thread-1) Close old Netty channel /1.1.1.1:44471 :> 2.2.2.2:20880
發(fā)現(xiàn)其在
連接1創(chuàng)建時(shí)間:2019-08-22 20:31:59.871 請求發(fā)送時(shí)間:2019-08-22 20:32:50.474 連接1關(guān)閉時(shí)間:2019-08-22 20:32:51,876
而且筆者翻看了業(yè)務(wù)日志，發(fā)現(xiàn)連接1在其生命周期內(nèi)有且只有一筆請求，這筆請求就是報(bào)錯(cuò)的請求，由此可以看出這個(gè)連接1從建立成功開始就無法使用。
為什么連接建立成功確無法使用
首先由于dubbo是基于netty的，這種成熟的廣泛應(yīng)用的框架在創(chuàng)建連接這種問題上不應(yīng)該會(huì)有問題。 而筆者仔細(xì)翻看netty翻看netty源碼也確實(shí)遵守了NIO的編寫套路。那么問題可能出現(xiàn)在環(huán)境上,既然應(yīng)用(client/server)本身日志找不到更多的有用信息，那么看看操作系統(tǒng)能否有什么可以追尋的蛛絲馬跡。于是筆者首先用dmesg查看下kernel打印的日志，client端沒發(fā)現(xiàn)什么有用的信息，但server端的dmesg引起了筆者的注意
possible SYN flooding on port 20880. Sending cookies. possible SYN flooding on port 20880. Sending cookies. possible SYN flooding on port 20880. Sending cookies. possible SYN flooding on port 20880. Sending cookies. possible SYN flooding on port 20880. Sending cookies.
其字面意思為kenerl本身可能在20880端口遭到了SYN泛洪攻擊，發(fā)送cookies。 這種日志會(huì)在并發(fā)連接過多的情況下由kernel打印出來。筆者netstat了下頻繁出問題的機(jī)器，發(fā)現(xiàn)其特點(diǎn)都是連接特別多(達(dá)到了好幾千甚至上萬)。而dubbo的上線機(jī)制是只要注冊到zookeeper后，zookeeper給所有的機(jī)器推送，所有的機(jī)器立馬連接，這樣就會(huì)造成比較高的并發(fā)連接，如下圖所示: 
既然懷疑到了高并發(fā)connect，那么筆者就立馬用netstat看下kernel對于tcp的統(tǒng)計(jì)信息:
netstat -s ... TcpExt: ... 1607 times the listen queue of a socket overflowed ...
果然有這種并發(fā)連接導(dǎo)致的統(tǒng)計(jì)信息,socket overflowed表示的是server端的tcp_backlog隊(duì)列溢出了。到這里筆者有八成把握是這個(gè)tcp_backlog設(shè)置的過小的問題了。下面就是分析，tcp_backlog溢出為什么會(huì)導(dǎo)致上述連接雖然成功但是第一筆報(bào)錯(cuò)的現(xiàn)象，從而和日志相印證，來證明筆者的猜測。
tcp_backlog溢出分析
tcp的三次握手
先從tcp的三次握手進(jìn)行著手分析，從tcp_v4_do_rcv函數(shù)進(jìn)行入手，因?yàn)檫@個(gè)函數(shù)是tcp協(xié)議獲取packet的地方,當(dāng)三次握手的SYN第一次進(jìn)來的時(shí)候，應(yīng)該會(huì)走這個(gè)函數(shù):
// 先考察一下三次握手的第一個(gè)SYN
int tcp_v4_do_rcv(struct sock *sk, struct sk_buff *skb){
if (sk->sk_state == TCP_LISTEN) {
......
// 由于現(xiàn)在連接處于第一個(gè)SYN,現(xiàn)在server端的socket處于LISTEN狀態(tài)
struct sock *nsk = tcp_v4_hnd_req(sk, skb);
......
}
}
// 我們繼續(xù)看下tcp_v4_hnd_req代碼,三次握手第一個(gè)SYN kernel走的分支
tcp_v4_do_rcv
/* 由于tcp_v4_hnd_req沒有發(fā)現(xiàn)和此五元組對應(yīng)的連接,所以do nothing */
|->tcp_v4_hnd_req
|->tcp_rcv_state_process
/** case TCP_LISTEN && th->syn */
|->conn_request(tcp_v4_conn_request)我們繼續(xù)分析conn_request函數(shù)，由于里面很多邏輯，所以我們?yōu)V掉了很多細(xì)節(jié):
int tcp_v4_conn_request(struct sock *sk, struct sk_buff *skb) {
// 如果csk的reqsk queue滿了，則設(shè)置want_cookie標(biāo)識(shí)
if (inet_csk_reqsk_queue_is_full(sk) && !isn) {
if (sysctl_tcp_syncookies) {
want_cookie = 1;
}
......
if(want_cookie){
// 下面這行就是打印possible SYN flooding的地方
syn_flood_warning(skb);
......
}
// 發(fā)送synack,即三次握手的第二次握手
// 注意want_cookie的時(shí)候并不把對應(yīng)的req加入到reqsk的hash列表中
if (__tcp_v4_send_synack(sk, req, dst) || want_cookie)
goto drop_and_free;
// 如果發(fā)送syack成功，則加到hash列表里面
inet_csk_reqsk_queue_hash_add(sk, req, TCP_TIMEOUT_INIT);
......
drop_and_free;
reqsk_free(req);
return 0;
}
}上面就是三次握手的前兩次握手，如下圖所示: 
現(xiàn)在讓我們看下最關(guān)鍵的第三次握手(客戶端發(fā)給server ack的過程),依舊從tcp_v4_do_rcv開始
tcp_v4_hnd_req
|->tcp_v4_hnd_req
// 這里面分兩種情況
static struct sock *tcp_v4_hnd_req(struct sock *sk, struct sk_buff *skb){
// 首先從inet_csk_search_req看是否有對應(yīng)的五元組
struct request_sock *req = inet_csk_search_req(sk, &prev, th->source,
iph->saddr, iph->daddr);
// 這邊的req分支下的tcp_check_req是重點(diǎn)，我們下面再分析
if (req)
return tcp_check_req(sk, skb, req, prev);
// 處理established情況
// 如果inet_csk沒找到，則可能是需要syn cookie，處理syn cookie
// 下面這條語句應(yīng)該是在syn
sk = cookie_v4_check(sk, skb, &(IPCB(skb)->opt));
// 如果處理成功，則把其加入到inet_csk_reqsk_queue_add隊(duì)列中
......
}上面這些代碼片段主要表明的就是如果三次握手成功，會(huì)在server端把新創(chuàng)建的server端sock放到inet_csk_reqsk里面，然后由后面的tcp_child_process去處理。 
tcp_check_req
上面分析完大致的tcp三次握手代碼邏輯之后，我們現(xiàn)在看看造成本文問題現(xiàn)象的核心分支tcp_check_req,這個(gè)是在對應(yīng)的req被放到inet_csk_reqsk(即不需要cookie或者cookie校驗(yàn)成功)后才能執(zhí)行到這一句,源碼如下:
// 下邊是client ack回來后的處理過程
// 筆者為了簡單起見，我們省略cookie校驗(yàn)的邏輯
struct sock *tcp_check_req(......){
/* 各種處理，各種校驗(yàn) */
child = inet_csk(sk)->icsk_af_ops->syn_recv_sock(sk, skb, req, NULL);
// 如果syn_recv_sock返回空，則跳到listen_overflow
if (child == NULL)
goto listen_overflow;
......
listen_overflow:
// 如果沒有設(shè)置tcp_abort_on_overflow則設(shè)置acked=1
if (!sysctl_tcp_abort_on_overflow) {
inet_rsk(req)->acked = 1;
return NULL;
}}
// 增加內(nèi)核統(tǒng)計(jì)參數(shù)
NET_INC_STATS_BH(sock_net(sk), LINUX_MIB_EMBRYONICRSTS);
// 如果設(shè)置了tcp_abort_on_overflow則發(fā)送reset報(bào)文
if (!(flg & TCP_FLAG_RST))
req->rsk_ops->send_reset(sk, skb);
// 同時(shí)將當(dāng)前sock從csk_reqsk中刪除，即當(dāng)client端下次報(bào)文過來的時(shí)候，無法找到
// 對應(yīng)的csk_reqsk
inet_csk_reqsk_queue_drop(sk, req, prev);
return NULL;如果進(jìn)了listen_overflow分支,server端會(huì)有兩種現(xiàn)象，一個(gè)是直接將acked設(shè)置為1(僅設(shè)置標(biāo)識(shí)不發(fā)送ack),另一個(gè)是發(fā)送ack。這兩個(gè)分支都會(huì)把對應(yīng)的req從reqsk_queue中刪除。下圖就是走了listen_overflow后不同分之,三次握手的情況:
不設(shè)置tcp_abort_on_overflow 
設(shè)置tcp_abort_on_overflow 
由上面看出設(shè)置了tcp_abort_on_overflow會(huì)在三次握手之后立馬置為closed狀態(tài)，二不設(shè)置tcp_abort_on_overflow會(huì)等第一個(gè)請求發(fā)出來的時(shí)候才會(huì)知道這個(gè)連接其實(shí)已經(jīng)被server端丟棄了。
什么時(shí)候listen_overflow
看上面的代碼，即在syn_recv_sock返回null的時(shí)候，會(huì)到listen_overflow，對應(yīng)的tcp協(xié)議的函數(shù)為:
struct sock *tcp_v4_syn_recv_sock(struct sock *sk, struct sk_buff *skb,
struct request_sock *req,
struct dst_entry *dst){
....
if (sk_acceptq_is_full(sk))
goto exit_overflow;
......
}sk_acceptq_is_full里面判斷full的隊(duì)列長度是下面這三個(gè)參數(shù)中的最小值:
取三者中的最小值 /proc/sys/inet/ipv4/tcp_max_syn_backlog /proc/sys/net/core/somaxconn tcp listen函數(shù)調(diào)用時(shí)候傳入的back_log
限于篇幅，就不給出這里判斷隊(duì)列是否為full的源碼了。
修復(fù)方案
設(shè)置kernel參數(shù)
一開始筆者僅僅在server端設(shè)置了下面這三個(gè)參數(shù)(天真的以為dubbo考慮到了backlog,設(shè)置了一個(gè)較大的數(shù)值，其實(shí)其用了jdk默認(rèn)的50)
注意，這邊511是根據(jù)redis的建議值設(shè)置的 /proc/sys/inet/ipv4/tcp_max_syn_backlog 511 /proc/sys/net/core/somaxconn 511 /proc/sys/net/ipv4/tcp_abort_on_overflow 1
發(fā)現(xiàn)依舊有Close old netty client這樣的錯(cuò)誤日志,但是業(yè)務(wù)方確告訴筆者已經(jīng)沒有上線流量損失的情況了。筆者上去觀察了一下情況，發(fā)現(xiàn)沒有流量損失是由于如上圖所述reset報(bào)文立馬發(fā)回來，導(dǎo)致能夠出錯(cuò)的時(shí)間窗口縮小為2s,而不是之前的第一筆必報(bào)錯(cuò)，2s內(nèi)由于沒有任何請求，所以大大減少了出錯(cuò)概率。如下圖所示: 
而創(chuàng)建連接和close old netty client日志的間隔都是小于等于兩秒也證明了tcp_abort_on_overflow生效了
dubbo代碼增加backlog的設(shè)置
由于dubbo用的是jdk默認(rèn)的backlog(50),所以筆者在dubbo源碼對應(yīng)的部分做了調(diào)整，如下代碼所示:
public class NettyServer extends AbstractServer implements Server {
......
protected void doOpen() throws Throwable {
...
// 可以從jvm參數(shù)中動(dòng)態(tài)調(diào)整這個(gè)backlog
String backlog = System.getProperty(BACK_LOG_KEY);
if(StringUtils.isEmpty(backlog)){
// 默認(rèn)為2048,這邊調(diào)大點(diǎn)，反正改內(nèi)核參數(shù)是即時(shí)生效的
backlog = DEFAULT_BACK_LOG;
}
bootstrap.setOption("backlog",backlog);
......
}
}將這個(gè)修改過的dubbo版本給業(yè)務(wù)方(server端)用了以后，再也沒有對應(yīng)的報(bào)錯(cuò)日志了，dubbo上線也平滑了。
事實(shí)上，從開始分析問題到猜測要調(diào)整backlog所花費(fèi)的時(shí)間并不長。但是筆者喜歡把所有的細(xì)節(jié)和自己的猜想一一印證，通過
看完上述內(nèi)容是否對您有幫助呢？如果還想對相關(guān)知識(shí)有進(jìn)一步的了解或閱讀更多相關(guān)文章，請關(guān)注創(chuàng)新互聯(lián)行業(yè)資訊頻道，感謝您對創(chuàng)新互聯(lián)的支持。
分享名稱：如何解決dubbo流量上線時(shí)的非平滑問題
當(dāng)前鏈接：http://muchs.cn/article34/pdgjpe.html
成都網(wǎng)站建設(shè)公司_創(chuàng)新互聯(lián)，為您提供移動(dòng)網(wǎng)站建設(shè)、靜態(tài)網(wǎng)站、網(wǎng)站建設(shè)、品牌網(wǎng)站建設(shè)、域名注冊、全網(wǎng)營銷推廣
聲明：本網(wǎng)站發(fā)布的內(nèi)容（圖片、視頻和文字）以用戶投稿、用戶轉(zhuǎn)載內(nèi)容為主，如果涉及侵權(quán)請盡快告知，我們將會(huì)在第一時(shí)間刪除。文章觀點(diǎn)不代表本網(wǎng)站立場，如需處理請聯(lián)系客服。電話：028-86922220；郵箱：631063699@qq.com。內(nèi)容未經(jīng)允許不得轉(zhuǎn)載，或轉(zhuǎn)載時(shí)需注明來源： 創(chuàng)新互聯(lián)
