query cache遇到的bug
近日工作中发现负责的业务有个slave出现大量延迟，latency > 2000。
第一次排查的时候发现有备份程序再执行，故草率判定为备份产生的IO压力导致，没有处理。
但是经过2个小时候发现延迟还在增大，登陆服务器查看备份程序员已经完成，但是延迟并没有解决，查看基础信息如下：
----total-cpu-usage---- -dsk/total- -net/total- ---paging-- ---system-- usr sys idl wai hiq siq| read writ| recv send| in out | int csw 1 1 92 6 0 0| 12M 8823k| 0 0 | 0 0.1 | 222 7124 1 0 66 32 0 0|5640k 14M|1640k 88k| 0 0 |2297 2194 1 2 67 30 0 0|5824k 15M|1657k 72k| 0 0 |2362 2277 1 0 68 30 0 0|5600k 13M|1240k 59k| 0 0 |2194 1984 1 0 67 31 0 0|5544k 14M| 920k 49k| 0 0 |2260 2195 1 0 68 30 0 0|5736k 15M|1401k 65k| 0 0 |2288 2198 1 0 67 31 0 0|5736k 15M|1435k 68k| 0 0 |2321 2251 2 1 69 28 0 0|8152k 43M|1619k 69k| 0 0 |3554 3872
Cpu0 : 0.4%us, 0.0%sy, 0.0%ni, 75.8%id, 23.8%wa, 0.0%hi, 0.0%si, 0.0%st Cpu1 : 0.4%us, 0.0%sy, 0.0%ni, 65.8%id, 33.8%wa, 0.0%hi, 0.0%si, 0.0%st Cpu2 : 0.4%us, 0.0%sy, 0.0%ni, 91.1%id, 8.5%wa, 0.0%hi, 0.0%si, 0.0%st Cpu3 : 5.8%us, 0.9%sy, 0.0%ni, 92.9%id, 0.4%wa, 0.0%hi, 0.0%si, 0.0%st Cpu4 : 0.4%us, 0.0%sy, 0.0%ni, 99.6%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st Cpu5 : 8.0%us, 2.2%sy, 0.0%ni, 0.9%id, 87.6%wa, 0.4%hi, 0.9%si, 0.0%st Cpu6 : 0.0%us, 0.4%sy, 0.0%ni, 99.6%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st Cpu7 : 1.3%us, 1.3%sy, 0.0%ni, 3.1%id, 92.4%wa, 0.0%hi, 1.8%si, 0.0%st
发现IOwait超高，不停的有数据在写磁盘，考虑仅仅追同步不会造成如此频繁的磁盘写入，故开始怀疑存在其他问题。
通过show processlist发现，存在特殊的状态。
+----------+-------------+-----------+------+---------+-------+------------------------------------------+------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----------+-------------+-----------+------+---------+-------+------------------------------------------+------------------+
| 27189128 | system user | | NULL | Connect | 1724 | invalidating query cache entries (table) | NULL |
| 30965812 | system user | | NULL | Connect | 15549 | Waiting for master to send event | NULL |
| 30966763 | myadmin | localhost | NULL | Query | 0 | NULL | show processlist |
+----------+-------------+-----------+------+---------+-------+------------------------------------------+------------------+
再查看query cache的设置如下：
+------------------------------+-----------+
| Variable_name | Value |
+------------------------------+-----------+
| query_alloc_block_size | 8192 |
| query_cache_limit | 8388608 |
| query_cache_min_res_unit | 4096 |
| query_cache_size | 268435456 |
| query_cache_type | OFF |
| query_cache_wlock_invalidate | OFF |
| query_prealloc_size | 8192 |
+------------------------------+-----------+
发现query cache已经关闭，理论上并应该会发生和query cache相关的操作。不应该在清理qcache了。
首先想法是kill掉这个进程，kill完毕发现，slave的sql_thread也被杀死，故怀疑由于是row格式，每个binlog执行的时候都会触发清理query cache的操作，导致状态永远都是invalidating query cache entries (table)。
然后，尝试在线修改query_cache_type的状态，从OFF改为ON，但是仍然不解决问题。
最后，重启mysqld，并将query_cache_type = 0写入到配置文件中后，问题消失。
通过查找google发现，这是遇到一个bug，具体可以看这个：
http://bugs.mysql.com/bug.php?id=60696
http://bugs.mysql.com/bug.php?id=65336
总结如下：
触发bug的条件：
1、binlog格式为ROW
2、query cache的配置为query_cache_type=0或者query_cache_size=0
3、在高负载下，在线关闭query_cache最容易触发。
解决方法：
1、重启mysqld
2、添加query_cache_type=0到配置文件中
