Tidb慢查询定位分析

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。

输出内容详细说明，如下：