一个小操作,SQL 查询速度翻了 1000 倍。

网友投稿 505 2024-03-03



背景介绍

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

一个小操作,SQL 查询速度翻了 1000 倍。

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

这个表的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 fromlog_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 | +-----------------+------------+---------------------+--------------+---------------+-----------+-------------+----------+--------+------+------------+---------+---------------+---------+------------+-----------+ 9 rows in set (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 | +----------------------------------+----------+----------+-----------+-----------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------------------------------------------------------------------------------+----------+------+ 5 rows in set (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代表tikvaccess 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执行耗时情况如下:

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

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

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

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

解决办法

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

根据官方文档描述,我们使用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      |                  &n

版权声明:本文内容由网络用户投稿,版权归原作者所有,本站不拥有其著作权,亦不承担相应法律责任。如果您发现本站中有涉嫌抄袭或描述失实的内容,请联系我们jiasou666@gmail.com 处理,核实后本网站将在24小时内删除侵权内容。

上一篇:WordPress使用TiDB Cloud替换MySQL的案例分享
下一篇:一招教你安全从MySQL切换到TiDB
相关文章