TiDB 查詢優化及調優系列（三）慢查詢診斷監控及排查
本章節介紹如何利用 TiDB 提供的系統監控診斷工具，對執行負載中的查詢進行排查和診斷。除了 上一章節介紹的通過 EXPLAIN 語句來檢視診斷查詢計劃問題 外，本章節主要會介紹通過 TiDB Slow Query 慢查詢記憶體表，以及 TiDB Dashboard 的視覺化 Statements 功能來監控和診斷慢查詢。
1.Slow Query 慢查詢記憶體表
TiDB 預設會啟用慢查詢日誌，並將執行時間超過規定閾值的 SQL 儲存到日誌檔案。慢查詢日誌常用於定位慢查詢語句，分析和解決 SQL 的效能問題。通過系統表 information_schema.slow_query 也可以檢視當前 TiDB 節點的慢查詢日誌，其欄位與慢查詢日誌檔案內容一致。TiDB 從 4.0 版本開始又新增了系統表 information_schema.cluster_slow_query ，可以用於檢視全部 TiDB 節點的慢查詢。
本節將首先簡要介紹慢查詢日誌的格式和欄位含義，然後針對上述兩種慢查詢系統表給出一些常見的查詢示例。
慢查詢日誌示例及欄位說明
下面是一段典型的慢查詢日誌：
# Time: 2019-08-14 T09: 26 : 59.487776265 + 08 : 00
# Txn_start_ts: 410450924122144769
# User: [email protected] 127.0.0.1
# Conn_ID: 3086
# Query_time: 1.527627037
# Parse_time: 0.000054933
# Compile_time: 0.000129729
# Process_time: 0.07 Wait_time: 0.002 Backoff_time: 0.002 Request_count: 1 Total_keys: 131073 Process_keys: 131072 Prewrite_time: 0.335415029 Commit_time: 0.032175429 Get_commit_ts_time: 0.000177098 Local_latch_wait_time: 0.106869448 Write_keys: 131072 Write_size: 3538944 Prewrite_region: 1
# DB: test
# Is_internal: false
# Digest: 50 a2e32d2abbd6c1764b1b7f2058d428ef2712b029282b776beb9506a365c0f1
# Stats: t: 414652072816803841
# Num_cop_tasks: 1
# Cop_proc_avg: 0.07 Cop_proc_p90: 0.07 Cop_proc_max: 0.07 Cop_proc_addr: 172.16.5.87 : 20171
# Cop_wait_avg: 0 Cop_wait_p90: 0 Cop_wait_max: 0 Cop_wait_addr: 172.16.5.87 : 20171
# Mem_max: 525211
# Succ: true
# Plan_digest: e5f9d9746c756438a13c75ba3eedf601eecf555cdb7ad327d7092bdd041a83e7
# Plan: tidb_decode_plan( 'ZJAwCTMyXzcJMAkyMAlkYXRhOlRhYmxlU2Nhbl82CjEJMTBfNgkxAR0AdAEY1Dp0LCByYW5nZTpbLWluZiwraW5mXSwga2VlcCBvcmRlcjpmYWxzZSwgc3RhdHM6cHNldWRvCg==' )
select
* from t;
以下逐一介紹慢查詢日誌中各個欄位的含義。
注意：慢查詢日誌中所有時間相關欄位的單位都是秒。
(1) 慢查詢基礎資訊：
· Time ：表示日誌列印時間。
· Query_time ：表示執行該語句花費的時間。
· Parse_time ：表示該語句在語法解析階段花費的時間。
· Compile_time ：表示該語句在查詢優化階段花費的時間。
· Digest ：表示該語句的 SQL 指紋。
· Stats ：表示 table 使用的統計資訊版本時間戳。如果時間戳顯示為 pseudo ，表示用預設假設的統計資訊。
· Txn_start_ts ：表示事務的開始時間戳，也就是事務的唯一 ID，可以用該值在 TiDB 日誌中查詢事務相關的其他日誌。
· Is_internal ：表示是否為 TiDB 內部的 SQL 語句。 true 表示是 TiDB 系統內部執行的 SQL 語句， false 表示是由使用者執行的 SQL 語句。
· Index_ids ：表示該語句使用的索引 ID。
· Succ ：表示該語句是否執行成功。
· Backoff_time ：表示遇到需要重試的錯誤時該語句在重試前等待的時間。常見的需要重試的錯誤有以下幾種：遇到了 lock 、 Region 分裂、 tikv server is busy 。
· Plan_digest ：表示 plan 的指紋。
· Plan ：表示該語句的執行計劃，執行 select tidb_decode_plan('...') 可以解析出具體的執行計劃。
· Query ：表示該 SQL 語句。慢日誌裡不會列印欄位名 Query ，但對映到記憶體表後對應的欄位叫 Query 。
(2) 和事務執行相關的欄位：
· Prewrite_time ：表示事務兩階段提交中第一階段（ prewrite 階段）的耗時。
· Commit_time ：表示事務兩階段提交中第二階段（ commit 階段）的耗時。
· Get_commit_ts_time ：表示事務兩階段提交中第二階段（ commit 階段）獲取 commit 時間戳的耗時。
· Local_latch_wait_time ：表示事務兩階段提交中第二階段（ commit 階段）發起前在 TiDB 側等鎖的耗時。
· Write_keys ：表示該事務向 TiKV 的 Write CF 寫入 Key 的數量。
· Write_size ：表示事務提交時寫 key 和 value 的總大小。
· Prewrite_region ：表示事務兩階段提交中第一階段（ prewrite 階段）涉及的 TiKV Region 數量。每個 Region 會觸發一次遠端過程呼叫。
(3) 和記憶體使用相關的欄位：
· Memory_max ：表示執行期間 TiDB 使用的最大記憶體空間，單位為 byte。
(4) 和使用者相關的欄位：
· User ：表示執行語句的使用者名稱。
· Conn_ID ：表示使用者的連線 ID，可以用類似 con:3 的關鍵字在 TiDB 日誌中查詢該連結相關的其他日誌。
· DB ：表示執行語句時使用的 database。
(5) 和 TiKV Coprocessor Task 相關的欄位：
· Process_time ：該 SQL 在 TiKV 上的處理時間之和。因為資料會並行發到 TiKV 執行，該值可能會超過 Query_time 。
· Wait_time ：表示該語句在 TiKV 上的等待時間之和。因為 TiKV 的 Coprocessor 執行緒數是有限的，當所有的 Coprocessor 執行緒都在工作的時候，請求會排隊；若佇列中部分請求耗時很長，後面的請求的等待時間會增加。
· Request_count ：表示該語句傳送的 Coprocessor 請求的數量。
· Total_keys ：表示 Coprocessor 掃過的 key 的數量。
· Process_keys ：表示 Coprocessor 處理的 key 的數量。相較於 total_keys ， processed_keys 不包含 MVCC 的舊版本。如果 processed_keys 和 total_keys 相差很大，說明舊版本比較多。
· Cop_proc_avg ：cop-task 的平均執行時間。
· Cop_proc_p90 ：cop-task 的 P90 分位執行時間。
· Cop_proc_max ：cop-task 的最大執行時間。
· Cop_proc_addr ：執行時間最長的 cop-task 所在地址。
· Cop_wait_avg ：cop-task 的平均等待時間。
· Cop_wait_p90 ：cop-task 的 P90 分位等待時間。
· Cop_wait_max ：cop-task 的最大等待時間。
· Cop_wait_addr ：等待時間最長的 cop-task 所在地址。
Slow Query 記憶體表使用排查
下面通過一些示例展示如何通過 SQL 檢視 TiDB 的慢查詢。
檢索當前節點 Top N 慢查詢
以下 SQL 用於檢索當前TiDB節點的 Top 2 慢查詢：
> select query_time, query
from information_schema.slow_query -- 檢索當前 TiDB 節點的慢查詢
where is_internal = false -- 排除 TiDB 內部的慢查詢
order by query_time desc
limit 2 ;
+ --------------+------------------------------------------------------------------+
| query_time | query |
+ --------------+------------------------------------------------------------------+
| 12.77583857 | select * from t_slim, t_wide where t_slim.c0=t_wide.c0; |
| 0.734982725 | select t0.c0, t1.c1 from t_slim t0, t_wide t1 where t0.c0=t1.c0; |
--------------+------------------------------------------------------------------+
檢索全部節點上指定使用者的 Top N 慢查詢
以下 SQL 會檢索全部 TiDB 節點上指定使用者 test 的 Top 2 慢查詢：
> select query_time, query , user
from information_schema.cluster_slow_query -- 檢索全部 TiDB 節點的慢查詢
where is_internal = false
and user = "test"
order by query_time desc
limit 2 ;
+ -------------+------------------------------------------------------------------+----------------+
| Query_time | query | user |
+ -------------+------------------------------------------------------------------+----------------+
| 0.676408014 | select t0.c0, t1.c1 from t_slim t0, t_wide t1 where t0.c0=t1.c1; | test |
+ -------------+------------------------------------------------------------------+----------------+
檢索同類慢查詢
在得到 Top N 慢查詢後，可通過 SQL 指紋繼續檢索同類慢查詢。
-- 先獲取 Top N 的慢查詢和對應的 SQL 指紋
> select query_time, query , digest
from information_schema.cluster_slow_query
where is_internal = false
order by query_time desc
limit 1 ;
+ -------------+-----------------------------+------------------------------------------------------------------+
| query_time | query | digest |
+ -------------+-----------------------------+------------------------------------------------------------------+
| 0.302558006 | select * from t1 where a= 1 ; | 4751cb6008fda383e22dacb601fde85425dc8f8cf669338d55d944bafb46a6fa |
+ -------------+-----------------------------+------------------------------------------------------------------+
-- 再根據 SQL 指紋檢索同類慢查詢
> select query , query_time
from information_schema.cluster_slow_query
where digest = "4751cb6008fda383e22dacb601fde85425dc8f8cf669338d55d944bafb46a6fa" ;
+ -----------------------------+-------------+
| query | query_time |
+ -----------------------------+-------------+
| select * from t1 where a= 1 ; | 0.302558006 |
| select * from t1 where a= 2 ; | 0.401313532 |
+ -----------------------------+-------------+
檢索統計資訊為 pseudo 的慢查詢
如果慢查詢日誌中的統計資訊被標記為 pseudo ，往往說明 TiDB 表的統計資訊更新不及時，需要執行 analyze table 手動收集統計資訊。以下 SQL 可以找到這一類慢查詢：
> select query , query_time, stats
from information_schema.cluster_slow_query
where is_internal = false
and stats like '%pseudo%' ;
+ -----------------------------+-------------+---------------------------------+
| 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 |
+ -----------------------------+-------------+---------------------------------+
查詢執行計劃發生變化的慢查詢
由於統計資訊不準，可能導致同類型 SQL 的執行計劃發生意料之外的改變。用以下 SQL 可以檢索到哪些慢查詢具有多種不同的執行計劃：
> select count ( distinct plan_digest) as count , digest, min ( query )
from information_schema.cluster_slow_query
group by digest
having count > 1
limit 3 \G
***************************[ 1. row ]***************************
count | 2
digest | 17 b4518fde82e32021877878bec2bb309619d384fca944106fcaf9c93b536e94
min ( query ) | SELECT DISTINCT c FROM sbtest25 WHERE id BETWEEN ? AND ? ORDER BY c [arguments: ( 291638 , 291737 )];
***************************[ 2. row ]***************************
count | 2
digest | 9337865f3e2ee71c1c2e740e773b6dd85f23ad00f8fa1f11a795e62e15fc9b23
min(query) | SELECT DISTINCT c FROM sbtest22 WHERE id BETWEEN ? AND ? ORDER BY c [arguments: ( 215420 , 215519 )];
***************************[ 3. row ]***************************
count | 2
digest | db705c89ca2dfc1d39d10e0f30f285cbbadec7e24da4f15af461b148d8ffb020
min(query) | SELECT DISTINCT c FROM sbtest11 WHERE id BETWEEN ? AND ? ORDER BY c [arguments: ( 303359303458
)];
-- 藉助 SQL 指紋進一步查詢執行計劃的詳細資訊
> select min (plan),plan_digest
from information_schema.cluster_slow_query
where digest= '17b4518fde82e32021877878bec2bb309619d384fca944106fcaf9c93b536e94'
group by plan_digest\G
*************************** 1. row ***************************
min (plan): Sort_6 root 100.00131380758702 sbtest.sbtest25.c: asc
└─HashAgg_10 root 100.00131380758702 group by :sbtest.sbtest25.c, funcs:firstrow(sbtest.sbtest25.c)->sbtest.sbtest25.c
└─TableReader_15 root 100.00131380758702 data :TableRangeScan_14
└─TableScan_14 cop 100.00131380758702 table :sbtest25, range :[ 502791 , 502890 ], keep order : false
plan_digest: 6 afbbd21f60ca6c6fdf3d3cd94f7c7a49dd93c00fcf8774646da492e50e204ee
*************************** 2. row ***************************
min (plan): Sort_6 root 1 sbtest.sbtest25.c: asc
└─HashAgg_12 root 1 group by :sbtest.sbtest25.c, funcs:firstrow(sbtest.sbtest25.c)->sbtest.sbtest25.c
└─TableReader_13 root 1 data :HashAgg_8
└─HashAgg_8 cop 1 group by :sbtest.sbtest25.c,
└─TableScan_11 cop 1.2440069558121831 table :sbtest25, range :[ 472745 , 472844 ], keep orderfalse
統計各個節點的慢查詢數量
以下 SQL 統計指定時段內各個 TiDB 節點上出現過的慢查詢數量：
> select instance , count (*)
from information_schema.cluster_slow_query
where time >= "2020-03-06 00:00:00"
and time < now ()
group by instance ;
+ ---------------+----------+
| instance | count(*) |
+ ---------------+----------+
| 0.0.0.0:10081 | 124 |
| 0.0.0.0:10080 | 119771 |
---------------+----------+
檢索異常時段的慢查詢
假定 2020-03-10 13:24:00 至 2020-03-10 13:27:00 期間發現 QPS 降低和查詢響應時間升高等問題，可以用以下 SQL 過濾出僅僅出現在異常時段的慢查詢：
> select * from
( select /*+ AGG_TO_COP(), HASH_AGG() */ count (*),
min ( time ),
sum (query_time) AS sum_query_time,
sum (Process_time) AS sum_process_time,
sum (Wait_time) AS sum_wait_time,
sum (Commit_time),
sum (Request_count),
sum (process_keys),
sum (Write_keys),
max (Cop_proc_max),
min ( query ), min (prev_stmt),
digest
from information_schema.cluster_slow_query
where time >= '2020-03-10 13:24:00'
and time < '2020-03-10 13:27:00'
adn Is_internal = false
group by digest) AS t1
where t1.digest not in
( select /*+ AGG_TO_COP(), HASH_AGG() */ digest
from information_schema.cluster_slow_query
where time >= '2020-03-10 13:20:00' -- 排除正常時段 `2020-03-10 13:20:00` ~ `2020-03-10 13:23:00` 期間的慢查詢
and time < '2020-03-10 13:23:00'
group by digest)
order by t1.sum_query_time desc
limit 10 \G
***************************[ 1. row ]***************************
count (*) | 200
min ( time ) | 2020-03-10 13 : 24 : 27.216186
sum_query_time | 50.114126194
sum_process_time | 268.351
sum_wait_time | 8.476
sum (Commit_time) | 1.044304306
sum (Request_count) | 6077
sum (process_keys) | 202871950
sum (Write_keys) | 319500
max (Cop_proc_max) | 0.263
min ( query ) | delete from test.tcs2 limit 5000 ;
min(prev_stmt) |
digest | 24bd6d8a9b238086c9b8c3d240ad4ef32f79ce94cf5a468c0b8fe1eb5f8d03df
2.TiDB Dashboard 視覺化 Statements
上一節介紹了利用 Slow Query 記憶體表來排查慢查詢，但 Slow Query 只會記錄超過慢日誌閾值的SQL 而缺少對全部執行負載的診斷排查。本節會介紹通過使用 TiDB Dashboard 來排查定位問題查詢。TiDB Dashboard 提供了 Statements 用來監控和統計 SQL，例如頁面上提供了豐富的列表資訊，包括延遲、執行次數、掃描行數、全表掃描次數等，用來分析哪些類別的 SQL 語句耗時過長、消耗記憶體過多等情況，幫助使用者定位效能問題。
TiDB 已支援多種效能排查工具。但在多種應用場景需求下，仍有不足，例如：
1. Grafana 不能排查單條 SQL 的效能問題
2. Slow log 只記錄超過慢日誌閥值的 SQL
3. General log 本身對效能有一定影響
4. Explain analyze 只能檢視可以復現的問題
5. Profile 只能檢視整個例項的瓶頸
因此推出視覺化 Statements，可以直接在頁面觀察 SQL 執行情況，不需要查詢系統表，便於使用者定位效能問題。
使用 TiDB Dashboard
從4.0版本開始，TiDB 提供了一個新的 Dashboard 運維管理工具，整合在 PD 元件上，預設地址為 http://pd-url:pd_port/dashboard 。不同於 Grafana 監控是從資料庫的監控視角出發，TiDB Dashboard 從 DBA 管理員角度出發，最大限度的簡化管理員對 TiDB 資料庫的運維，可在一個介面檢視到整個分散式資料庫叢集的執行狀況，包括資料熱點、SQL 執行情況、叢集資訊、日誌搜尋、實時效能分析等。
檢視 Statements 整體情況
登入後，在左側點選「SQL 語句分析」即可進入此功能頁面。
在時間區間選項框中選擇要分析的時間段，即可得到該時段所有資料庫的 SQL 語句執行統計情況。
如果只關心某些資料庫，則可以在第二個選項框中選擇相應的資料庫對結果進行過濾，支援多選。
結果以表格的形式展示，並支援按不同的列對結果進行排序，如下圖所示。
1. 選擇需要分析的時間段
2. 支援按資料庫過濾
3. 支援按不同的指標排序
注意：這裡所指的 SQL 語句實際指的是某一類 SQL 語句。語法一致的 SQL 語句會規一化為一類相同的 SQL 語句。
例如：
SELECT * FROM employee WHERE id IN ( 1 , 2 , 3 );
select * from EMPLOYEE where ID in ( 45
);
規一化為
select * from employee where id in (...);
在 SQL 類別列，點選某類 SQL 語句，可以進入該 SQL 語句的詳情頁檢視更詳細的資訊，以及該 SQL 語句在不同節點上執行的統計情況。
單個 Statements 詳情頁關鍵資訊如下圖所示。
1. SQL 執行總時長
2. 平均影響行數（一般是寫入）
3. 平均掃描行數（一般是讀）
4. 各個節點執行指標（可以快速定位出某個節點效能瓶頸）
Statements 引數配置
· tidb_enable_stmt_summary
Statements 功能預設開啟，也可以通過設定系統變數開啟，例如：
set global tidb_enable_stmt_summary = true ;
· tidb_stmt_summary_refresh_interval
設定 performance_schema.events_statements_summary_by_digest 表的的清空週期，單位是秒 (s)，預設值是 1800，例如：
set global tidb_stmt_summary_refresh_interval = 1800 ;
· tidb_stmt_summary_history_size
設定 performance_schema.events_statements_summary_by_digest_history 表儲存每種 SQL 的歷史的數量，預設值是 24，例如：
set global tidb_stmt_summary_history_size = 24 ;
由於 Statements 資訊是儲存在記憶體表中，為了防止記憶體溢位等問題，需要限制儲存的 SQL 條數和 SQL 的最大顯示長度。這兩個引數需要在 config.toml 的 [stmt-summary] 類別下配置：
· 通過 max-stmt-count 更改儲存的 SQL 種類數量，預設 200 條。當 SQL 種類超過 max-stmt-count 時，會移除最近沒有使用的 SQL
· 通過 max-sql-length 更改 DIGEST_TEXT 和 QUERY_SAMPLE_TEXT 的最大顯示長度，預設是 4096
注意： tidb_stmt_summary_history_size 、 max-stmt-count 、 max-sql-length 幾項配置影響記憶體佔用，建議根據實際情況調整，不宜設定得過大。
綜上所述，視覺化 Statements 可以快速定位某個 SQL 效能問題。
本文為「TiDB 查詢優化及調優」系列文章的第三篇，前文我們分別介紹了優化器的基本概念和 TiDB 的查詢計劃，後續將繼續對 TiDB 調整及優化查詢執行計劃、其他優化器開發或規劃中的診斷調優功能等進行介紹。
如果您對 TiDB 的產品有任何建議，歡迎來到 internals.tidb.io 與我們交流。
:bulb: Tip：上文標藍部分均有跳轉，由於微信外鏈限制，大家可以點選尾部 【閱讀原文】 檢視原文～ 
- TiDB 6.5 新特性解析丨過去一年，我們是如何讓 TiFlash 高效又穩定地榨乾 CPU？
- TiDB 在安信證券資產中心與極速交易場景的實踐
- 微眾銀行 TiDB HTAP 和自動化運維實踐
- PingCAP 副總裁劉松 ：“ Serverless 化” 即將成為資料庫的下一個變革性技術
- TiCDC 原始碼閱讀（四）TiCDC Scheduler 工作原理解析
- Hackathon 實用指南丨快速給 TiDB 新增一個功能
- Hackathon idea 清單出爐，總有一款適合你
- TiDB Hackathon 2022丨總獎金池超 35 萬！邀你喚醒程式碼世界的更多可能性！
- 劉奇：能否掌控複雜性，決定著分散式資料庫的生死存亡
- TiFlash 原始碼閱讀（九）TiFlash 中常用運算元的設計與實現
- TiFlash 原始碼閱讀（八）TiFlash 表示式的實現與設計
- 如何在 TiDB Cloud 上使用 Databricks 進行資料分析 | TiDB Cloud 使用指南
- TiFlash 原始碼閱讀（五） DeltaTree 儲存引擎設計及實現分析 - Part 2
- 深入解析 TiFlash丨面向編譯器的自動向量化加速
- TiFlash 原始碼閱讀（四）TiFlash DDL 模組設計及實現分析
- TiDB v6.0.0 (DMR) ：快取表初試丨TiDB Book Rush
- TiFlash 函式下推必知必會丨十分鐘成為 TiFlash Contributor
- TiDB 6.0 實戰分享丨記憶體悲觀鎖原理淺析與實踐
- TiDB 6.1 發版：LTS 版本來了
- TiDB 6.0 實戰分享丨冷熱儲存分離解決方案