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

語言: CN / TW / HK

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

免費試用 TiDB Cloud
適用於中國出海企業和開發者

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: [email protected]
# 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:false
plan_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(*)           | 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

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 (4, 5);

規一化為

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

1.png

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

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

1.SQL 執行總時長

2.平均影響行數(一般是寫入)

3.平均掃描行數(一般是讀)

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

2.png

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_sizemax-stmt-countmax-sql-length幾項配置影響記憶體佔用,建議根據實際情況調整,不宜設定得過大。

綜上所述,視覺化 Statements 可以快速定位某個 SQL 效能問題。

本文為「TiDB 查詢優化及調優」系列文章的第三篇,前文我們分別介紹了 優化器的基本概念  TiDB 的查詢計劃 ,後續將繼續對 TiDB 調整及優化查詢執行計劃、其他優化器開發或規劃中的診斷調優功能等進行介紹。 如果您對 TiDB 的產品有任何建議,歡迎來到 internals.tidb.io 與我們交流。