美文网首页
分析一个执行时间很长的sql

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

作者: dyyy_li | 来源:发表于2019-09-26 09:24 被阅读0次

背景

在查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

    背景 在查bug时发现有两个相似sql查询速度相差巨大: 区别仅在于 category 一个是43,一个是8。(后...

  • mysql 查询时间测试

    MySQL 的性能-SQL 执行分析(执行时间分析) 先执行 show variables like 'profi...

  • sql优化之慢sql耗时排查

    sql 语句性能分析 1、看 sql 语句执行时间 2、看 sql 的执行计划 3、查看 sql 的执行中各个环节...

  • SQL 调优之查询调优

    sql 语句性能分析 1、看 sql 语句执行时间 2、看 sql 的执行计划 3、查看 sql 的执行中各个环节...

  • 【故障诊断】MySql 慢查询

    一般来说,SQL的执行时间在几十毫秒~几百毫秒左右,如果一个简单的sql,操作一个数据量不大的表,执行时间还很长,...

  • MySQL EXPLAIN

    在日常工作中,我们会有时会去查询一些执行时间比较久的SQL语句,EXPLAIN可以帮助开发人员分析SQL问题,查看...

  • oracle表中没有用bitmap索引,但是执行计划中却有bit

    还是之前的项目的数据库优化过程,这次换成了分析AWR报告中的TOP SQL 项目中有一个很长的SQL,篇幅原因就不...

  • SQL性能优化

    1.sql无效表删除 2.查看sql消耗时间,执行时间,抓取数据时间。 3.执行时间过多,查询执行器,查看执行器消...

  • 作为一名程序员写好SQL是真的很重要

    负责的项目主要采用阿里云数据库MySQL,最近频繁出现慢SQL告警,执行时间最长的竟然高达5分钟。导出日志后分析,...

  • 用log4jdbc发现性能问题

    介绍 log4jdbc是一个java的jdbc驱动, 可以用于记录SQL日志和SQL执行时间等信息 log4jdb...

网友评论

      本文标题:分析一个执行时间很长的sql

      本文链接:https://www.haomeiwen.com/subject/pstmuctx.html