环境信息:
系统版本: CentOS release 6.10
配置:虚机、64G内存、16C逻辑CPU
版本:5.7.12-log MySQL Community Server (GPL)
pt-query-digest mysql-slow.log --since '2020-11-01 00:01:00' --until '2020-11-09 10:00:00' >slow_report1.log
以上的慢SQL,平均执行时间为123s,看着是很简单的SQL,基本逻辑是:查询t_test_info表id大于等于它本身最大的id乘以个随机数取整,同时区域编号为5400的数据,根据id排序后,取第一行数据。t_test_info的数据量为6w+,并不是非常大。
表结构如下:
对应的执行计划:
UNCACHEABLE SUBQUERY:对于外层的主表,一个子查询的结果不能被缓存,每次都需要计算(耗时操作)
发现这执行计划存在问题,idx_ctime这个索引是ctime列的,整个SQL都未出现ctime这一列,难道是优化器选错索引?考虑ingore index(idx_ctime) 去干预,发现它就选择了idx_con_id这个索引,忽略考虑ingore index(idx_ctime) 去干预,发现它就选择了idx_con_id索引又会选择下一个。所以从执行计划来看,虽然是使用了索引,但filtered过滤的是100%的数据,跟全表扫描没啥区别。
这里也考虑说select * 全字段数据,换成select id减少SQL执行阶段Sending data的时间,执行时间也是一样的,没有区别。
FORMAT=JSON格式的执行计划,查看资源消耗情况,根据SQL的逻辑,看资源消耗是正常的(先进行子查询外部的查询,得到一个结果集63713行数据,然后这个结果的每一行在跟select子查询的结果集进行匹配)
开启optimizer_trace,对该sql执行的过程进行跟踪分析:
同时使用pstask进行记录堆栈信息
这里的19175 是根据performance_schema.threads查询该SQL对应的THREAD_OS_ID。
通过pt-pmp对trace信息汇总 pt-pmp /tmp/pstack_1110.log:

/tmp/pstack_1110.log 部分信息
根据pt-pmp的统计,以上的次数多达237次。这里感觉是陷入某内部函数循环里面,需要多次判断取值才能返回。要想找到根因,只能看源码了,个人能力有限,先记录下来,有大神感兴趣可以研究一下。
到这里,我考虑将rand函数换成一个常量,查看执行计划并执行,发现是不一样的,执行时间也是毫秒级。
为进一步猜想是随机函数作为子查询的bug(也可能是UNCACHEABLE SUBQUERY问题,我更倾向这个原因,能力有限,还无法定论,大神可以指正一下),那么在当前版本5.7.12上可能存在,在别的版本已经修复,于是我在测试环境找了个8.0.20版本的库,构建了相同表结构,并造了相同数量的数据。
先对比了执行计划,发现执行计划是一样的, 8.0.20版本的执行计划:
不同的是,在8.0.20的环境上,执行时间大概是0.03秒,差了几万倍,差别太大了。
回到5.7.12环境上,我根据SQL实现的逻辑,进行了改写,避免rand函数作为子查询,按照子查询改写为join的思路如下:
以上SQL在5.7.12环境上毫秒级就可以出结果,但该SQL会产生笛卡尔积,如果数据量很大,性能也会下降。并非合适的解决方案。
于是再按照避免rand函数作为子查询思路,拆分成两个SQL,先获取一个随机数,以传参的方式,进行查询,这种在代码层也相对较好实现。
在8.0以上版本,可以考虑使用with as的方式构建个临时表的方式进行改写,5.7不支持该语法。
后记,后续参考了官方资料,更倾向是执行计划走UNCACHEABLE SUBQUERY这个原因导致的
https://dev.mysql.com/doc/refman/5.7/en/explain-output.html
https://dev.mysql.com/doc/refman/5.7/en/query-cache-operation.html
同时参考《MySQL:查询字段数量多少对查询效率的影响》