一個小操作,SQL查詢速度翻了1000倍。

語言: CN / TW / HK

背景介紹

某一天早上來到公司,接到業務同學反饋,線上某個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 | +-----------------+------------+---------------------+--------------+---------------+-----------+-------------+----------+--------+------+------------+---------+---------------+---------+------------+-----------+ 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執行耗時情況如下:

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, 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面板即可。

image.png

如果監控中使用Pseudo統計資訊的SQL過多,那麼說明我們的統計資訊存在大量失效的情況,需要對這類SQL訪問的表重新進行資訊統計。

總結

到這裡,上面的問題算是解決了,我們也知道了如何對使用了Pseudo統計資訊的SQL進行排查了。

我們先嚐試寫一些總結:

1、遇到慢查詢,我們一般需要進行一系列分析,包括SQL歷史執行狀態瞭解、SQL語義分析、SQL訪問的表對應的表結構分析、執行計劃分析等等

2、TiDB的Dashboard中的慢日誌模組已經幫使用者整理了相關資訊,要學會藉助已有的功能去排查問題。

3、問題解決後,還應該想辦法從源頭上杜絕問題再次發生。

其實如果更近一步去思考,既然TiDB本身會進行統計資訊收集,那麼它的收集策略又是怎樣的呢???為什麼它有收集統計資訊的功能,我們的表還會使用到pseudo統計資訊呢???這些,其實都是值得思考的問題。這裡我給出一點官方文件的提示:

image.png

image.png

關於統計資訊的更多細節,等待大家在實踐中去探索,去發現。:)

原作者:Asiaye 發表時間:2022/4/26 原文連結:https://tidb.net/blog/df697598