vlambda博客
学习文章列表

突遇mysql 5.7中导致SQL执行结果出错的严重bug

两天前接到研发同学反馈,说是怀疑数据库执行SQL出错了,一个查询sql ,本来应该需要输出1000条结果的,但偶尔只出来一条结果。因为研发同学开始不太相信数据库会出现这样的错误,所以自己在程序端自行研究一段时间,始终没有找出问题的原因,最后向DBA求证是否真的只返回一条结果,然后DBA在数据库端确认这个现象。

  案例中出错的sql很简单,就是根据一天的时间范围,将一天内的数据按1000条分批取出,但偶尔这条SQL的执行结果只返回1条记录,但实际上,应该是1000条记录。

 

这种并非100%复现的bug,而且是导致执行结果错误的bug,DBA倍感恐惧跟压力。BUG已经出现,我们得尽快弄清楚bug的所有触发条件,以便评估这个bug是否会在我们的生产环境中可能被触发。如果存在触发的风险,则可能需要立即修改应用程序规避这个bug 或者升级数据库。

 

经过两天的学习跟研究,基本弄清楚这个Bug产生的原因,以及反推出触发条件,然后对bug进行稳定地多种场景复现。

 

  经过跟踪,最终定位导致bug产生的代码段如下图,这是mvcc数据查找的核心函row_search_mvcc中的一段代码(之前也曾想对这个函数进行仔细的研究,但这段代码逻辑有点复杂,里面的goto 语句到处跳转,看不下去,也弄不明白,这次在bug的压迫下弄明白了)。row_search_mvcc这个函数的整体逻辑还是有点复杂,在这里不打算去介绍,我们的目的是弄清楚bug的触发条件,下面这段代码提供了非常关键的信息。


我们来解析上面这段代码:

page_rec_is_supremum(rec) 用来判断这个行是否是本数据块(页)的最后一行,如果是,进入下面的判断(以前以为数据查找一定是精确到行的,看来不是,至少范围查找会把本页内所有行都查了)。

接下来,end_loop>100, 这个条件也非常重要。也就是说,循环次数少于100,这个bug 也不会触发。

prebuilt->m_mysql_handler->end_range!= NULL 表示范围的右区间不能为空。如果作者不偷懒,在后面会举例说明这个值(右区间)在什么情况下为空,什么情况下不为空。不为空也是触发bug的必要条件,但限定左右两端的范围的查询,大部分情况下都不为空。所以从代码上看,只有大于条件的查询,可能就不会触发这个bug. (作者尚未做实验证实这个结论)

再往里看,因为当前行是superemum,不包含业务数据, 则需要取前一行,来判断查询是否已经越界,越界的话,就可以终止查询了。

offsets = rec_get_offsets(prev_rec, prebuilt->index,

                    offsets,ULINT_UNDEFINED, &heap);

所以,上面这一行是获取前一行数据的页面内位置点offsetprev_rec为前一行, 然后通过

row_sel_store_mysql_rec 函数将这行数据格式化成row in the MySQL format,保存在变量end_range_cache 中,然后再通过函数row_search_end_range_check 来判断该行是否已经越界,如果越界,则可以终止查询。终止查询的代码为err = DB_RECORD_NOT_FOUND; goto normal_return;

但在跳转到normal_return:之前,会判断fetch_cache 里面是否有记录(补充一下,fetch cache的作用是为了加速获取行而采用的机制),如果有,则prebuilt->n_fetch_cached> 0, 则设置为prebuilt->m_end_range = true;

  prebuilt->m_end_range设置为true 时,同一个会话(更恐怖的是,不同会话也有可能出现,但出现的概率低,这种情况本篇文章不再扩展下去),再对这个表进行范围查询时,如果有超过一条的结果,也只能获取一条结果,bug就是这样产生的。


  

原因如下:当再一次对这个表执行SQL时,在执行到函数row_search_mvcc时,该函数的最前面的部分,有如下代码:

突遇mysql 5.7中导致SQL执行结果出错的严重bug

在执行到第二次循环的时候,会命中prebuilt->m_end_range == true 这个条件,然后

设置返回码为DB_RECORD_NOT_FOUND,同时跳转到func_exit代码块,终止了本次sql执行时的数据查找,所以不管这个SQL正确的结果集会有多少条记录,只会返回1条记录。



上面是这个BUG 的源码分析过程, 有个非常重要的关键点,就是end_loop>100, 这个循环次数,

我们简单的理解为查找过程中跳过的行数。下面我们来举例复现这个bug .

表跟数据准备:

创建t2表:

CREATE TABLE `t2` (

 `id` int(11) NOT NULL AUTO_INCREMENT,

 `cid` int(11) DEFAULT NULL,

 PRIMARY KEY (`id`),

 KEY `cid` (`cid`)

)

插入测试数据:

insert into t2 values(1,1);

insert into t2 values(2,2);

insert into t2 values(3,3);

insert into t2 values(4,4);

insert into t2 values(5,5);

insert into t2 values(6,6);

insert into t2 values(7,7);

insert into t2 values(8,8);

insert into t2 values(9,9);

insert into t2 values(10,10);

insert into t2 values(11,11);

insert into t2 values(12,12);

insert into t2 values(13,13);


依次按先后顺序执行如下步骤:

会话1:

Begin;

 

会话2:

Begin;

 

然后会话2 插入数据, 插入数据超过100行。

 

insert into t2 values(14,14);

insert into t2 values(15,15);

insert into t2 values(16,16);

insert into t2 values(17,17);

insert into t2 values(18,18);

insert into t2 values(19,19);

…………………………………………………

…………………………………………………

………………………………………………..

insert into t2 values(124,124);

insert into t2 values(125,125);


然后会话1执行

 

select * from t2 where cid>0 andcid<12; 

再次执行

select * from t2 where cid>0 andcid<12;


“不可思议的神奇结果出现了”,以下是结果截图:

突遇mysql 5.7中导致SQL执行结果出错的严重bug


在这里,将测试案例再扩展一下,请注意观察测试结果是否发生变化。注意,每次测试时只进行一种扩展。

 

扩展1:如果会话1的sql select count(*) from t2 where cid>0 and cid<10;改成

select count(*) from t2 where cid>0and cid<14,现象会发生变化吗?

 

扩展2:如果会话2的插入数据量少于90行,现象是否会发生变化吗?

 

  这两个扩展测试案例有兴趣的朋友可以自行测试一下,测试完,可以让大家更深入了解上面提到的bug产生的条件。 


  但是,上述的测试案例中,有insert 操作,而我们研发同事上报的案例,查询结果产生错误的表,曾经只做过delete 操作。于是如法炮制delete 操作案例,希望bug也会复现。

   

   但是,很失望,通过delete 操作,并没有手工复现这个现象,然后一度怀疑,我们遇到的问题可能跟上面的测试案例里的问题不是同一个。

        

  为什么delete 操作导致查询结果出错的案例没有被复现?为什么delete 操作的案例难以复现?猜测原因是:在delete 操作commit 之前,查询语句能从回滚段查到正常结果。事务提交之后,被标记为delete 的行,可能很快就被purge 线程清理,所以不太好手工复现。同时,我们研发同学遇到的情况:是在大并发的delete 情况下,同时进行查询,偶尔遇到只返回1条记录的情况,并非手工测试能触发。

  

  为了验证上面的猜测,决定临时禁用purge线程,但purge线程无法通过参数禁用,所以只能在purge线程的工作函数中加入跳出代码,使purge线程不再实际工作,然后进行测试。


会话1

将数据删除,并进行commit:(注:因为强行禁用了purge线程的功能,数据库在工作一段时间后自动crash,如下图所示

会话2执行查询,bug出现了。


至此,已经定位了我们研发同事在测试过程中遇到的问题。