TiDB 會將執行時間超過slow-threshold（默認值為300 毫秒）的語句輸出到slow-query-file（默認值：”tidb-slow.log”）日志文件中，用于幫助用戶定位慢查詢語句，分析和解決SQL 執行的性能問題。

慢查詢日志位置

通過命令showvariables like ‘%slow%’; 查看當前slowlog位置

慢查詢日志格式解析

Slow Query 基礎信息：

Time：表示日志打印時間。

Query_time：表示執行這個語句花費的時間。

Query：表示SQL 語句。慢日志里面不會打印Query，但映射到內存表后，對應的字段叫Query。

Digest：表示SQL 語句的指紋。

Txn_start_ts：表示事務的開始時間戳，也是事務的唯一ID，可以用這個值在TiDB 日志中查找事務相關的其他日志。

Is_internal：表示是否為TiDB 內部的SQL 語句。true表示 TiDB系統內部執行的 SQL語句，false表示用戶執行的 SQL語句。

Index_ids：表示語句涉及到的索引的ID。

Succ：表示語句是否執行成功。

Backoff_time：表示語句遇到需要重試的錯誤時在重試前等待的時間，常見的需要重試的錯誤有以下幾種：遇到了lock、Region分裂、tikvserver is busy。

和內存使用相關的字段

Memory_max：表示執行期間TiDB 使用的最大內存空間，單位為byte。

和SQL 執行的用戶相關的字段：

User：表示執行語句的用戶名。

Conn_ID：表示用戶的鏈接ID，可以用類似con:3 的關鍵字在TiDB 日志中查找該鏈接相關的其他日志。

DB：表示執行語句時使用的database。

和TiKV Coprocessor Task 相關的字段：

Request_count：表示這個語句發送的Coprocessor 請求的數量。

Total_keys：表示Coprocessor 掃過的key 的數量。

Process_time：執行SQL 在 TiKV的處理時間之和，因為數據會并行的發到TiKV 執行，這個值可能會超過Query_time。

Wait_time：表示這個語句在TiKV 的等待時間之和，因為TiKV 的Coprocessor 線程數是有限的，當所有的Coprocessor線程都在工作的時候，請求會排隊；當隊列中有某些請求耗時很長的時候，后面的請求的等待時間都會增加。

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 所在地址。

通過在sql命令窗口查看慢查詢語句

搜索Top N 的慢查詢

select query_time,query

frominformation_schema.slow_query

where is_internal =false  -- 排除 TiDB內部的慢查詢 SQL

order by query_timedesc

limit 2;

時間單位為秒

這是之前測試數據時，執行的插入語句，被tidb判斷為慢查詢，因為沒有索引

搜索某個用戶的Top N 慢查詢

select query_time,query, user

frominformation_schema.slow_query

where is_internal =false  -- 排除 TiDB內部的慢查詢 SQL

and user = "test"       -- 查找的用戶名

order by query_timedesc

limit 2;

根據SQL 指紋搜索同類慢查詢

先根據topn查詢到digest值，再查詢指紋值

select query_time,query, digest

frominformation_schema.slow_query

where is_internal =false

order by query_timedesc

limit 1;

select query,query_time

frominformation_schema.slow_query

where digest ="31a61be6ba3e5a51b26372ba82e6cdc7b517e73630af5937ad7b607500375aac";

搜索統計信息為pseudo 的慢查詢SQL 語句

select query,query_time, stats

frominformation_schema.slow_query

where is_internal =false

and stats like%pseudo%;

跟MySQL一樣，使用pt-query-digest查看tidb的慢日志同樣可以分析慢查詢

pt-query-digest/data/deploy/log/tidb_slow_query.log

pt-query-digest輸出結果分析

第一部分：總體統計結果

Overall：總共有多少條查詢

Time range：查詢執行的時間范圍

unique：唯一查詢數量，即對查詢條件進行參數化以后，總共有多少個不同的查詢

total：總計  min：最小  max：最大 avg：平均

95%：把所有值從小到大排列，位置位于95%的那個數，這個數一般最具有參考價值

median：中位數，把所有值從小到大排列，位置位于中間那個數

第二部分：查詢分組統計結果

Rank：所有語句的排名，默認按查詢時間降序排列，通過--order-by指定

QueryID：語句的ID，（去掉多余空格和文本字符，計算hash值）

Response：總的響應時間

time：該查詢在本次分析中總的時間占比

calls：執行次數，即本次分析總共有多少條這種類型的查詢語句

R/Call：平均每次執行的響應時間

V/M：響應時間Variance-to-mean的比率

Item：查詢對象

第三部分：每一種查詢的詳細統計結果

由下面查詢的詳細統計結果，最上面的表格列出了執行次數、最大、最小、平均、95%等各項目的統計。

ID：查詢的ID號，和上圖的QueryID對應

Databases：數據庫名

Users：各個用戶執行的次數（占比）

Query_timedistribution ：查詢時間分布,長短體現區間占比，本例中1s-10s之間查詢數量是10s以上的兩倍。

Tables：查詢中涉及到的表

Explain：SQL語句

PT-QUERY-DIGEST用法示例：

1.直接分析慢查詢文件:

pt-query-digest slow.log > slow_report.log

2.分析最近12小時內的查詢：

pt-query-digest --since=12h  slow.log > slow_report2.log

3.分析指定時間范圍內的查詢：

pt-query-digestslow.log --since 2017-01-07 09:30:00 --until 2017-01-07 10:00:00>> slow_report3.log

4.分析指含有select語句的慢查詢

pt-query-digest--filter $event->{fingerprint} =~ m/^select/i slow.log>slow_report4.log

5.針對某個用戶的慢查詢

pt-query-digest--filter ($event->{user} || "") =~ m/^root/i slow.log>slow_report5.log

6.查詢所有所有的全表掃描或fulljoin的慢查詢

pt-query-digest--filter (($event->{Full_scan} || "") eq "yes")||(($event->{Full_join} || "") eq "yes")slow.log> slow_report6.log

7.把查詢保存到query_review表

pt-query-digest--user=root –password=abc123 --review h=localhost,D=test,t=query_review--create-review-table  slow.log

8.把查詢保存到query_history表

pt-query-digest --user=root –password=abc123 --review h=localhost,D=test,t=query_history--create-review-table slow.log_0001

pt-query-digest --user=root –password=abc123 --review h=localhost,D=test,t=query_history--create-review-table slow.log_0002

9.通過tcpdump抓取mysql的tcp協議數據，然后再分析

tcpdump -s 65535 -x-nn -q -tttt -i any -c 1000 port 3306 > mysql.tcp.txt

pt-query-digest--type tcpdump mysql.tcp.txt> slow_report9.log

10.分析binlog

mysqlbinlogmysql-bin.000093 > mysql-bin000093.sql

pt-query-digest --type=binlog  mysql-bin000093.sql > slow_report10.log

11.分析generallog

pt-query-digest --type=genlog  localhost.log > slow_report11.log

在tidb中并不是所有SLOW_QUERY 的語句都是有問題的。真正會造成集群整體壓力增大的，是那些process_time 很大的語句。wait_time很大，但 process_time很小的語句通常不是問題語句，是因為被問題語句阻塞，在執行隊列等待造成的響應時間過長。所以我們可以使用adminshow slow 命令直接定位慢查詢語句。通過查找到問題語句后,通過對應的優化手段進行優化,如索引分析,統計信息收集等.

admin show slowrecent N;

admin show slow top[internal | all] N;

例如：

admin show slow top3;

admin show slow topinternal 3;

admin show slow topall 5;

由于內存限制，保留的慢查詢記錄的條數是有限的。當命令查詢的 N 大于記錄條數時，返回的結果記錄條數會小于 N。

輸出內容詳細說明，如下：