分析一个执行时间很长的sql

背景

在查bug时发现有两个相似sql查询速度相差巨大:

SELECT * FROM news_basic WHERE category =43 AND status in (1,7) AND source in (11,12,13)
  ORDER BY publish_time  DESC    LIMIT 6;

SELECT * FROM news_basic WHERE category =8 AND status in (1,7) AND source in (11,12,13) 
 ORDER BY publish_time  DESC    LIMIT 6;

区别仅在于 category 一个是43,一个是8。(后面方便阐述称第一个sql为Q43,第二个sql为Q8。)
Q43的query速度:0.00347175秒;Q8是21.150秒。

数据库版本:5.6.28

当然,在实际业务中,WHERE status in (1,7) AND source in (11,12,13) 的数据子集的category 取值分布在[10,1000]。所以,Q8的结果集必定是空的,从业务上讲是个不符合业务的sql。

但这两个sql为什么速度差这么多呢?

首先对比下数据库中两个category的记录数,数据量差距并不大。排除两category数据量相差过大造成的影响。

数据库中记录对比

再对比下执行计划 EXPLAIN

很奇怪,两sql的执行计划一致。
查询过程先走publish_time的索引再回表,没有疑问。只是rows估计扫过行数都是24,Q8也这么少吗?


Q8执行计划

Q43执行计划

进行猜测

最后使用show profile 验证一下

  1. 打开profile: set profiling = 1;
  2. 执行两条sql语句
  3. 执行show profiles;
  4. show profile for query N; (这里N=1,2).
    结果如图所示(左侧Q8,右侧Q43)


    左侧Q8,右侧Q43

时间都消耗在sending data上了,执行器耗时巨长。

注:Sending data 并不一定是指“正在发送数据”,而可能是处于执行器过程中的任意阶段.(林晓斌 MySQL实战45讲,33讲)
所以,虽然Q45结果集是空,但sending data仍可能很长。

继续深入下: 执行show profile ALL for query N;
将部分差异明显的内容整理成表格,如下所示:

二者show profile主要的差异对比

结论:

  1. 可以看出,Q8 执行的主要耗时是statistics过程中,此过程中读入了若干block 。
    先进行publish_time 的排序,然后回表根据where做检索。当检索的条数等于limit_count 时,检索停止,返回数据。
    Q8会触发mysql对limit的优化策略mysql5.6官方对limit的优化。所以在筛选到6条记录后进行返回了。
  2. Q43先通过publisth_time进行排序,然后全表检索,Q43每条记录都不符合where的限定条件。耗时都在sending data阶段。【为什么不是execting阶段?】
    该过程block_ops_in 高达1733k。后文估计了表内所有数据大约占 239k个block,这个数字远小于1733k,显然是有重复读入的。

仍存的疑问:

  1. 官方对block_ops 解释过于简单,有没有更详细的说法。

  2. 为什么block_ops_in会重复读入,与耗时成正比呢?对block_ops 的


    两次执行Q8的对比

    当然,表格标黄处都与query耗时成正比,时间越长,cpu时间 上下文切换肯定会越高的。

  3. 为什么Q8会有block_ops_out?
    官网对block_ops_in 和block_ops_out的解释
    The number of block input and output operations.
    ops是operation per second吗?

  4. execting和sending data的区别。


估算表内数据占多少block

page 和 block 是一个概念。库中pagesize是默认值 16384,也就是16k。news_basic表数据所占共3.65GB。

数据长度

很粗略地估计一下(如果表中有长字段,那么每行的size会更小,实际页数会更少)。

其他的发现

navicat的“概况”

navicat在执行完一批次查询后有个“概况”标签,与show profile类似,但是实际结果二者不太相同。
navicat会执行sql进行统计:

SELECT STATE AS `Status`, ROUND(SUM(DURATION),7) AS `Duration`, CONCAT(ROUND(SUM(DURATION)/0.002964*100,3), '') AS `Percentage` 
FROM INFORMATION_SCHEMA.PROFILING 
WHERE QUERY_ID=102 
GROUP BY SEQ, STATE 
ORDER BY SEQ

navicat分析Q8,大量的时间在execting下,sending data 会很小。

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
平台声明:文章内容(如有图片或视频亦包括在内)由作者上传并发布,文章内容仅代表作者本人观点,简书系信息发布平台,仅提供信息存储服务。
禁止转载,如需转载请通过简信或评论联系作者。

推荐阅读更多精彩内容

  • 分析SQL执行带来的开销是优化SQL的重要手段。在MySQL数据库中,可以通过配置profiling参数来启用SQ...
    张伟科阅读 1,098评论 0 1
  • ORA-00001: 违反唯一约束条件 (.) 错误说明:当在唯一索引所对应的列上键入重复值时,会触发此异常。 O...
    我想起个好名字阅读 5,413评论 0 9
  • Swift1> Swift和OC的区别1.1> Swift没有地址/指针的概念1.2> 泛型1.3> 类型严谨 对...
    cosWriter阅读 11,135评论 1 32
  • 1.设计模式是什么? 你知道哪些设计模式,并简要叙述?设计模式是一种编码经验,就是用比较成熟的逻辑去处理某一种类型...
    龍飝阅读 2,180评论 0 12
  • 劳累一天的鸟,睡了 雄鸟在巢边的枝上守护,警惕 雌鸟在巢里低垂扇面的翅膀 裹胸几个雏鸟的低鸣,并非寒冷 头钻出母亲...
    忠志_3d7b阅读 202评论 1 2