作者： Asiaye 原文来源：https://tidb.net/blog/df697598
背景介绍
某一天早上来到公司，接到业务同学反馈，**线上某个SQL之前查询速度很快，从某个时间点开始查询速度突然变慢了**，希望DBA帮忙查看下。业务同学反馈的原话如下：
复制代码
看到这个问题，我第一时间询问了业务对这个表的基本操作，得到的反馈如下：
复制代码
分析过程
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 |+-----------------+------------+---------------------+--------------+---------------+-----------+-------------+----------+--------+------+------------+---------+---------------+---------+------------+-----------+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 代表 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执行耗时情况如下：
复制代码
可以看到，大部分执行耗时都在 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 | | 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 倍还多！！！
修改之后，业务同学反馈查询速度提升明显，监控肉眼可见：
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 面板即可。
如果监控中使用 Pseudo 统计信息的 SQL 过多，那么说明我们的统计信息存在大量失效的情况，需要对这类 SQL 访问的表重新进行信息统计。
总结
到这里，上面的问题算是解决了，我们也知道了如何对使用了Pseudo统计信息的SQL进行排查了。
我们先尝试写一些总结：
复制代码
1、遇到慢查询，我们一般需要进行一系列分析，包括 SQL 历史运行状态了解、SQL 语义分析、SQL 访问的表对应的表结构分析、执行计划分析等等
2、TiDB 的 Dashboard 中的慢日志模块已经帮用户整理了相关信息，要学会借助已有的功能去排查问题。
3、问题解决后，还应该想办法从源头上杜绝问题再次发生。
其实如果更近一步去思考，既然TiDB本身会进行统计信息收集，那么它的收集策略又是怎样的呢？？？为什么它有收集统计信息的功能，我们的表还会使用到pseudo统计信息呢？？？这些，其实都是值得思考的问题。这里我给出一点官方文档的提示：
复制代码
关于统计信息的更多细节，等待大家在实践中去探索，去发现。:)
评论