现象

Sysbench对MySQL进行压测, 并发数过大(>5k)时, Sysbench建立连接的步骤会超时.

猜想

猜想: 直觉上这很简单, Sysbench每建立一个连接, 都要消耗一个线程, 资源消耗过大导致超时.

验证: 修改Sysbench源码, 调大超时时间, 仍然会发生超时.

检查环境

猜想失败, 回到常规的环境检查:

MySQL error log 未见异常.
syslog 未见异常.
tcpdump 观察网络包未见异常, 连接能完成正常的三次握手; 只观察到在出问题的连接中, 有一部分的TCP握手的第一个SYN包发生了重传, 另一部分没有发生重传.
自己写一个简单的, 替换sysbench, 可重现场景. 排除sysbench的影响

猜想2

怀疑 MySQL 在应用层因为某种原因, 没有发送握手包, 比如卡在某一个流程上:

检查MySQL堆栈未见异常, 仿佛MySQL在应用层没有看到新连接进入.
通过strace检查MySQL, 发现accept()调用确实没有感知到新连接.

怀疑是OS的原因, Google之, 得到参考文档:

分析

参考文档中的现象跟目前的状况很类似, 简述如下:

正常的TCP连接流程:

Client 向 Server 发起连接请求, 发送SYN.
Server 预留连接资源, 向 Client 回复SYN-ACK.
Client 向 Server 回复ACK.
Server 收到 ACK, 连接建立.
在业务层上, Client和Server间进行通讯.

当发生类似SYN-flood的现象时, TCP连接的流程会使用SYN-cookie, 变为:

Client 向 Server 发起连接请求, 发送SYN.
Server 不预留连接资源, 向 Client 回复SYN-ACK, 包中附带有签名A.
Client 向 Server 回复ACK, 附带 f(签名A) (对签名进行运算的结果).
Server 验证签名, 分配连接资源, 连接建立.
在业务层上, Client和Server间进行通讯.

当启用SYN-cookie时, 第3步的ACK包因为 某种原因 丢失, 那么:

从Client的视角, 连接已经建立.
从Server的视角, 连接并不存在, 既没有建立, 也没有”即将建立” (若不启用SYN-cookie, Server会知道某个连接”即将建立”)

发生这种情况时:

若业务层的第一个包应是从 Client 发往 Server, 则会进行重发或抛出连接错误
若业务层的第一个包应是从 Server 发往 Client的, Server不会发出第一个包. MySQL的故障就属于这种情况.

TCP握手的第三步ACK包为什么丢失

参考文档中, 对于TCP握手的第三步ACK包的丢失原因, 描述为:

Some of these packets get lost because some buffer somewhere overflows.

我们可以通过Systemtap进一步探究原因. 通过:

probe kernel.function("cookie_v4_check").return {
        source_port = @cast($skb->head + $skb->transport_header, "struct tcphdr")->source
        printf("source=%d, return=%d\n", readable_port(source_port), $return)
}

function readable_port(port) {
        return (port & ((1<<9)-1)) << 8 | (port >> 8)
}

观察结果, 可以确认cookie_v4_check (syn cookie机制进行包签名检查的函数)会返回 NULL(0). 即验证是由于syn cookie验证不通过, 导致TCP握手的第三步ACK包不被接受.

之后就是对其中不同条件进行观察, 看看是哪个条件不通过. 最终原因是accept队列满 (sk_acceptq_is_full):

796 static inline bool sk_acceptq_is_full(const struct sock *sk)
797 {
798         return sk->sk_ack_backlog > sk->sk_max_ack_backlog;
799 }

恢复故障与日志的正关联

在故障处理的一开始, 我们就检查了syslog, 结论是未见异常.

当整个故障分析完成, 得知了故障与syn cookie有关, 回头看syslog, 里面是有相关的信息, 只是和故障发生的时间不匹配, 没有正关联, 因此被忽略.

检查:

6130         if (!queue->synflood_warned &&
6131             sysctl_tcp_syncookies != 2 &&
6132             xchg(&queue->synflood_warned, 1) == 0)
6133                 pr_info("%s: Possible SYN flooding on port %d. %s.  Check SNMP counters.\n",
6134                         proto, ntohs(tcp_hdr(skb)->dest), msg);

可以看到日志受到了抑制, 因此日志与故障的正关联被破坏.

粗看源码, 每个listen socket只会发送一次告警日志, 要获得日志与故障的正关联, 必须每次测试重启MySQL.