背景介紹
某一天早上來到公司，接到業務同學反饋，線上某個SQL之前查詢速度很快，從某個時間點開始查詢速度突然變慢了，希望DBA幫忙檢視下。業務同學反饋的原話如下：
看到這個問題，我第一時間詢問了業務對這個表的基本操作，得到的反饋如下：
這個表的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_opertimeDESC 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, stats
from
information_schema.slow_query
where is_internal = false
and 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統計資訊呢？？？這些，其實都是值得思考的問題。這裡我給出一點官方文件的提示：
關於統計資訊的更多細節，等待大家在實踐中去探索，去發現。:)
原作者：Asiaye 發表時間：2022/4/26 原文連結：tidb.net/blog/df697598
本作品採用《CC 協議》，轉載必須註明作者和本文連結