太长不看:
-
部分高版本 MySQL Connector-J 存在 BUG,对于预编译用法即prepare+execute,在某些小概率场景下,与 TiDB 或者低版本 MySQL 交互可能引发SQL execute卡住的问题
-
原因在于 MySQL Connector-J 从 v6.0.4 开始,对于 EOF 协议包的处理存在问题,导致错误处理或遗漏 EOF 包。 在满足以下条件的情况下,会偶现连接卡死的问题,在应用层面并没有规避途径:
-
触发途径
- 使用 MySQL 版本低于 5.7.5,或者其他兼容 MySQL 协议但是并没有废弃 EOF 包的数据库(如 TiDB < v6.3.0)
- 使用了 MySQL 官方的 JDBC Connector-J,且版本在 v6.0.4 - v8.0.32 之间
- 在交互中使用了预编译用法,即 prepare+execute
- 受到返回包长度,网络 pMTU 的影响,返回的数据被分为多个 TCP 分段,最后一个分段完整或局部包含 EOF 包,且不包含其他协议包
- 受到网络延迟或者 TCP Nagle Algorithm 的影响,最后一个分段到达存在延迟。
-
当前状态
-
起始
问题来源于公司准生产环境一个业务系统遇到超时故障,表现形式为偶发的 DB 连接卡住,且超时机制无效,只能进行重启。虽然问题为偶发,但只存在于该业务系统中,其他相同环境的系统均运行正常。
同事在之前已经排除了 DB 侧,PROXY 侧,业务侧等各种各样的可能原因,包括且不限于: 慢查询/负载/防火墙/带宽,且查看对应日志均无错误。同时分析环境前后变化,确定了 JDBC 驱动有升级过,从 mysql-connector-java-5.1.41.jar 升级为 mysql-connector-java-8.0.27.jar。
之后和业务侧,主机侧,网络侧以及厂商共同进行排查,都没有找到问题。
当时还在转正期没有权限,于是最后到我手上的也就只有两张抓包截图了。(安全问题只显示部分内容)
-
具体分析
情况大概了解,之后就需要见招拆招了。
以下内容需要 TCP 协议和 MySQL 协议包格式有个基础了解,可以参考着 MySQL 的 internal manual 看看。-
为什么2次客户端请求,DB总共会回3个包?
可以看到 2 reassembled tcp segments,表示TCP进行了分段发送,即一个TCP数据包因为各种原因比如MSS,被分成了2个片段来进行发送,算是一个常见的现象。
可见 #120788(5),#120790(4)表示 第1个片段是在120788包里,第2个片段是在120790包里。
TIPS:IP分片一般是因为MTU,分片后,目标网卡会进行组装;TCP分段一般是因为MSS,分段后,需由应用层按实际情况进行解析或组装。
-
为什么正常情况和异常情况下的网络包交互顺序不一样?
而且异常情况下, 应该回复给prepare的第2个包的片段,从时间线上来看,是回复给了execute请求?
这个需要看TiDB发送、处理请求的源码 以及 JDBC Client 端如何发送、处理请求的源码。 -
第2个包是否很特殊?
TiDB兼容MySQL协议,所以此时需要查看MySQL协议来确认。 -
execute请求错序收到了第2个片段后,为什么会表现为卡住?
也需要通过源码来解释。 -
查看MySQL协议
-
查看收到prepare请求的处理协议,可以看到需要回复
[COM_STMT_PREPARE_OK](https://dev.mysql.com/doc/internals/en/com-stmt-prepare-response.html#packet-COM_STMT_PREPARE_OK)
-
查看**
[COM_STMT_PREPARE_OK](https://dev.mysql.com/doc/internals/en/com-stmt-prepare-response.html#packet-COM_STMT_PREPARE_OK)
** 的协议格式
可以看到由3部分组成:
- First packet: 状态、statement id、columns个数、params个数 等等信息
- 如果满足If num_params > 0,会有更多的packet,packet包括字段属性定义等等 外加
[EOF_Packet](https://dev.mysql.com/doc/internals/en/packet-EOF_Packet.html)
- 如果满足If num_params > 0,会有更多的packet,packet包括参数属性定义等等 外加
[EOF_Packet](https://dev.mysql.com/doc/internals/en/packet-EOF_Packet.html)
-
我们再回过头看prepare请求,DB回复的2个包的内容
第1个包:满足If num_params > 0 和 满足If num_params > 0,所以包会包含协议里的第二部分和第三部分
第二个包:
我们发现,第2个包正好就是一个 EOF 相关的包,看来和我们前面分析得一样,这第二个包确实很特殊。
那就再看看[EOF_Packet](https://dev.mysql.com/doc/internals/en/packet-EOF_Packet.html)
到底是什么样。查看
[EOF_Packet](https://dev.mysql.com/doc/internals/en/packet-EOF_Packet.html)
的协议格式:https://dev.mysql.com/doc/internals/en/packet-EOF_Packet.html
即EOF和OK packet的功能类似,都是表示query执行结果的结尾,特别注意文档中的 Note: 在5.7.5之后, EOF packet已经被废弃!
同时也能找到废弃 EOF的提案 https://dev.mysql.com/worklog/task/?id=7766至此,锁定在EOF packet 相关处理上可能存在问题,2种可能:
-
MySQL官方协议宣布5.7.5废弃EOF packet,为什么TiDB还是会回复EOF packet?是否正常?
TiDB官方宣称兼容 MySQL 5.7 协议,所以可能确实没有覆盖这个废弃提案。
-
8.0.27版本是否能够向前兼容呢?比如低于5.7的版本确实回复了EOF packet,是否能正常处理呢?
接下来,就必须去查看TiDB发送、处理请求的源码 以及 Java JDBC驱动如何发送、处理请求的源码了。可以大致分为两步:
-
查看TiDB回复prepare的包实现逻辑是否有BUG
-
重点对比 MySQL JDBC 5.1.41 和 MySQL JDBC 8.0.27 对EOF包的处理的差异点
-
-
看源码
一、 查看TiDB回复prepare的包实现是否有BUG(在测试环境查看验证,所以具体数值有变动)
查看 TiDB 关于实现该协议的代码,结合 MySQL 官方的协议文档,判断 TiDB 的具体实现不存在问题。
根据 Rrepare_Response_OK 的协议,当返回的参数个数和字段数大于零时,会分别为其构造存放了字段和参数详细信息的协议包,并使用 EOF 包标识结束。
在这种情况下,集中考虑TCP分段这一特殊情形。 查看抓到的包可知,因为可能网络的 MSS影响,Rrepare_Response_OK 的 MySQL 协议包被分为了两个 TCP 片段(segement),大小分别为 1428 字节和 4 字节。
此时根据上一步得到的协议包构成情况,可以判断得出在当前情况下,最后的 EOF 包被分割到了两个包中。这时候,需要对 EOF 协议包进行一个了解:
EOF 包的 payload 由三部分组成:-
header
:占用 1 字节,始终为 0xfe, 用于标识当前包类型为 EOF -
warnings
: 占用 2 字节, 用于标识当前 db 中的 warning 数量 -
status_flag
: 占用 2 字节, 用于标识当前 db server 端和连接中设置的部分状态
此时再加上 MySQL 协议通用的协议头 4 个字节, 一个 EOF 的总长度为 9 个字节。
可得,通讯中的最后一个 EOF 包被分成了两块,其中前一个包包含 5 字节, 后一个包包含 4 字节。
TCP抓包也同样可以确认确实是把EOF分在了2个包里( #120788(5),#120790(4)表示第1个片段是在120788包里,第2个分片是在120790包里 ):
-
所以response 1 和 response 2 真正是这样进行了分为2个包的整体效果是这样:
在异常情况下,应用客户端端并没有等待第二个包,而是径直发送了 Execute Statement。
此时猜测 JDBC在判断 EOF包的处理逻辑上可能出现了问题?它并没有完整的检查整个包,而是把header直接将其丢弃了。EOF 残余的四个字节和 Execute 的 Response 被混合在了一起,从而导致了Execute超时。所以接下里继续分析JDBC的处理逻辑
二、再来看JDBC的源码,重点对比 mysql-connector-java-5.1.41.jar 和 mysql-connector-java-8.0.27.jar对EOF包的处理的差异点
5.1.41 JDBC 处理Prepare Response的逻辑:
可以看到是在等待EOF的包,也就是Prepare后,会等到明确的EOF packet才会继续往下执行
8.0.27 JDBC 处理Prepare Response的逻辑:
可以看到并没有处理column definition packet 对应之后的EOF_packet (#BUG)
进而导致把EOF packet的第一个分段直接从buffer里清空或直接跳过了,接着应用继续往下执行execute,此时EOF packet的第二个分段(4个字节)正好达到了,所以execute直接把这个回复当成了execute期望的回复,进而导致卡住。
那为什么返回的四个字节会导致execute卡住呢?
这四个字节是 0x0200, 由 jdbc 源码可知,此时它接收的是 execute 的返回包,因而会把接收的结果当做一个正常的 MySQL 协议包看待。 前文已有提到,一个 MySQL 协议包由固定四个字节的协议头和不定长的有效载荷组成。 其中 length: 占 3 个字节:用于标志有效载荷的长度。 而 Sequence id:占 1 个字节,用于标志当前协议包的序号。
因此可知,0x0200 被解析成了协议头,因此 jdbc 会认为当前这个协议包长度是 516 个字节,序号为 0。 此时它会从缓冲区提取 516 个字节的数据。
如果缓冲区数据不足 516 字节,则程序会认为数据还没传输完,会持续地等待:
如果缓冲区数据超过 516 字节,则程序会认为提取并解析当前的包,当然解析的结果是乱码。但因为当前的包不是 OK Packet 也不是 ERR Packet,因而程序会再次重复当前步骤,再次陷入等待。
所以从代码分析可以初步得出两个结论:
1、5.1.41版本JDBC驱动 与 8.0.27版本 JDBC驱动对于Prepare Response中的EOF packet包的处理逻辑确实不同;且8.0.27在这个处理上有BUG,遗漏处理了column definition packet 对应之后的EOF_packet,在Prepare Response的包存在TCP分段回复的情况下可能触发客户端Execute卡住的问题
2、TiDB回复的Prepare Response包实现没有问题。虽然MySQL官方宣布在5.7.5之后, EOF packet已经被废弃,但当前TiDB版本暂未覆盖这个废弃提案,但并不是本次问题的根因。(MySQL官方版本5.7.5之前的版本也会回复 EOF packet,但这个bug下,也可能导致出问题)
依据 client 侧 connector 代码层的处理思路,梳理如下:
- 先考虑 Response_OK 协议包中参数 number of field(column):
- 如果 等于 0:意味没有 EOF 协议包,正常处理
- 如果 大于 0:意味有 EOF 协议包结尾:考虑当前 handle Prepare 函数中返回的所有协议包总大小:
- 如果 小于 MSS: 不会触发 TCP 分包:正常处理*
- 如果 大于 MSS: 意味着会被分为多个包:考虑最后一个包,也就是 EOF 协议包:
- 如果没有被分割到两个 TCP 包中:正常处理*
- 如果被分割到两个 TCP 包中:考虑当前网络情况下两个 TCP 包的到达时间
- 如果不存在延迟:正常处理*
- 如果存在延迟:触发
需要注意的是,带了*号的正常处理指的是流程上显示正常,但此时的 EOF 协议包依旧在缓冲区中,并没有被正确地处理。但因为 jdbc 在 Handle Execute 函数中,会在接受数据库返回的结果前重置序列号和清空缓冲区,因而并没有影响到整体流程。
优化方向或解决方案
至此问题已明确,当前可从几方面进行解决该问题:
1、 TiDB当前暂未废弃EOF packet,而驱动8.0.27版本正好有代码BUG,错误处理了 包括EOF packet的COM_STMT_PREPARE_OK 回包,导致SQL语句卡住:
应用可以回退版本到5.1.41版本JDBC进行临时规避
2、 提交issue给到JDBC官方,对此BUG进行修复
3、提交issue给到TiDB官方,建议废弃EOF packet
-