解Bug之路-dubbo流量上线时的非平滑问题
前言redis
笔者最近解决了一个困扰了业务系统好久的问题。这个问题只在发布时出现，每次只影响一两次调用，相较于其它的问题来讲，这个问题有点不够受重视。因为种种缘由，使得这个问题到了业务必须解决的程度，因而就到了笔者的手上。bootstrap
问题现场
咱们采用的是dubbo服务，这是个稳定成熟的RPC框架。可是咱们在某些应用中会发现，只要这个应用一发布(或者重启),就会出现请求超时的问题，以下图所示:
并且都是第一笔请求会报错，以后就再也没有问题了。cookie
排查日志
好了，现象咱们知道了，因而开始排查那个时间点的日志。Server端没有任何日志，而Client(App1)端报错超时。报错以下所示:并发
2019-08-22 20:33:50.798com.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
看日志报错是这个tcp五元组(1.1.1.1:44502->2.2.2.2:20880)有问题。因而笔者netstat了一下，查看当前此链接的状态:框架
netstat -anp | grep 445021.1.1.1:44502 2.2.2.2:20880 ESTABLISHED
这个链接处于正常的ESTABLISHED状态，并且调用2.2.2.2这个server的链接只有这一个,那后续这台机器调用2.2.2.2这个server确定只用到了这个链接，查看日志发现除了这一笔，其它调用一切正常。异步
思路1:Server端处理超时
按照上面的报错，确定这个链接有问题，按照正常思路，是不是第一笔调用的时候各类初始化过程(以及jit)致使server处理请求过慢?以下图所示:
但这个问题很快被第二笔请求(和第一笔请求间隔只有一秒)给否决了。也就是说第一笔请求花了60s还超时，而第二笔请求在第一笔请求发出后的一秒后发出就成功了(并且耗时是毫秒级的)。若是按照上述思路，第二笔请求也应该等各类初始化完成以后再处理，也应该卡至关长的一段时间才对。再加上server端没有任何日志，就感受好像没有收到请求。jvm
思路2:Client端没有发送成功
因而咱们开始了思路2，Client端没有发送成功。因为Dubbo是基于Netty的，其请求传输的处理过程是个NIO的异步化过程(只不过经过使用future机制对业务来讲是同步的)。首先咱们看下dubbo的超时检测机制,以下图所示:
固然，还有future的超时机制,这边我就不列举出来了。从这个机制能够看出，就算Client端发送的时候(由于写是写到socket的writebuffer里面，通常不会满，因此不会报错)没有发送出去,也不会在发的那一刻报出错误，而是要等定时扫描。为了验证这个猜测，笔者就开始着手排查链接的日志。socket
链接日志
由于规律是第一笔失败，那么笔者开始怀疑链接建立的有问题,但后面的请求成功又代表链接建立是没有问题的。那么，是不是链接尚未建立好就发送了第一笔请求呢？带着这样的疑问，笔者找到了以下的日志:tcp
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这个链接串是在2019-08-22 20:32:51.876链接成功的，而上面出错的日志起始时间为ide
请求发送时间:2019-08-22 20:32:50.474链接开始创建时间:2019-08-22 20:32:51.876链接成功创建时间:2019-08-22 20:32:51.876
请求在链接成功创建以前，感受很是符合笔者上述的猜测。但细想又不对，上述日志表示的是在2019-08-22 20:32:51.876开始创建链接并在1ms内创建成功链接。而请求确是50s发出的，dubbo自己代码不可能在链接还没作出建立动做的时候就开始发送请求(由于44502是由kernel分配的，没到建立链接动做以前是不可能知道这个端口号的,但它却在日志里面打印出来了),以下图所示：
思考了一段时间，笔者以为这种状况颇有多是日志是不许确的，它仅仅打印当前链接包装类中的信息，以前那个出错的链接已经被新建的链接掩盖了(在日志中)。咱们看下dubbo中对应的打印日志代码:
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();
}
这个1.1.1.1:44502是由channel.getLocalAddress()得出的,咱们看下调用链:
channel.getLocalAddress() |->nettyClient.channel.getLocalAddress()
笔者看了下代码，dubbo在reconnect(从新链接的时候)会把nettyClient.channel换掉，从而可能打印出来和发送请求时不一样的client端口信息。再加上日志里面打印出来的线程号DubboClientReconnectTimer-thread-1就几乎能够肯定，以前还有一个链接，只不过这个链接失败了，新建的链接为1.1.1.1f
:44502。再仔细的找了下日志，发现了下面这条日志:
------------------日志分割线----------------2019-08-22 20:32:51,876（DubboClientReconnectTimer-thread-1) Close old Netty channel /1.1.1.1:44471 :> 2.2.2.2:20880on 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关闭后，立马建立了2.2.2.2:44502
那么总体过程以下图所示:
咱们看下1.1.1.1:44471是何时建立的,继续搜寻日志:
zgrep '1.1.1.1:44471' dubbo.log.1.zip2019-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
发现其在
链接1建立时间:2019-08-22 20:31:59.871请求发送时间:2019-08-22 20:32:50.474链接1关闭时间:2019-08-22 20:32:51,876
并且笔者翻看了业务日志，发现链接1在其生命周期内有且只有一笔请求，这笔请求就是报错的请求，由此能够看出这个链接1从创建成功开始就没法使用。
为何链接创建成功确没法使用
首先因为dubbo是基于netty的，这种成熟的普遍应用的框架在建立链接这种问题上不该该会有问题。
而笔者仔细翻看netty翻看netty源码也确实遵照了NIO的编写套路。那么问题可能出如今环境上,既然应用(client/server)自己日志找不到更多的有用信息，那么看看操做系统可否有什么能够追寻的蛛丝马迹。因而笔者首先用dmesg查看下kernel打印的日志，client端没发现什么有用的信息，但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泛洪***，发送cookies。
这种日志会在并发链接过多的状况下由kernel打印出来。笔者netstat了下频繁出问题的机器，发现其特色都是链接特别多(达到了好几千甚至上万)。而dubbo的上线机制是只要注册到zookeeper后，zookeeper给全部的机器推送，全部的机器立马链接，这样就会形成比较高的并发链接，以下图所示:
既然怀疑到了高并发connect，那么笔者就立马用netstat看下kernel对于tcp的统计信息:
netstat -s... TcpExt: ... 1607 times the listen queue of a socket overflowed ...
果真有这种并发链接致使的统计信息,socket overflowed表示的是server端的tcp_backlog队列溢出了。到这里笔者有八成把握是这个tcp_backlog设置的太小的问题了。下面就是分析，tcp_backlog溢出为何会致使上述链接虽然成功可是第一笔报错的现象，从而和日志相印证，来证实笔者的猜想。
tcp_backlog溢出分析
tcp的三次握手
先从tcp的三次握手进行着手分析，从tcp_v4_do_rcv函数进行入手，由于这个函数是tcp协议获取packet的地方,当三次握手的SYN第一次进来的时候，应该会走这个函数:
// 先考察一下三次握手的第一个SYNint tcp_v4_do_rcv(struct sock *sk, struct sk_buff *skb){ if (sk->sk_state == TCP_LISTEN) {
...... // 因为如今链接处于第一个SYN,如今server端的socket处于LISTEN状态
struct sock *nsk = tcp_v4_hnd_req(sk, skb);
......
}
}// 咱们继续看下tcp_v4_hnd_req代码,三次握手第一个SYN kernel走的分支tcp_v4_do_rcv /* 因为tcp_v4_hnd_req没有发现和此五元组对应的链接,因此do nothing */
|->tcp_v4_hnd_req
|->tcp_rcv_state_process /** case TCP_LISTEN && th->syn */
|->conn_request(tcp_v4_conn_request)
咱们继续分析conn_request函数，因为里面不少逻辑，因此咱们滤掉了不少细节:
int tcp_v4_conn_request(struct sock *sk, struct sk_buff *skb) { // 若是csk的reqsk queue满了，则设置want_cookie标识
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);
......
} // 发送synack,即三次握手的第二次握手
// 注意want_cookie的时候并不把对应的req加入到reqsk的hash列表中
if (__tcp_v4_send_synack(sk, req, dst) || want_cookie) goto drop_and_free; // 若是发送syack成功，则加到hash列表里面
inet_csk_reqsk_queue_hash_add(sk, req, TCP_TIMEOUT_INIT);
......
drop_and_free;
reqsk_free(req); return 0;
}
}
上面就是三次握手的前两次握手，以下图所示:
如今让咱们看下最关键的第三次握手(客户端发给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看是否有对应的五元组
struct request_sock *req = inet_csk_search_req(sk, &prev, th->source,
iph->saddr, iph->daddr); // 这边的req分支下的tcp_check_req是重点，咱们下面再分析
if (req) return tcp_check_req(sk, skb, req, prev); // 处理established状况
// 若是inet_csk没找到，则多是须要syn cookie，处理syn cookie
// 下面这条语句应该是在syn
sk = cookie_v4_check(sk, skb, &(IPCB(skb)->opt)); // 若是处理成功，则把其加入到inet_csk_reqsk_queue_add队列中
......
}
上面这些代码片断主要代表的就是若是三次握手成功，会在server端把新建立的server端sock放到inet_csk_reqsk里面，而后由后面的tcp_child_process去处理。
tcp_check_req
上面分析完大体的tcp三次握手代码逻辑以后，咱们如今看看形成本文问题现象的核心分支tcp_check_req,这个是在对应的req被放到inet_csk_reqsk(即不须要cookie或者cookie校验成功)后才能执行到这一句,源码以下:
// 下边是client ack回来后的处理过程// 笔者为了简单起见，咱们省略cookie校验的逻辑struct sock *tcp_check_req(......){ /* 各类处理，各类校验 */
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: // 若是没有设置tcp_abort_on_overflow则设置acked=1
if (!sysctl_tcp_abort_on_overflow) {
inet_rsk(req)->acked = 1; return NULL;
}} // 增长内核统计参数
NET_INC_STATS_BH(sock_net(sk), LINUX_MIB_EMBRYONICRSTS); // 若是设置了tcp_abort_on_overflow则发送reset报文
if (!(flg & TCP_FLAG_RST))
req->rsk_ops->send_reset(sk, skb); // 同时将当前sock从csk_reqsk中删除，即当client端下次报文过来的时候，没法找到
// 对应的csk_reqsk
inet_csk_reqsk_queue_drop(sk, req, prev); return NULL;
若是进了listen_overflow分支,server端会有两种现象，一个是直接将acked设置为1(仅设置标识不发送ack),另外一个是发送ack。这两个分支都会把对应的req从reqsk_queue中删除。下图就是走了listen_overflow后不一样分之,三次握手的状况:
不设置tcp_abort_on_overflow
设置tcp_abort_on_overflow
由上面看出设置了tcp_abort_on_overflow会在三次握手以后立马置为closed状态，二不设置tcp_abort_on_overflow会等第一个请求发出来的时候才会知道这个链接其实已经被server端丢弃了。
何时listen_overflow
看上面的代码，即在syn_recv_sock返回null的时候，会到listen_overflow，对应的tcp协议的函数为:
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的队列长度是下面这三个参数中的最小值:
取三者中的最小值 /proc/sys/inet/ipv4/tcp_max_syn_backlog /proc/sys/net/core/somaxconntcp listen函数调用时候传入的back_log
限于篇幅，就不给出这里判断队列是否为full的源码了。
修复方案
设置kernel参数
一开始笔者仅仅在server端设置了下面这三个参数(天真的觉得dubbo考虑到了backlog,设置了一个较大的数值，其实其用了jdk默认的50)
注意，这边511是根据redis的建议值设置的/proc/sys/inet/ipv4/tcp_max_syn_backlog 511/proc/sys/net/core/somaxconn 511/proc/sys/net/ipv4/tcp_abort_on_overflow 1
发现依旧有Close old netty client这样的错误日志,可是业务方确告诉笔者已经没有上线流量损失的状况了。笔者上去观察了一下状况，发现没有流量损失是因为如上图所述reset报文立马发回来，致使可以出错的时间窗口缩小为2s,而不是以前的第一笔必报错，2s内因为没有任何请求，因此大大减小了出错几率。以下图所示:
而建立链接和close old netty client日志的间隔都是小于等于两秒也证实了tcp_abort_on_overflow生效了
dubbo代码增长backlog的设置
因为dubbo用的是jdk默认的backlog(50),因此笔者在dubbo源码对应的部分作了调整，以下代码所示:
public class NettyServer extends AbstractServer implements Server {
...... protected void doOpen() throws Throwable {
... // 能够从jvm参数中动态调整这个backlog
String backlog = System.getProperty(BACK_LOG_KEY); if(StringUtils.isEmpty(backlog)){ // 默认为2048,这边调大点，反正改内核参数是即时生效的
backlog = DEFAULT_BACK_LOG;
}
bootstrap.setOption("backlog",backlog);
......
}
}
将这个修改过的dubbo版本给业务方(server端)用了之后，再也没有对应的报错日志了，dubbo上线也平滑了。
总结
事实上，从开始分析问题到猜想要调整backlog所花费的时间并不长。可是笔者喜欢把全部的细节和本身的猜测一一印证，经过源码分析出来的过程图景可以将全部的问题现象所有解释，是一件很爽快的事情。