[转帖]一个小操作,SQL 查询速度翻了 1000 倍

一个,操作,sql,查询,速度 · 浏览次数 : 0

小编点评

**数据统计信息失效的解决方案** **方案1:SQL排查并手动分析** ```sql select * from t1 where a=1; select * from t1 where a=2; select * from t1 where a>2; select * from t1 where a>3; ``` **方案2:修改参数pseudo-estimate-ratio** ```sql set pseudo-estimate-ratio=1; ``` **方案3:修改参数tidb_enable_pseudo_for_outdated_stats** ```sql set tidb_enable_pseudo_for_outdated_stats=Off; ``` **方案4:使用TiDB Dashboard排查** 1. 登录 TiDB 的 Dashboard。 2. 点击 TiDB--->statistics--->pseudo estimation OPS面板。 3. 如果监控中使用Pseudo统计信息的SQL过多,那么说明我们的统计信息存在大量失效的情况,需要对这类SQL访问的表重新进行信息统计。 **总结** 解决问题后,需要想办法从源头上杜绝问题再次发生。其实如果更近一步去思考,既然TiDB本身会进行统计信息收集,那么它的收集策略又是怎样的呢?为什么它有收集统计信息的功能,我们的表还会使用到pseudo统计信息呢?这些,其实都是值得思考的问题。

正文

https://tidb.net/book/tidb-monthly/2022/2022-04/usercase/sql-1000
复制

 

背景介绍

某一天早上来到公司,接到业务同学反馈,线上某个SQL之前查询速度很快,从某个时间点开始查询速度突然变慢了,希望DBA帮忙查看下。业务同学反馈的原话如下:

image.png

看到这个问题,我第一时间询问了业务对这个表的基本操作,得到的反馈如下:

  • 这个表的SQL语法没有发生过变化
  • 这个表的表结构近期未发生变更
  • 这个表是个日志表,近期只有写入insert,没有大量delete、update操作

分析过程

1、SQL分析

首先,我们来看下这条SQL(脱敏之后):

SELECT

xxx, xxx, xxx, xxx, ....

FROM log_xxxx_2022_4

WHERE 1=1

AND l_mid = 'xxxxxxx-E527B8CD-84B-960'

AND l_opertime < '2022-04-20 10:56:37'

AND l_opertime >= '2022-03-20 10:56:37'

ORDER BY l_opertime DESC LIMIT 0,20;

SQL的语义本身比较简单,是一个单表查询,不涉及复杂查询:

从某一张表里面,利用l_mid和l_opertime这两个字段作为过滤条件,输出表里面的其他字段,并按照l_opertime排序。

2、表结构分析

这样一条简单的SQL,如果有索引的话,应该不会出现问题才对,我们看下表结构:

show index from  log_xxxx_2022_4;+-----------------+------------+---------------------+--------------+---------------+-----------+-------------+----------+--------+------+------------+---------+---------------+---------+------------+-----------+| Table           | Non_unique | Key_name            | Seq_in_index | Column_name   | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_comment | Visible | Expression | Clustered |+-----------------+------------+---------------------+--------------+---------------+-----------+-------------+----------+--------+------+------------+---------+---------------+---------+------------+-----------+| log_xxxx_2022_4 |          0 | PRIMARY             |            1 | l_id          | A         |           0 |     NULL | NULL   |      | BTREE      |         |               | YES     | NULL       | YES       || log_xxxx_2022_4 |          1 | l_oper              |            1 | l_oper        | A         |           0 |     NULL | NULL   |      | BTREE      |         |               | YES     | NULL       | NO        || log_xxxx_2022_4 |          1 | l_channel           |            1 | l_channel     | A         |           0 |     NULL | NULL   |      | BTREE      |         |               | YES     | NULL       | NO        || log_xxxx_2022_4 |          1 | l_xxxxid            |            1 | l_xxxxid      | A         |           0 |     NULL | NULL   |      | BTREE      |         |               | YES     | NULL       | NO        || log_xxxx_2022_4 |          1 | l_mid               |            1 | l_mid         | A         |           0 |     NULL | NULL   |      | BTREE      |         |               | YES     | NULL       | NO        || log_xxxx_2022_4 |          1 | l_user              |            1 | l_user        | A         |           0 |     NULL | NULL   |      | BTREE      |         |               | YES     | NULL       | NO        || log_xxxx_2022_4 |          1 | l_opertime          |            1 | l_opertime    | A         |           0 |     NULL | NULL   |      | BTREE      |         |               | YES     | NULL       | NO        || log_xxxx_2022_4 |          1 | l_xxxstatus         |            1 | l_xxxstatus   | A         |           0 |     NULL | NULL   |      | BTREE      |         |               | YES     | NULL       | NO        || log_xxxx_2022_4 |          1 | index_l_submit_time |            1 | l_submit_time | A         |           0 |     NULL | NULL||BTREE||| YES     |NULL|NO|+-----------------+------------+---------------------+--------------+---------------+-----------+-------------+----------+--------+------+------------+---------+---------------+---------+------------+-----------+9rowsinset(0.00 sec)
复制
 

从上述索引结构,可以看出来,我们的l_mid字段和l_opertime字段,都有索引。

从索引原理上看,这个SQL的执行计划至少应该是一个IndexRangeScan(索引范围扫描)。

3、执行计划分析

传统的MySQL中,使用Explain语句来分析MySQL的执行计划。在TiDB中,我们可以使用2种方法查看TiDB的执行计划:

a、Explain + SQL :这种方法不会真正执行语句,会直接返回执行计划

b、Explain Analyze + SQL : 这种方法会执行SQL语句,并返回SQL的执行计划

我们使用上述方法b来查看执行计划(原因是这种方法可以看到SQL的执行时间),上述SQL的执行计划如下:

+----------------------------------+----------+----------+-----------+-----------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------------------------------------------------------------+----------+------+| id                               | estRows  | actRows  | task      | access object                                       | execution info                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                         | operator info                                                                        | memory   | disk |+----------------------------------+----------+----------+-----------+-----------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------------------------------------------------------------+----------+------+| Limit_12                         | 20.00    | 0        | root      |                                                     | time:26.2s, loops:1                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                    | offset:0, count:20                                                                   | N/A      | N/A  || └─IndexLookUp_28                 | 20.00    | 0        | root      |                                                     | time:26.2s, loops:1, index_task: {total_time: 26.1s, fetch_handle: 1.95s, build: 3.39s, wait: 20.7s}, table_task: {total_time: 2m6.3s, num: 1043, concurrency: 5}                                                                                                                                                                                                                                                                                                                                                                                                                      |                                                                                      | 167.2 MB | N/A  ||   ├─IndexRangeScan_25(Build)     | 20000.00 | 21180838 | cop[tikv] | table:log_xxxx_2022_4, index:l_opertime(l_opertime) | time:848.9ms, loops:20703, cop_task: {num: 23, max: 1.42s, min: 2.14ms, avg: 712.3ms, p95: 1.15s, max_proc_keys: 969873, p95_proc_keys: 960000, tot_proc: 15.1s, tot_wait: 41ms, rpc_num: 23, rpc_time: 16.4s, copr_cache_hit_ratio: 0.04}, tikv_task:{proc max:763ms, min:31ms, p80:729ms, p95:747ms, iters:20788, tasks:23}, scan_detail: {total_process_keys: 20220838, total_process_keys_size: 930158548, total_keys: 20220861, rocksdb: {delete_skipped_count: 0, key_skipped_count: 20220839, block: {cache_hit_count: 12975, read_count: 28, read_byte: 1.35 MB}}}             | range:[2022-03-20 10:56:37,2022-04-20 10:56:37), keep order:true, desc, stats:pseudo | N/A      | N/A  ||   └─Selection_27(Probe)          | 20.00    | 0        | cop[tikv] |                                                     | time:1m57.9s, loops:1043, cop_task: {num: 1441, max: 891.8ms, min: 848.6µs, avg: 91.2ms, p95: 286.5ms, max_proc_keys: 20992, p95_proc_keys: 20480, tot_proc: 1m51.3s, tot_wait: 17.1s, rpc_num: 1441, rpc_time: 2m11.3s, copr_cache_hit_ratio: 0.00}, tikv_task:{proc max:235ms, min:0s, p80:78ms, p95:98ms, iters:27477, tasks:1441}, scan_detail: {total_process_keys: 21180838, total_process_keys_size: 7841770073, total_keys: 21184733, rocksdb: {delete_skipped_count: 0, key_skipped_count: 55260873, block: {cache_hit_count: 239289, read_count: 83, read_byte: 622.7 KB}}}  | eq(comment5_log.log_xxxx_2022_4.l_mid, "625F70C0-ABD4F004-E527B8CD-84B-960")         | N/A      | N/A  ||     └─TableRowIDScan_26          | 20000.00 | 21180838 | cop[tikv] |table:log_xxxx_2022_4                               | tikv_task:{proc max:231ms, min:0s, p80:76ms, p95:95ms, iters:27477, tasks:1441}                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                        | keep order:false, stats:pseudo                                                       | N/A      | N/A  |+----------------------------------+----------+----------+-----------+-----------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------------------------------------------------------------+----------+------+5rowsinset(26.15 sec)
复制
 

上述SQL的执行时间是:26.15 sec

我们对TiDB的执行计划进行分析:

id 列:算子名称.

从图中可以看出,我们当前的SQL算子包含:

IndexLookUp:先汇总 Build 端 TiKV 扫描上来的 RowID,再去 Probe 端上根据这些 RowID 精确地读取 TiKV 上的数据。

IndexFullScan:另一种“全表扫描”,扫的是索引数据,不是表数据。

TableRowIDScan:根据上层传递下来的 RowID 扫描表数据。时常在索引读操作后检索符合条件的行。

estRows 列:显示TiDB预计会处理的行数

actRows 列:显示TiDB算子实际输出的数据条数

预估扫描行数最多是2w行,但是实际的输出条数是2000w行。

task 列:显示算子在执行语句时的所在位置,root代表tidb,cop代表tikv

access object 列:代表被访问的表对象和索引

execution info 列:算子的实际执行信息,包含执行时间等

这部分内容可以看到每个步骤的执行时间,但是不是特别直观,后面我们会通过Dashboard页面去分析执行时间。

operator info 列:显示访问表、分区、索引的其他信息

range: [2022-03-20 10:56:37,2022-04-20 10:56:37] 表示查询的 WHERE 字句 (l_opertime = 2022-04-20 10:56:37) 被下推到了 TiKV,对应的 task 为 cop[tikv]

keep order:true 表示这个查询需要TiKV按照顺序返回结果

*stats:pseudo 它表示estRows显示的预估行数可能不准,TiDB定期在后台更新统计信息,也可以通过Analyze table 来手动更新信息。*

memory 列:算子占用的内存空间大小

disk 列:算子占用磁盘空间的大小

 

4、TiDB DashBoard分析

​ 上述Explain Analyze分析的执行计划内容,execution info列不够直观。我们看下TiDB 的Dashboard,其实也能发现一些端倪。

​ 进入TiDB 的 Dashboard页面--->点击左侧的慢查询--->按照SQL语句(或者提炼的SQL指纹)进行搜索--->查看SQL执行耗时情况,看到类似的SQL执行耗时情况如下:

image.png

可以看到,大部分执行耗时都在Coprocessor执行耗时阶段,其他阶段占用的时间非常少。

值得注意的是,Coprocessor累计执行耗时看起来大于SQL执行时间,这个是因为TiKV 会并行处理任务,因此累计执行耗时不是自然流逝时间

我们再看看SQL的基本信息:

image.png

从SQL基本信息上,也可以看到,*当前SQL使用的统计信息是pseudo,而pseudo代表统计信息不准确,就有可能导致TiDB基于成本的执行计划选择错误。*

解决办法

有了上述的理论基础,问题的解决就变得简单了。

image.png

根据官方文档描述,我们使用Analyze table log_xxxx_2022_4 来重新收集下这个表的统计信息,然后重新执行查询:

analyze table log_cmnt_2022_4;Query OK, 0 rows affected, 1 warning (51.11 sec)再次利用Explain Analyze查看SQL执行计划:     +----------------------------------+---------+---------+-----------+-------------------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------------------------------------------------------------------------------------------------------------------------+-----------+------+| id                               | estRows | actRows | task      | access object                             | execution info                                                                                                                                                                                                                                                                                                                                                                                | operator info                                                                                                                                    | memory    | disk |+----------------------------------+---------+---------+-----------+-------------------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------------------------------------------------------------------------------------------------------------------------+-----------+------+| TopN_9                           | 2.15    | 0       | root      |                                           | time:977µs, loops:1                                                                                                                                                                                                                                                                                                                                                                           | coxxxx5_log.log_xxxx_2022_4.l_opertime:desc, offset:0, count:20                                                                                 | 0 Bytes   | N/A  || └─IndexLookUp_24                 | 2.15    | 0       | root      |                                           | time:939.3µs, loops:2,                                                                                                                                                                                                                                                                                                                                                                        |                                                                                                                                                  | 236 Bytes | N/A  ||   ├─IndexRangeScan_17(Build)     | 2.15    | 0       | cop[tikv] | table:log_xxxx_2022_4, index:l_mid(l_mid) | time:822.3µs, loops:1, cop_task: {num: 1, max: 749.8µs, proc_keys: 0, tot_proc: 1ms, rpc_num: 1, rpc_time: 734.8µs, copr_cache_hit_ratio: 0.00}, tikv_task:{time:1ms, loops:1}, scan_detail: {total_process_keys: 0, total_process_keys_size: 0, total_keys: 1, rocksdb: {delete_skipped_count: 0, key_skipped_count: 0, block: {cache_hit_count: 11, read_count: 0, read_byte: 0 Bytes}}}    | range:["625F70C0-ABD4F004-E527B8CD-84B-960","625F70C0-ABD4F004-E527B8CD-84B-960"], keep order:false                                              | N/A       | N/A  ||   └─TopN_23(Probe)               | 2.15    | 0       | cop[tikv] |                                           |                                                                                                                                                                                                                                                                                                                                                                                               | comment5_log.log_xxxx_2022_4.l_opertime:desc, offset:0, count:20                                                                                 | N/A       | N/A  ||     └─Selection_19               | 2.15    | 0       | cop[tikv] |                                           |                                                                                                                                                                                                                                                                                                                                                                                               | ge(comxxxx5_log.log_xxxx_2022_4.l_opertime, 2022-03-20 10:56:37.000000), lt(coxxxxx5_log.log_xxxx_2022_4.l_opertime, 2022-04-20 10:56:37.000000) | N/A       | N/A  ||       └─TableRowIDScan_18        | 2.15    | 0       | cop[tikv] | table:log_xxxx_2022_4                     |                                                                                                                                                                                                                                                                                                                                                                                               | keep order:false                                                                                                                                 | N/A       | N/A  |+----------------------------------+---------+---------+-----------+-------------------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------------------------------------------------------------------------------------------------------------------------+-----------+------+6 rows in set (0.00 sec)
复制
 

从最新的SQL执行计划中,我们不难发现:

1、执行计划中,预估的行数estRows,从一开始的2w行到现在的2.15行,实际执行行数actRows,从一开始的2000w行,到现在的0行,有了很大的一个改善。

2、SQL的执行时间变成了0.00s,意味着执行时间在10ms之内。

现在我们对比下执行时间:

统计信息收集之前:SQL执行26s

统计信息收集之后:SQL执行0.00s

一个Analyze操作,让整个SQL执行时间,足足翻了1000倍还多!!!

修改之后,业务同学反馈查询速度提升明显,监控肉眼可见:

image.png

image.png

Pseudo状态的SQL如何主动排查?如何解决?

​ 从我们上述案例中可以发现,如果一个表的统计信息采用了pseudo,很可能造成查询慢的情况。因此,在实际应用中,我们需要对使用了pseudo统计信息的SQL进行摸排,可以使用下面的方法来进行摸排:

方案1、SQL排查并手动analyze

select query, query_time, statsfrom information_schema.slow_querywhere is_internal = falseand stats like '%pseudo%';
复制
 

使用上述SQL查找到所有的使用了pseudo统计信息的SQL,并对它们访问的表,手动做一次analyze table操作。

上述SQL的输出样例如下:

+-----------------------------+-------------+---------------------------------+| query                       | query_time  | stats                           |+-----------------------------+-------------+---------------------------------+| select * from t1 where a=1; | 0.302558006 | t1:pseudo                       || select * from t1 where a=2; | 0.401313532 | t1:pseudo                       || select * from t1 where a>2; | 0.602011247 | t1:pseudo                       || select * from t1 where a>3; | 0.50077719  | t1:pseudo                       || select * from t1 join t2;   | 0.931260518 | t1:407872303825682445,t2:pseudo |+-----------------------------+-------------+---------------------------------+
复制
 

方案2、修改参数:pseudo-estimate-ratio

这个参数代表修改的行数/表的总行数的比值,超过该值的时候,系统会认为统计信息已经过期,就会使用pseudo,这个值的默认值是0.8,最小值是0,最大值是1。它是统计信息是否失效的判断标准。

可以将这个参数调整成1,从而让TiKV执行SQL的时候不选择pseudo统计信息。

方案3、修改参数:tidb_enable_pseudo_for_outdated_stats

这个变量用来控制TiDB优化器在某一张表上的统计信息过期之后的行为,默认值是On。

如果使用默认值On,在某张表的统计信息过期之后,代表优化器认为当前表除了总行数之外,其他的统计信息已经失效,所以会采用pseudo统计信息;

如果使用Off,即使一张表上的统计信息失效,也会使用当前表的统计信息,不会使用pseudo。如果你的表更新频繁,又没有即使对表进行analyze table,那么建议使用off选项。

方案4、TiDB Dashboard排查

登录TiDB的Dashboard,点击TiDB--->statistics--->pseudo estimation OPS面板即可。

image.png

如果监控中使用Pseudo统计信息的SQL过多,那么说明我们的统计信息存在大量失效的情况,需要对这类SQL访问的表重新进行信息统计。

总结

到这里,上面的问题算是解决了,我们也知道了如何对使用了Pseudo统计信息的SQL进行排查了。

我们先尝试写一些总结:

1、遇到慢查询,我们一般需要进行一系列分析,包括SQL历史运行状态了解、SQL语义分析、SQL访问的表对应的表结构分析、执行计划分析等等

2、TiDB的Dashboard中的慢日志模块已经帮用户整理了相关信息,要学会借助已有的功能去排查问题。

3、问题解决后,还应该想办法从源头上杜绝问题再次发生。

其实如果更近一步去思考,既然TiDB本身会进行统计信息收集,那么它的收集策略又是怎样的呢???为什么它有收集统计信息的功能,我们的表还会使用到pseudo统计信息呢???这些,其实都是值得思考的问题。这里我给出一点官方文档的提示:

image.png

image.png

关于统计信息的更多细节,等待大家在实践中去探索,去发现。:)

与[转帖]一个小操作,SQL 查询速度翻了 1000 倍相似的内容:

[转帖]一个小操作,SQL 查询速度翻了 1000 倍

https://tidb.net/book/tidb-monthly/2022/2022-04/usercase/sql-1000 背景介绍​ 某一天早上来到公司,接到业务同学反馈,线上某个SQL之前查询速度很快,从某个时间点开始查询速度突然变慢了,希望DBA帮忙查看下。业务同学反馈的原话如下: ​

[转帖]shell 篇 用上今天分享的快捷键以后,我早下班了一小时

每次看着别人操作 shell 的时候,快捷键用得飞起,尤其是那个快速搜索历史命令,避免低效的↑↓键切换历史命令,很装逼有木有。。 废话不多说,下面是我整理的常用快捷键,真的可以提高自己的工作效率的,很不错!~ 一、常用快捷键小技巧 以下快捷键,都是一些常用的,记住这些命令,你的工作效率就会大大提升。

[转帖]简单介绍四种IO模型

https://cdn.modb.pro/db/525350 当一个网络IO发生(假设是read)时,它会涉及两个系统对象,一个是调用这个IO的进程,另一个是系统内核。当一个read操作发生时,它会经历两个阶段:①等待数据准备;②将数据从内核拷贝到进程中。为了解决网络IO中的问题,提出了4中网络IO

[转帖]PostgreSQL的MVCC vs InnoDB的MVCC

任何一个数据库最主要功能之一是可扩展。如果不删除彼此,则尽可能较少锁竞争从而达到这个目的。由于read、write、update、delete是数据库中最主要且频繁进行的操作,所以并发执行这些操作时不被阻塞则显得非常重要。为了达到这种目的,大部分数据库使用多版本并发控制(Multi-Version

[转帖]GC overhead limit exceeded原因分析及解决方案

https://zhuanlan.zhihu.com/p/88956975 最近一个上线运行良好的项目出现用户无法登录或者执行某个操作时,有卡顿现象。查看了日志,出现了大量的java.lang.OutOfMemoryError: GC overhead limit exceeded错误。 oracl

[转帖]【JVM】线程安全与锁优化

线程安全 1.定义 当多个线程访问一个对象时,如果不用考虑这些线程在运行时环境下的调度和交替行,也不需要进行额外的同步,或者在调用方进行任何其他的协调操作,调用这个对象的行为都可以获得正确的结果 2.分类 (1)不可变 不可变的对象一定是线程安全的,只要一个不可变对象被正确地构建出来(没有发生thi

[转帖]Oracle Linux 9 - Oracle 提供支持 RHEL 兼容发行版

https://sysin.org/blog/oracle-linux-9/ Oracle Linux 是一个开放、全面的操作环境,提供虚拟化、管理、云原生计算工具和操作系统,通过一个统一的支持解决方案满足您的业务需求。Oracle Linux 与 Red Hat Enterprise Linux

[转帖]炸了~Redis bigkey导致生产事故-bigkey问题全面分析

文章首发于公众号:BiggerBoy 原文链接 一个Redis生产事故的复盘,整理这篇文章分享给大家。本期文章分析Redis中的bigkey相关问题,主要从以下几个点入手: 文章目录 什么是bigkey?bigkey的危害bigkey的产生如何发现bigkey实际生产的操作方式 如何优化bigkey

[转帖]50个应知必会的Linux常识和操作

1.存放用户账号的文件在哪里? /etc/passwd 1 2.如何删除一个非空的目录? rm -rf 目录名 1 3.查看当前的工作目录用什么命令? pwd 1 4.创建一个文件夹用什么命令? mkdir 1 5.哪个Linux命令可以一次显示一页内容?上一页和下一页使用什么命令? more Sp

[转帖]gdb调试常见命令详细总结(附示例操作)

一、简介 通过gdb调试我们可以监控程序执行的每一个细节,包括变量的值、函数的调用过程、内存中数据、线程的调度等,从而发现隐藏的错误或者低效的代码,程序的调试过程主要有:单步执行,跳入函数,跳出函数,设置断点,设置观察点,查看变量。 本文将主要介绍linux下的gdb调试工具常用的命令和具体的使用实