免费国产乱理伦在线2019,日本午夜激情视频官网,国产激情视频免费在线,久久国产精品婷婷一区二区,狠狠躁夜夜躁人人爽天天2020

導(dǎo)讀

可觀測性已經(jīng)成為分布式系統(tǒng)成功運行的關(guān)鍵組成部分。如何借助多樣、全面的數(shù)據(jù)，讓架構(gòu)師更簡單、高效地定位問題、分析問題、解決問題，已經(jīng)成為業(yè)內(nèi)的一個技術(shù)焦點。本系列文章將深入解讀 TiDB 的關(guān)鍵參數(shù)，幫助大家更好地觀測系統(tǒng)的狀態(tài)，實現(xiàn)性能的優(yōu)化提升。

本文為 TiDB 可觀測性解讀系列文章的第二篇，將探討如何利用算子執(zhí)行信息更準(zhǔn)確地分析和診斷 SQL 性能。

你有沒有遇到過這樣的情況：同樣模式的 SQL 語句，僅僅是日期參數(shù)或者函數(shù)的變化，最終返回的結(jié)果形式也都相同，性能卻相差幾十甚至上百倍?，F(xiàn)實中遇到這樣的問題，我們一般會運行 explain 語句，檢查執(zhí)行計劃的變化情況。如果執(zhí)行計劃沒有改變，如何進行進一步排查？

這種情況下，可以通過 explain analyze 語句來深入查看算子的實際運行情況。本文將結(jié)合實際案例和常見問題，探討如何利用算子執(zhí)行信息更準(zhǔn)確地分析和診斷 SQL 性能。

通常我們可以用explain analyze語句獲得算子執(zhí)行信息。explain analyze會實際執(zhí)行對應(yīng)的 SQL 語句，同時記錄其運行時信息，和執(zhí)行計劃一并返回出來，記錄的信息包括：actRows、execution info、memory、disk。

不同算子的 execution info 可以通過 TiDB 文檔 (https://docs.pingcap.com/zh/tidb/stable/sql-statement-explain-analyze)了解。這些信息是研發(fā)人員在長期的性能問題定位中，總結(jié)提煉出來的指標(biāo)，值得每一個想對 TiDB SQL 性能診斷有深入研究的同學(xué)閱讀。

有時候一些 SQL 的性能問題是偶發(fā)的，這會增加我們直接使用 explain analyze 來分析的難度。這時候我們還需要借助慢日志功能來獲取有效的算子執(zhí)行信息。通常，我們可以通過 TiDB Dashboard 的慢日志查詢 (https://docs.pingcap.com/zh/tidb/stable/dashboard-overview#最近的慢查詢)頁面，快速定位并查詢到問題 SQL 的詳細執(zhí)行信息。

接下來，我們將通過一些具體案例來探討相關(guān)問題。請注意，以下案例中的執(zhí)行計劃大多直接來源于生產(chǎn)環(huán)境(做了脫敏處理)，由于本地難以復(fù)現(xiàn)這些場景，版本難以統(tǒng)一。但版本差異并不影響問題診斷和分析的完整性，本文主要探討診斷問題的思路和方法。

查詢延時抖動

查詢偶發(fā)性延時抖動是較為常見的性能問題之一。如果能夠通過慢日志定位到導(dǎo)致性能抖動的具體查詢語句，進一步分析這些查詢的算子執(zhí)行信息，往往能夠找到問題的根源并獲得有效的優(yōu)化線索。

實際案例

以一個客戶遇到過的點查詢性能抖動問題為例，點查詢的延遲偶爾會超過 2s。我們先通過慢日志查詢，定位到某次查詢的算子執(zhí)行信息：

診斷分析

首先，我們看到查詢中只有一個Point_Get_1算子，其execution info中記錄的執(zhí)行時間為2.52s。這說明執(zhí)行時間被完整記錄了下來。

進一步查看execution info，我們注意到其中包含ResolveLock項。這一項的細節(jié)顯示，總的執(zhí)行時間為2.52s，這意味著查詢的絕大部分時間都花在了resolve lock操作上。與此同時，實際的Get統(tǒng)計項顯示總時間為2.2ms，這表明獲取數(shù)據(jù)本身幾乎不耗時。

此外，還有一個txnNotFound_backoff項，它記錄了因殘留事務(wù)觸發(fā)的重試信息。這里顯示總共進行了12次重試，累計耗時2.51s，與ResolveLock項的2.52s基本一致。因此，我們可以初步推測：點查詢可能讀取到了殘留事務(wù)的鎖，嘗試resolve lock時發(fā)現(xiàn)鎖已過期，進而觸發(fā)了鎖清理操作，這一過程導(dǎo)致了較高的查詢延遲。

接下來，我們可以通過監(jiān)控數(shù)據(jù)進一步驗證這一推測：

算子并發(fā)度

在 TiDB 中，我們可以通過設(shè)置一些系統(tǒng)參數(shù)來調(diào)節(jié)算子的執(zhí)行并發(fā)度，從而最終調(diào)節(jié) SQL 的執(zhí)行性能。算子的執(zhí)行并發(fā)度往往對 SQL 的執(zhí)行性能有重要的影響，比如同樣多的 cop task，我們把并發(fā)度從 5 改到 10，性能可能就會有將近 1 倍的提升，當(dāng)然也會更集中地占用系統(tǒng)的資源。執(zhí)行信息可以幫助我們了解算子的實際執(zhí)行并發(fā)度，為更進一步的性能診斷做好準(zhǔn)備。下面我們來看一個運維同學(xué)實際遇到的問題。

實際問題

系統(tǒng)中設(shè)置了tidb_executor_concurrency為 5 以控制算子的并發(fā)度；同時設(shè)置了tidb_distsql_scan_concurrency為 15，用于限制每個讀取算子的最大線程數(shù)。那么，在下述執(zhí)行計劃中，cop_task和tikv_task是如何與這兩個參數(shù)相對應(yīng)的呢？

mysql>explainanalyzeselect*fromt0whereclike'2147%';
+-------------------------------+---------+---------+-----------+-------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------+---------+------+
|id|estRows|actRows|task|accessobject|executioninfo|operatorinfo|memory|disk|
+-------------------------------+---------+---------+-----------+-------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------+---------+------+
|IndexLookUp_10|3.82|99|root||time:2.83ms,loops:2,index_task:{total_time:733.8μs,fetch_handle:727.9μs,build:806ns,wait:5.14μs},table_task:{total_time:1.96ms,num:1,concurrency:5},next:{wait_index:821μs,wait_table_lookup_build:108.2μs,wait_table_lookup_resp:1.85ms}||41.0KB|N/A|
|├─IndexRangeScan_8(Build)|3.82|99|cop[tikv]|table:t0,index:idx_c(c)|time:719.1μs,loops:3,cop_task:{num:1,max:650μs,proc_keys:99,rpc_num:1,rpc_time:625.7μs,copr_cache_hit_ratio:0.00,distsql_concurrency:15},tikv_task:{time:0s,loops:3},scan_detail:{total_process_keys:99,total_process_keys_size:18810,total_keys:100,get_snapshot_time:102μs,rocksdb:{key_skipped_count:99,block:{cache_hit_count:3}}}|range:["2147","2148"),keeporder:false|N/A|N/A|
|└─TableRowIDScan_9(Probe)|3.82|99|cop[tikv]|table:t0|time:1.83ms,loops:2,cop_task:{num:4,max:736.9μs,min:532.6μs,avg:599μs,p95:736.9μs,max_proc_keys:44,p95_proc_keys:44,rpc_num:4,rpc_time:2.32ms,copr_cache_hit_ratio:0.00,distsql_concurrency:15},tikv_task:{procmax:0s,min:0s,avg:0s,p80:0s,p95:0s,iters:5,tasks:4},scan_detail:{total_process_keys:99,total_process_keys_size:22176,total_keys:99,get_snapshot_time:217.3μs,rocksdb:{block:{cache_hit_count:201}}}|keeporder:false|N/A|N/A|
+-------------------------------+---------+---------+-----------+-------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+-----------------------------------------+---------+------+
3rowsinset(0.00sec)

問題分析

我們正好借這個例子解釋下執(zhí)行信息中 cop_task 和 tikv_task 項的關(guān)系以及 cop task 的實際執(zhí)行并發(fā)度。

cop_task 和 tikv_task 的關(guān)系

首先需要明確，execution info中的各類xxx_task和執(zhí)行計劃中的 “task” 列并不是同一個概念。

例如，在執(zhí)行計劃中，task列的類別分別為 "root"、"cop[tikv]" 等。它既描述了算子實際在哪個組件執(zhí)行（如 TiDB、TiKV 或 TiFlash），又進一步說明了其與存儲引擎的通信協(xié)議類型（如 Coprocessor、Batch Coprocessor 或 MPP）。

相比之下，execution info中的各類task更多是從不同維度對算子執(zhí)行信息進行拆解，以便用戶快速定位潛在性能問題，并通過不同維度的信息進行相互印證。具體來說：

tikv_task描述的是某個具體 TiKV 算子的整體執(zhí)行情況；
cop_task描述的是整個 RPC 任務(wù)的執(zhí)行情況，它包含了tikv_task。例如，一個cop_task可能包含tableScan + Selection兩個算子，每個算子都有自己的tikv_task信息來描述其執(zhí)行情況；而cop_task則描述了整個 RPC 請求的執(zhí)行信息，其時間涵蓋了這兩個算子的執(zhí)行時間。

類似地，在 MPP 查詢中，execution info中的tiflash_task統(tǒng)計項描述了某個具體 TiFlash 算子的整體執(zhí)行情況：

+------------------------------+-------------+----------+--------------+----------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------+-----------+---------+
|id|estRows|actRows|task|accessobject|executioninfo|operatorinfo|memory|disk|
+------------------------------+-------------+----------+--------------+----------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------+-----------+---------+
|HashAgg_22|1.00|1|root||time:17ms,open:1.92ms,close:4.83μs,loops:2,RU:1832.08,partial_worker:{wall_time:15.055084ms,concurrency:5,task_num:1,tot_wait:15.017625ms,tot_exec:12.333μs,tot_time:75.203959ms,max:15.042667ms,p95:15.042667ms},final_worker:{wall_time:15.079958ms,concurrency:5,task_num:5,tot_wait:1.414μs,tot_exec:41ns,tot_time:75.277708ms,max:15.060375ms,p95:15.060375ms}|funcs:count(Column#19)->Column#17|6.23KB|0Bytes|
|└─TableReader_24|1.00|1|root||time:16.9ms,open:1.9ms,close:3.46μs,loops:2,cop_task:{num:2,max:0s,min:0s,avg:0s,p95:0s,copr_cache_hit_ratio:0.00}|MppVersion:3,data:ExchangeSender_23|673Bytes|N/A|
|└─ExchangeSender_23|1.00|1|mpp[tiflash]||tiflash_task:{time:13.1ms,loops:1,threads:1},tiflash_network:{inner_zone_send_bytes:24}|ExchangeType:PassThrough|N/A|N/A|
|└─HashAgg_9|1.00|1|mpp[tiflash]||tiflash_task:{time:13.1ms,loops:1,threads:1}|funcs:count(test.lineitem.L_RETURNFLAG)->Column#19|N/A|N/A|
|└─TableFullScan_21|11997996.00|11997996|mpp[tiflash]|table:lineitem|tiflash_task:{time:12.8ms,loops:193,threads:12},tiflash_scan:{mvcc_input_rows:0,mvcc_input_bytes:0,mvcc_output_rows:0,local_regions:10,remote_regions:0,tot_learner_read:0ms,region_balance:{instance_num:1,max/min:10/10=1.000000},delta_rows:0,delta_bytes:0,segments:20,stale_read_regions:0,tot_build_snapshot:0ms,tot_build_bitmap:0ms,tot_build_inputstream:15ms,min_local_stream:10ms,max_local_stream:11ms,dtfile:{data_scanned_rows:11997996,data_skipped_rows:0,mvcc_scanned_rows:0,mvcc_skipped_rows:0,lm_filter_scanned_rows:0,lm_filter_skipped_rows:0,tot_rs_index_check:3ms,tot_read:53ms}}|keeporder:false|N/A|N/A|
+------------------------------+-------------+----------+--------------+----------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------+-----------+---------+
cop task 的執(zhí)行并發(fā)度

首先，我們來看執(zhí)行計劃。IndexLookUp_10是一個root 算子。我們知道，IndexLookUp算子主要執(zhí)行兩個步驟：一是通過索引獲取目標(biāo)行的rowid；二是根據(jù) rowid 讀取所需的列數(shù)據(jù)。在IndexLookUp_10的execution info中，index_task和table_task的細節(jié)被分別列出。顯然，index_task對應(yīng)的是IndexRangeScan_8算子，而table_task對應(yīng)的是TableRowIDScan_9算子。

從并發(fā)度的角度來看，index_task沒有顯示并發(fā)信息，這意味著IndexRangeScan_8算子本身的并發(fā)度默認為1。然而，IndexRangeScan_8的cop_task的distsql_concurrency為15（由tidb_distsql_scan_concurrency參數(shù)決定），這意味著理論上它可以并發(fā)執(zhí)行15 個 cop task來讀取數(shù)據(jù)。

對于table_task，其并發(fā)度為5（由tidb_executor_concurrency參數(shù)決定），表示最多可以同時運行 5 個TableRowIDScan_9算子。而TableRowIDScan_9的cop_task的distsql_concurrency同樣為15（由tidb_distsql_scan_concurrency決定）。因此，table_task的最大并發(fā)讀取能力為5 × 15 = 75 個 cop task。

max 換成 min，慢了好幾十倍

實際案例

一條對索引列求 max 值的 SQL 花費 100 毫秒左右，換成求 min 值，卻需要花費 8s 多時間，這是他們 explain analyze 的信息：

mysql>explainanalyzeselectmax(time_a)fromt0limit1;
+--------------------------------+---------+---------+-----------+----------------------------------------------------+-------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------+-----------+------+
|id|estRows|actRows|task|accessobject|executioninfo|operatorinfo|memory|disk|
+--------------------------------+---------+---------+-----------+----------------------------------------------------+-------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------+-----------+------+
|Limit_14|1.00.|1|root||time:2.328901ms,loops:2|offset:0,count:1|N/A|N/A|
|└─StreamAgg_19|1.00|1|root||time:2.328897ms,loops:1|funcs:max(t0.time_a)->Column#18|128Bytes|N/A|
|└─Limit_39|1.00|1|root||time:2.324137ms,loops:2|offset:0,count:1|N/A|N/A|
|└─IndexReader_45|1.00|1|root||time:2.322215ms,loops:1,cop_task:{num:1,max:2.231389ms,proc_keys:32,rpc_num:1,rpc_time:2.221023ms,copr_cache_hit_ratio:0.00}|index:Limit_26|461Bytes|N/A|
|└─Limit_44|1.00|1|cop[tikv]||time:0ns,loops:0,tikv_task:{time:2ms,loops:1}|offset:0,count:1|N/A|N/A|
|└─IndexFullScan_31|1.00|32|cop[tikv]|table:t0,index:time_a(time_a)|time:0ns,loops:0,tikv_task:{time:2ms,loops:1}|keeporder:true,desc|N/A|N/A|
+------------------------------+---------+---------+-----------+----------------------------------------------------+-------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------+-----------+------+
6rowsinset(0.12sec)
mysql>explainanalyzeselectmin(time_a)fromt0limit1;
+--------------------------------+---------+---------+-----------+----------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------+-----------------+------+
|id|estRows|actRows|task|accessobject|executioninfo|operatorinfo|memory|disk|
+--------------------------------+---------+---------+-----------+----------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------+-----------------+------+
|Limit_14|1.00|1|root||time:8.263857153s,loops:2|offset:0,count:1|N/A|N/A|
|└─StreamAgg_19|1.00|1|root||time:8.26385598s,loops:1|funcs:min(t0.time_a)->Column#18|128Bytes|N/A|
|└─Limit_39|1.00|1|root||time:8.263848289s,loops:2|offset:0,count:1|N/A|N/A|
|└─IndexReader_45|1.00|1|root||time:8.26384652s,loops:1,cop_task:{num:175,max:1.955114915s,min:737.989μs,avg:603.631575ms,p95:1.161411687s,max_proc_keys:480000,p95_proc_keys:480000,tot_proc:1m44.809s,tot_wait:361ms,rpc_num:175,rpc_time:1m45.632904647s,copr_cache_hit_ratio:0.00}|index:Limit_44|6.6025390625KB|N/A|
|└─Limit_44|1.00|1|cop[tikv]||time:0ns,loops:0,tikv_task:{procmax:1.955s,min:0s,p80:784ms,p95:1.118s,iters:175,tasks:175}|offset:0,count:1|N/A|N/A|
|└─IndexFullScan_31|1.00|32|cop[tikv]|table:t0,index:time_a(time_a)|time:0ns,loops:0,tikv_task:{procmax:1.955s,min:0s,p80:784ms,p95:1.118s,iters:175,tasks:175}|keeporder:true|N/A|N/A|
+--------------------------------+---------+---------+-----------+----------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------+-----------------+------+
6rowsinset(8.38sec)
診斷分析

使用算子執(zhí)行信息進行性能診斷時，我們一般先從上到下看每個算子本身（即去除掉等待子算子數(shù)據(jù)的時間后）的執(zhí)行時間，再去尋找對整個查詢性能影響最大的算子，以下為算子執(zhí)行時間的計算方法：

單子算子的算子執(zhí)行時間

以下是不同類型算子的執(zhí)行時間計算方法：

1. 類型為 "root" 的算子

可以直接用該算子的執(zhí)行時間減去其子算子的執(zhí)行時間，得到該算子本身的處理時間。

2. 類型為 "cop[tikv]" 的算子

執(zhí)行信息中包含tikv_task統(tǒng)計項?？梢酝ㄟ^以下公式估算包含等待子算子數(shù)據(jù)的執(zhí)行時間：

估算執(zhí)行時間 = avg × tasks / concurrency

然后，再從該時間中減去子算子的執(zhí)行時間，得到該算子的實際處理時間。

3. 類型為 "mpp[tiflash]"、"cop[tiflash]" 或 "batchcop[tiflash]" 的算子

執(zhí)行信息中包含tiflash_task統(tǒng)計項。通?？梢杂胮roc max減去子算子的proc max，得到該算子的處理時間。這是因為對于 TiFlash 任務(wù)，可以簡單理解為同一條查詢的所有 TiFlash 任務(wù)是同時開始執(zhí)行的。

注意：對于ExchangeSender算子，其執(zhí)行時間包含了等待數(shù)據(jù)被上層ExchangeReceiver算子接收的時間，因此往往會大于上層ExchangeReceiver讀取內(nèi)存數(shù)據(jù)的時間。

多子算子的算子執(zhí)行時間

對于包含多個子算子的復(fù)合算子，其execution info中通常會詳細列出各個子算子的執(zhí)行信息。例如，在IndexLookUp算子的執(zhí)行信息中，會明確包含index_task和table_task的執(zhí)行細節(jié)。通過分析這些子算子的執(zhí)行信息，我們可以精準(zhǔn)判斷哪個子算子對整體性能的影響更大，從而更有針對性地進行優(yōu)化。

在這個例子中，我們可以看出IndexReader_45是對性能影響最大的關(guān)鍵算子。對比其兩次執(zhí)行信息可以發(fā)現(xiàn)，cop task的數(shù)量存在顯著差異：在“max”場景下，僅有1個cop task；而在“min”場景下，卻有175 個cop task。同時，proc_keys的數(shù)量也從32增加到了480,000。

從 "operator info" 列的標(biāo)記來看，“max”場景中讀取順序為降序（keep order, desc），即從大到小讀??；而“min”場景中則是默認的升序（keep order）。由此可以推測：優(yōu)化器根據(jù)聚合函數(shù)的類型，對索引的讀取順序進行了優(yōu)化——在“max”場景中采用降序讀取，而在“min”場景中采用升序讀取。這種優(yōu)化策略的初衷是盡快找到第一條滿足條件的數(shù)據(jù)。

在“min”場景中，最小的 keys 附近恰好存在大量已被刪除但尚未回收的 keys。因此，系統(tǒng)在讀取過程中不得不掃描大量無用數(shù)據(jù)，直到最終找到第一條有效數(shù)據(jù)，這導(dǎo)致了顯著的性能開銷。

換個日期，查詢慢了 160 倍還沒跑出來

實際案例

這是另一個客戶的實際案例：查詢12 月 20 日數(shù)據(jù)的 SQL 語句僅耗時 25 分鐘便完成，而查詢12 月 21 日數(shù)據(jù)的 SQL 語句卻運行了超過 40 小時仍未完成，最終只能手動終止。以下是這兩條 SQL 語句及其對應(yīng)的執(zhí)行信息：

【12.20日】
explainanalyzeINSERTINTOt1(col0,col1)
SELECT
str_to_date('20241219','%Y%m%d')AScol0,
count(1)
FROMt0WHERE
col0=str_to_date('20241219','%Y%m%d')
ANDcol2='1';
+-------------------------------------+-----------+-------------+-----------+-------------------------------------------------------------------------------------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------+------+
|id|task|estRows|actRows|operatorinfo|executioninfo|memory|disk|
+-------------------------------------+-----------+-------------+-----------+-------------------------------------------------------------------------------------------------------------+-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------+------+
|Insert_1|root|0|0|N/A|time:25m21.1s,loops:1,prepare:25m21.1s,insert:62.2μs,lock_keys:{time:3.28ms,region:1,keys:1,slowest_rpc:{total:0.003s,region_id:615664606,store:214.194.4.93:20160,tikv_wall_time:230.1μs},lock_rpc:2.811716ms,rpc_count:1}|29.2KB|N/A|
|└─Projection_7|root|1|1|col0->Column#209,Column#208|time:25m21.1s,loops:2,Concurrency:OFF|380Bytes|N/A|
|└─HashAgg_16|root|1|1|funcs:count(Column#215)->Column#208|time:25m21.1s,loops:2,partial_worker:{wall_time:25m21.069799539s,concurrency:5,task_num:82364,tot_wait:2h6m36.573780845s,tot_exec:8.745753026s,tot_time:2h6m45.348679761s,max:25m21.069763913s,p95:25m21.069763913s},final_worker:{wall_time:25m21.069835493s,concurrency:5,task_num:5,tot_wait:2h6m45.348923309s,tot_exec:18.591μs,tot_time:2h6m45.348944905s,max:25m21.069801614s,p95:25m21.069801614s}|260.2KB|N/A|
|└─IndexLookUp_17|root|1|84339969|N/A|time:25m19.4s,loops:82365,index_task:{total_time:25m20.7s,fetch_handle:7m18.7s,build:23.5ms,wait:18m2s},table_task:{total_time:2h6m24.2s,num:5813,concurrency:5},next:{wait_index:7.63ms,wait_table_lookup_build:5.74s,wait_table_lookup_resp:25m10.7s}|52.6MB|N/A|
|├─IndexRangeScan_13(Build)|cop[tikv]|59335552.00|118921714|table:t0,index:idx_index0(col0,col3,col4),range:[2024-12-19,2024-12-19],keeporder:false,stats:pseudo|time:1m0.5s,loops:116574,cop_task:{num:3457,max:359.8ms,min:1.13ms,avg:51.7ms,p95:121.5ms,max_proc_keys:50144,p95_proc_keys:50144,tot_proc:1m54s,tot_wait:373ms,rpc_num:3458,rpc_time:2m58.7s,copr_cache_hit_ratio:0.00,distsql_concurrency:15},backoff{regionMiss:2ms},scan_detail:{total_process_keys:118921714,total_process_keys_size:14309548264,total_keys:119003503,get_snapshot_time:635.1ms,rocksdb:{key_skipped_count:120441534,block:{cache_hit_count:212755,read_count:23658,read_byte:538.1MB,read_time:179.2ms}}}|N/A|N/A|
|└─HashAgg_9(Probe)|cop[tikv]|1|84339969|funcs:count(1)->Column#215|time:1h47m18.5s,loops:90847,cop_task:{num:91439604,max:4.05s,min:450μs,avg:2.5ms,p95:9.62ms,max_proc_keys:9094,p95_proc_keys:2,tot_proc:3m46.3s,tot_wait:1h36m3.1s,rpc_num:91439649,rpc_time:61h20m32.2s,copr_cache_hit_ratio:0.00,distsql_concurrency:15},backoff{regionMiss:86ms},scan_detail:{total_process_keys:118921714,total_process_keys_size:272099421438,total_keys:353720316,get_snapshot_time:3h23m51s,rocksdb:{delete_skipped_count:4,key_skipped_count:234799057,block:{cache_hit_count:2970751374,read_count:15457191,read_byte:268.8GB,read_time:4m11.8s}}}|N/A|N/A|
|└─Selection_15|cop[tikv]|59335.55|110035144|eq(t0.col2,"1")|tikv_task:{procmax:321ms,min:0s,avg:193.5μs,p80:0s,p95:0s,iters:91440577,tasks:91439604}|N/A|N/A|
|└─TableRowIDScan_14|cop[tikv]|59335552.00|118921714|table:t0,keeporder:false,stats:pseudo|tikv_task:{procmax:321ms,min:0s,avg:183.3μs,p80:0s,p95:0s,iters:91440577,tasks:91439604}|N/A|N/A|
+------------------------+-----------+------------+--------------------------------------------------+------------------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------+------+
【12.21日】
explainanalyzeINSERTINTOt1(col0,col1)
SELECT
str_to_date('20241220','%Y%m%d')AScol0,
count(1)
FROMt0WHERE
col0=str_to_date('20241220','%Y%m%d')
ANDcol2='1';
+-------------------------------------+-----------+-------------+-----------+-------------------------------------------------------------------------------------------------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------+------+
|id|task|estRows|actRows|operatorinfo|executioninfo|memory|disk|
+-------------------------------------+-----------+-------------+-----------+-------------------------------------------------------------------------------------------------------------+-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------+------+
|Insert_1|root|0|0|N/A|time:40h30m50.9s,loops:1|0Bytes|N/A|
|└─Projection_7|root|1|0|col0->Column#209,Column#208|time:40h30m50.9s,loops:1,Concurrency:OFF|8.24KB|N/A|
|└─HashAgg_16|root|1|0|funcs:count(Column#215)->Column#208|time:40h30m50.9s,loops:1,partial_worker:{wall_time:40h30m50.867278633s,concurrency:5,task_num:141733,tot_wait:202h33m46.814913611s,tot_exec:27.470849055s,tot_time:202h34m14.336192096s,max:40h30m50.867251785s,p95:40h30m50.867251785s},final_worker:{wall_time:40h30m50.867835193s,concurrency:5,task_num:5,tot_wait:202h34m14.336323864s,tot_exec:587.154μs,tot_time:202h34m14.336916359s,max:40h30m50.867823183s,p95:40h30m50.867823183s}|253.9KB|N/A|
|└─IndexLookUp_17|root|1|145134747|N/A|time:40h30m44.5s,loops:141734,index_task:{total_time:40h30m50.8s,fetch_handle:1h26m6.1s,build:53.4ms,wait:39h4m44.7s},table_task:{total_time:202h30m18s,num:10576,concurrency:5},next:{wait_index:38.7ms,wait_table_lookup_build:16m5.5s,wait_table_lookup_resp:35h58m38.1s}|54.1MB|N/A|
|├─IndexRangeScan_13(Build)|cop[tikv]|59418221.51|216452387|table:t0,index:idx_index0(col0,col3,col4),range:[2024-12-20,2024-12-20],keeporder:false,stats:pseudo|time:1h10m20.7s,loops:212130,cop_task:{num:6031,max:4.3s,min:1.25ms,avg:68.2ms,p95:157.5ms,max_proc_keys:50144,p95_proc_keys:50144,tot_proc:4m2.6s,tot_wait:1.72s,rpc_num:6032,rpc_time:6m51.3s,copr_cache_hit_ratio:0.00,distsql_concurrency:15},backoff{regionMiss:4.01s},tikv_task:{procmax:240ms,min:0s,avg:35ms,p80:52ms,p95:60ms,iters:235427,tasks:6031},scan_detail:{total_process_keys:216452387,total_process_keys_size:26106920846,total_keys:216513446,get_snapshot_time:1.82s,rocksdb:{key_skipped_count:217250001,block:{cache_hit_count:85194,read_count:336650,read_byte:5.71GB,read_time:2.59s}}}|N/A|N/A|
|└─HashAgg_9(Probe)|cop[tikv]|1|145183684|funcs:count(1)->Column#215|time:200h6m9.4s,loops:157469,cop_task:{num:152652462,max:5.48s,min:428.9μs,avg:3.46ms,p95:9.78ms,max_proc_keys:9041,p95_proc_keys:3,tot_proc:3h59m54.1s,tot_wait:9h5m23.6s,rpc_num:152657420,rpc_time:138h15m0.2s,copr_cache_hit_ratio:0.00,distsql_concurrency:15},backoff{regionMiss:5.94s},tikv_task:{procmax:468ms,min:0s,avg:494.8μs,p80:0s,p95:4ms,iters:152653501,tasks:152652462},scan_detail:{total_process_keys:216364520,total_process_keys_size:340485612010,total_keys:490792535,get_snapshot_time:12h12m26.1s,rocksdb:{delete_skipped_count:1944,key_skipped_count:274430096,block:{cache_hit_count:5855418083,read_count:285117868,read_byte:4977.3GB,read_time:4h18m23.9s}}}|N/A|N/A|
|└─Selection_15|cop[tikv]|59418.22|207051411|eq(t0.col2,"1")|tikv_task:{procmax:1.3s,min:0s,avg:489.8μs,p80:0s,p95:4ms,iters:152653501,tasks:152652462}|N/A|N/A|
|└─TableRowIDScan_14|cop[tikv]|59418221.51|232766720|table:t0,keeporder:false,stats:pseudo|tikv_task:{procmax:1.3s,min:0s,avg:478.8μs,p80:0s,p95:4ms,iters:152653501,tasks:152652462}|N/A|N/A|
+------------------------+-----------+------------+--------------------------------------------------+------------------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------+------+
診斷分析

首先對比兩次查詢的執(zhí)行計劃，確認執(zhí)行計劃未發(fā)生跳變。接著，我們從上至下逐一分析，找出兩次查詢中主要執(zhí)行時間差異的來源?？梢钥吹?，Insert_1、Projection_7 和HashAgg_16的執(zhí)行時間均在秒級，因此可以排除這些算子的嫌疑。

重點聚焦于IndexLookUp算子。在 12 月 21 日的查詢中，index_task的總耗時為 40 小時，但實際獲取 rowid 的時間僅為 1 個多小時，其余時間主要消耗在等待table_task讀取表數(shù)據(jù)上，具體為wait：39h4m44.7s。

進一步查看table_task的執(zhí)行細節(jié)，以下兩個信息值得關(guān)注：total_time：202h30m18s 和concurrency：5。計算可得，平均每個并發(fā)任務(wù)的耗時為202h / 5 = 40.4h，與IndexLookUp的總耗時基本一致。因此，基本可以確定問題出在table_task上，即對應(yīng)的HashAgg_9算子。

在HashAgg_9算子的execution info中，主要包含以下關(guān)鍵信息：

time: 200h6m9.4s, loops: 157469"cop[tikv]"TiKV walltime5walltime200h / 5 = 40htotal_timewalltime：該算子的任務(wù)類型為，表明其實際在上執(zhí)行。這里的執(zhí)行時間反映了 TiDB 等待和讀取 Coprocessor 任務(wù)返回數(shù)據(jù)的總耗時。需要注意的是，這個時間并不是實際的，而是多個并發(fā)任務(wù)的執(zhí)行時間累加而成。由于 table_task 的并發(fā)度為，因此實際算子的大約為，與總耗時一致。從 TiDB 9.0 版本開始，我們將這種并發(fā)執(zhí)行時間的統(tǒng)計項名稱改為，以便與真正的區(qū)分開來。
cop_task: 此部分信息描述了向 TiKV 發(fā)送cop task的執(zhí)行情況。其中，rpc_timedistsql_concurrency是兩個關(guān)鍵指標(biāo)：
rpc_time是 TiDB 端記錄的從發(fā)送cop task到接收結(jié)果的總耗時。
distsql_concurrency是單個table_task發(fā)送cop_task的并發(fā)度。由于table_task的并發(fā)度為5，因此整體的cop task并發(fā)度為5 × 15 = 75

根據(jù)這兩個指標(biāo)，我們可以推算出cop task的實際walltime大約為138h / 75 ≈ 1.8h，與整體的40h相比，占比并不高。

backoff：這部分描述了 cop task 發(fā)送失敗時重試的時間。
tikv_task：這部分是描述的 HashAgg_9 這個算子在 TiKV 上的執(zhí)行信息，實際時間并不多。
scan_detail：描述了 TiKV 從 RocksDB 讀取數(shù)據(jù)的信息統(tǒng)計，由于 tikv_task 推算出算子總執(zhí)行時間并不長，所以這部分信息不影響總體性能。

綜合上述信息可以發(fā)現(xiàn)， HashAgg_9的總執(zhí)行時間并非主要消耗在cop task的執(zhí)行上，而更可能是花費在從cop task response中讀取數(shù)據(jù)的過程中。結(jié)合 CPU profiling 的結(jié)果，可以看到 Go runtime 的 GC（垃圾回收）占用了大約80%的 CPU 時間。

進一步觀察heap profiling的結(jié)果，可以最終確認問題根源是 issue44047 (https://github.com/pingcap/tidb/issues/44047)：此前，TiDB 為了精確統(tǒng)計cop task的 p90 等指標(biāo)，會緩存所有cop task的執(zhí)行信息。當(dāng)cop task數(shù)量極為龐大時，這會導(dǎo)致 TiDB 內(nèi)存緊張，進而頻繁觸發(fā) Go 的 GC（垃圾回收），最終引發(fā)性能異常。該問題已經(jīng)在 TiDB 6.5 版本中修復(fù)。

在 TiDB 9.0 版本中，我們將進一步豐富算子執(zhí)行信息，提升系統(tǒng)的可觀測性，具體改進包括：

1. 算子執(zhí)行時間的細化

在 9.0 版本中，TiDB 算子的執(zhí)行信息新增了open和close時間。此前，執(zhí)行信息中的time并未涵蓋算子初始化和結(jié)束執(zhí)行的時間，這可能導(dǎo)致執(zhí)行時間顯著低于實際耗時（如 issue50377 (https://github.com/pingcap/tidb/issues/50377) 和 issue55957 (https://github.com/pingcap/tidb/issues/55957)）。在 9.0 版本中，time被修正為從進入算子到離開算子的完整wall time，包括所有子算子的執(zhí)行時間。其中：

open：表示算子初始化所需的時間。
close：表示從算子處理完所有數(shù)據(jù)到完全結(jié)束的時間。
time包含了openclose的時間。

2. 并發(fā)執(zhí)行時間的區(qū)分

當(dāng)算子存在多并發(fā)執(zhí)行時，此前的execution info中顯示的是并發(fā)任務(wù)的wall time累加值，這可能導(dǎo)致子算子的執(zhí)行時間大于父算子的執(zhí)行時間（如 issue56746 (https://github.com/pingcap/tidb/issues/56746)），容易引起混淆。在 9.0 版本中，這些累加的時間信息（如time、open和close）將被替換為total_time、total_open和total_close，以更清晰地反映并發(fā)執(zhí)行的真實耗時。

3. TiFlash 執(zhí)行中的等待時間信息補充

在 TiFlash 的執(zhí)行信息中，新增了以下等待時間的統(tǒng)計：

minTSO_wait：記錄 MPP Task 等待 TiFlash MinTSO 調(diào)度器調(diào)度的時間。
pipeline_breaker_wait：在 TiFlash 的 Pipeline 執(zhí)行模型中，記錄包含 pipeline breaker 算子的 pipeline 等待上游 pipeline 數(shù)據(jù)的時間。目前主要用于展示包含 Join 算子的 pipeline 等待哈希表構(gòu)建完成的時間。
pipeline_queue_wait：在 TiFlash 的 Pipeline 執(zhí)行模型中，記錄 pipeline 在 CPU Task Thread Pool 和 IO Task Thread Pool 中的等待時間。

通過這些改進，TiDB 9.0 版本將為用戶提供更全面、更準(zhǔn)確的執(zhí)行信息，幫助更好地診斷和優(yōu)化查詢性能。