现象
Sysbench对MySQL进行压测, 并发数过大(>5k)时, Sysbench建立连接的步骤会超时.
猜想
猜想: 直觉上这很简单, Sysbench每建立一个连接, 都要消耗一个线程, 资源消耗过大导致超时.
验证: 修改Sysbench源码, 调大超时时间, 仍然会发生超时.
检查环境
猜想失败, 回到常规的环境检查:
- MySQL error log 未见异常.
- syslog 未见异常.
- tcpdump 观察网络包未见异常, 连接能完成正常的三次握手; 只观察到在出问题的连接中, 有一部分的TCP握手的第一个SYN包发生了重传, 另一部分没有发生重传.
- 自己写一个简单的并发发生器, 替换sysbench, 可重现场景. 排除sysbench的影响
猜想2
怀疑 MySQL 在应用层因为某种原因, 没有发送握手包, 比如卡在某一个流程上:
- 检查MySQL堆栈未见异常, 仿佛MySQL在应用层没有看到新连接进入.
- 通过strace检查MySQL, 发现
accept()调用确实没有感知到新连接.
怀疑是OS的原因, Google之, 得到参考文档: A TCP “stuck” connection mystery
分析
参考文档中的现象跟目前的状况很类似, 简述如下:
正常的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, 里面是有相关的信息, 只是和故障发生的时间不匹配, 没有正关联, 因此被忽略.
检查Linux源码:
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.
解决方案
这种故障一旦形成, 难以检测; 系统日志中只会出现一次, 在下次重启MySQL之前就不会再出现了; Client如果没有合适的超时机制, 万劫不复.
解决方案:
1. 修改MySQL的协议, 让Client先发握手包. 显然不现实.
2. 关闭syn_cookie. 有安全的人又要跳出来了.
3. 或者调高syn_cookie的触发条件 (syn backlog长度). 降低系统对syn flood的敏感度, 使之可以容忍业务的syn波动.
有多个系统参数混合影响syn backlog长度, 参看http://blog.dubbelboer.com/2012/04/09/syn-cookies.html
