一個小操作,SQL查詢速度翻了1000倍。
背景介紹
某一天早上來到公司,接到業務同學反饋,線上某個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_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, 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 原文連結:http://tidb.net/blog/df697598
- TiDB 的“聚簇因子” -- 從 cop task 到 shard_row_id_bits
- TiDB Hackathon 2022丨總獎金池超 35 萬!邀你喚醒程式碼世界的更多可能性!
- TiDB監控節點擴縮容操作(是否保留歷史資料)
- TiFlash 表示式的實現與設計
- 上游sql通過drainer同步到kafka時在kafka中是什麼樣子的
- TiFlash 儲存層概覽
- TiFlash 計算層概覽
- TiCDC 架構和資料同步鏈路解析
- TiKV & TiFlash 加速複雜業務查詢
- 讓秒殺狂歡更從容:大促背後的資料庫(下篇)
- TiCDC 6.0原理之Sorter演進
- TiDB 之 TiCDC6.0 初體驗
- 帶你全面瞭解compaction 的13個問題
- TiDB 6.1 新特性解讀 | TiDB 6.1 MPP 實現視窗函式框架
- TiFlash 面向編譯器的自動向量化加速
- 你踩過這些坑嗎?謹慎在時間型別列上建立索引
- TiDB和C#的簡單CRUD應用程式
- TiDB VS MySQL
- TIDB監控升級解決panic的漫漫探索之路
- 記憶體悲觀鎖原理淺析與實踐