本章節介紹如何利用 TiDB 提供的系統監控診斷工具，對執行負載中的查詢進行排查和診斷。除了上一章節介紹的通過 EXPLAIN 語句來檢視診斷查詢計劃問題外，本章節主要會介紹通過 TiDB Slow Query 慢查詢記憶體表，以及 TiDB Dashboard 的視覺化 Statements 功能來監控和診斷慢查詢。

適用於中國出海企業和開發者

Slow Query 慢查詢記憶體表

TiDB 預設會啟用慢查詢日誌，並將執行時間超過規定閾值的 SQL 儲存到日誌檔案。慢查詢日誌常用於定位慢查詢語句，分析和解決 SQL 的效能問題。通過系統表 information_schema.slow_query也可以檢視當前 TiDB 節點的慢查詢日誌，其欄位與慢查詢日誌檔案內容一致。TiDB 從 4.0 版本開始又新增了系統表 information_schema.cluster_slow_query，可以用於檢視全部 TiDB 節點的慢查詢。

本節將首先簡要介紹慢查詢日誌的格式和欄位含義，然後針對上述兩種慢查詢系統表給出一些常見的查詢示例。

慢查詢日誌示例及欄位說明

下面是一段典型的慢查詢日誌：

# Time: 2019-08-14T09:26:59.487776265+08:00# Txn_start_ts: 410450924122144769# User: root@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: 50a2e32d2abbd6c1764b1b7f2058d428ef2712b029282b776beb9506a365c0f1# 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==')insert into t 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 可以找到這一類慢查詢：

如果慢查詢日誌中的統計資訊被標記為 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     | 17b4518fde82e32021877878bec2bb309619d384fca944106fcaf9c93b536e94
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: (303359, 303458)];

-- 藉助 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:falseplan_digest: 6afbbd21f60ca6c6fdf3d3cd94f7c7a49dd93c00fcf8774646da492e50e204ee
*************************** 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 order:false

統計各個節點的慢查詢數量

以下 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(*)           | 200min(time)          | 2020-03-10 13:24:27.216186sum_query_time     | 50.114126194sum_process_time   | 268.351sum_wait_time      | 8.476sum(Commit_time)   | 1.044304306sum(Request_count) | 6077sum(process_keys)  | 202871950sum(Write_keys)    | 319500max(Cop_proc_max)  | 0.263min(query)         | delete from test.tcs2 limit 5000;
min(prev_stmt)     |
digest             | 24bd6d8a9b238086c9b8c3d240ad4ef32f79ce94cf5a468c0b8fe1eb5f8d03df

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 元件上，預設地址為。不同於 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 (4, 5);

規一化為

select * from employee where id in (...);

在 SQL 類別列，點選某類 SQL 語句，可以進入該 SQL 語句的詳情頁檢視更詳細的資訊，以及該 SQL 語句在不同節點上執行的統計情況。

單個 Statements 詳情頁關鍵資訊如下圖所示。

1.SQL 執行總時長

2.平均影響行數（一般是寫入）

3.平均掃描行數（一般是讀）

4.各個節點執行指標（可以快速定位出某個節點效能瓶頸）

Statements 引數配置

tidb_enable_stmt_summaryStatements 功能預設開啟，也可以通過設定系統變數開啟，例如：

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 與我們交流。

TiDB 查詢優化及調優系列（三）慢查詢診斷監控及排查