MySql 缓存使用的Bug 分析（EOF包被OK包替换引起的）

隐藏很森的bug分析

某一天，我们的线上应用突然查不出来数据，明明数据库里有记录，查出来就是null。
死活找不到原因，后来把流量切换到早已上线的另一个版本应用上去，大部分数据能查出来了，但是一部分id查询会100%产生超时。
困扰N久

当天对索引重建 好了一部分。
但是后来又坏一部分。
反反复复。。。。

直达过几天，我们怀疑到MySql缓存，把缓存关闭后，问题才得到解决。

围绕着这个现象，我对MySql缓存 和 协议进行了一些分析，总算是找到了原因。

在解释之前，先讲一些基础知识

MySql缓存

引用：

https://www.cnblogs.com/lpfuture/p/5751853.html
mysql query cache内容为 select 的结果集, cache 使用完整的 sql 字符串做 key, 并区分大小写，空格等。即两个sql必须完全一致才会导致cache命中。

一旦表数据进行任何一行的修改，基于该表相关cache立即全部失效。

MySql协议

网上有很多文章
引用：

http://blog.csdn.net/wind520/article/details/43964821

重点关注 “4.3.3 Result Set 消息” 部分

结构	说明
[Result Set Header]	列数量
[Field]	列信息（多个）
[EOF]	列结束
[Row Data]	行数据（多个）
[EOF]	数据结束

这个是EOF被OK包替换之前的结构。

在MySql 5.7.5之后，支持了OK包替换EOF包：

https://dev.mysql.com/doc/dev/mysql-server/latest/page_protocol_basic_eof_packet.html

https://dev.mysql.com/worklog/task/?id=7766

网上没有找到新结构的文章，通过网络录包拿到数据分析新结构为：

结构	说明
[Result Set Header]	列数量
[Field]	列信息（多个）
[Row Data]	行数据（多个）
[OK(EOF)]	数据结束

变动是：
1. 将列信息和行数据之间的EOF取消
2. 数据结束的EOF替换为OK包

https://dev.mysql.com/doc/relnotes/connector-j/5.1/en/news-5-1-39.html
java客户端从5.1.39版本之后，支持了OK包替换EOF包。

基于以上事实，我做了如下实验

实验条件：
MySql版本 5.7.13-log
两个应用A、B：A使用5.1.35版本客户端jar，B使用5.1.39版本客户端jar。
两条SQL，一条返回无记录，一条返回3条记录
用 WireShark 录包

场景一

MySql 缓存关闭。
使用 无记录的SQL

应用A(5.1.35)执行查询，server返回录包：

返回的是连续2个EOF，应用正常。

应用B(5.1.39)执行查询，server返回录包：

可见格式为新格式，OK包替换了原EOF包，仅有一个OK(EOF)。应用正常。

更换SQL
使用 返回3条记录的SQL

应用A(5.1.35)执行查询，server返回录包：

可见为老格式，两个EOF，应用正常。

应用B(5.1.39)执行查询，server返回录包：

可见格式为新格式。应用正常。

场景二

MySql 缓存开启。
保证缓存为失效状态。

使用 返回3条记录的SQL

应用A(5.1.35)查询：
结果与场景一中相同，应用正常。
注意：此时该SQL的返回已经被MySql缓存了！

然后用B(5.1.39)查询：
网络包显示，返回的为老格式，说明是返回的刚刚应用A查询缓存的结果。此时，本来应该有记录的，B应用却查询出无记录，应用异常！

清空缓存（在表中执行一个更新操作 即可清空缓存）
再用B(5.1.39)查询一次：
返回为新格式，应用正常。

使用 返回无记录的SQL

应用A(5.1.35)查询一次：
结果与场景一中相同，应用正常。
然后用B(5.1.39)查询：
网络包显示，返回的为老格式，说明是返回的刚刚A缓存的结果。然而B应用也认为是无记录，应用正常。
说明这种情况下可以兼容

场景三

MySql 缓存开启。
保证缓存为失效状态。

使用 返回无记录的SQL

先用B(5.1.39)客户端 查一次，
此时返回与场景一中相同，为新格式，应用正常。
注意：此时该SQL的返回已经被MySql缓存了！
用A(5.1.35)应用查一次，
返回结果仍然是新格式，说明是返回了刚刚B的缓存。
A应用出现超时，栈信息：

com.mysql.jdbc.exceptions.jdbc4.CommunicationsException: Communications link failure

The last packet successfully received from the server was 30,026 milliseconds ago.  The last packet sent successfully to the server was 30,027 milliseconds ago.

中间省略......

Caused by: java.io.EOFException: Can not read response from server. Expected to read 4 bytes, read 0 bytes before connection was unexpectedly lost.
        at com.mysql.jdbc.MysqlIO.readFully(MysqlIO.java:2914) ~[mysql-connector-java-5.1.35.jar:5.1.35]
        at com.mysql.jdbc.MysqlIO.nextRowFast(MysqlIO.java:1996) ~[mysql-connector-java-5.1.35.jar:5.1.35]
        ... 152 common frames omitted

这个说明老版本(<=5.1.38)的客户端jar无法解析这种新格式。
可以理解，老格式有2个EOF，新格式仅一个OK(EOF)，老版本收到新格式的话，还要等一个EOF，而这个EOF永远等不到，只能超时！

清空缓存
再用A(5.1.35)应用查一次：
发现返回的结构改回老格式，两个EOF。应用不再超时。

使用 返回有3条记录的SQL
应用B(5.1.39)查询一次：
结果与场景一中相同，应用正常。
然后用A(5.1.35)查询：
网络包显示，返回的为新格式，说明是返回的刚刚B缓存的结果。应用能正常查出数据，说明这个可以兼容。

结论

如果MySql缓存开启会出现如下情况。
当SQL返回有记录时：

结论	缓存了老格式	缓存了新格式
客户端为老格式jar	-	正常
客户端为新格式jar	应查出却查不出来	-

当SQL返回无记录时：

结论	缓存了老格式	缓存了新格式
客户端为老格式jar	-	超时
客户端为新格式jar	正常	-

故障分析

有了这个结论，现在再回头分析故障。
先找到新线索：

1. 我们的应用有两个版本，分别用了5.1.39 和 5.1.35的 mysql-connector-java
2. 一直在用的是5.1.39 的版本
3. 前几天把5.1.35版本上线了，但无外部流量
4. 5.1.35版本有计划任务，会定时查询某些SQL
5. 线上MySql缓存是开着的
6. 应用的对DB表查询多，更新少

我们知道，当缓存的格式跟客户端版本一致的时候，是不会有任何问题的。

现在，我们来重现故障：
当某一个表更新操作到来，该表的查询缓存被清空，此时，正在用的5.1.39的查询请求还没过来，而5.1.35版本的计划任务刚好执行，这个查询被执行后，缓存就是老版本的格式了！而正在提供服务的是5.1.39，按照刚刚得出的结论，会出现有记录却查不出来的情况！

后来切流量到5.1.35版本上面，就能查出数据了，也好理解了

后来的部分超时，经查，是另一张表的查询缓存是 5.1.39格式的。。

好了，分析结束
那么：

最终解决方案：

关闭缓存。