mysql pt diskstats_MySQL慢查询分析工具pt-query-digest

一、简介

pt-query-digest是用于分析mysql慢查询的一个工具，它可以分析binlog、General log、slowlog，也可以通过SHOWPROCESSLIST或者通过tcpdump抓取的MySQL协议数据来进行分析。可以把分析结果输出到文件中，分析过程是先对查询语句的条件进行参数化，然后对参数化以后的查询进行分组统计，统计出各查询的执行时间、次数、占比等，可以借助分析结果找出问题进行优化。

二、安装pt-query-digest

pt-query-digest是percona-toolkit里面一个工具，其作用就是分析慢查询日志，将MySQL慢查询日志进行统计并友好的显示出来

1、安装依赖包

[root@zabbix_server bin]# yum install perl-DBI perl-DBD-MySQL perl-IO-Socket-SSL perl-Digest-MD5 -y

2、下载percona-toolkit二进制包

[root@zabbix_server conf.d]# mkdir /usr/local/src/percona-toolkit

[root@zabbix_server conf.d]# cd /usr/local/src/percona-toolkit

[root@zabbix_server percona-toolkit]# wget https://www.percona.com/downloads/percona-toolkit/3.0.10/binary/tarball/percona-toolkit-3.0.10_x86_64.tar.gz

--2020-04-07 16:44:49-- https://www.percona.com/downloads/percona-toolkit/3.0.10/binary/tarball/percona-toolkit-3.0.10_x86_64.tar.gz

正在解析主机 www.percona.com... 74.121.199.234正在连接 www.percona.com|74.121.199.234|:443... 已连接。

已发出 HTTP 请求，正在等待回应... 200OK

长度：8170395 (7.8M) [application/x-gzip]

正在保存至: “percona-toolkit-3.0.10_x86_64.tar.gz”

28% [============================> ] 2,312,153 693K/s eta(英国中部时33% [==================================> ] 2,770,905 759K/s eta(英国中部时39% [========================================> ] 3,229,657 817K/s eta(英国中部时45% [==============================================> ] 3,688,409 871K/s eta(英国中部时50% [====================================================> ] 4,147,161 916K/s eta(英国中部时56% [==========================================================> ] 4,605,913 953K/s eta(英国中部时61% [================================================================> ] 5,064,665 986K/s eta(英国中部时67% [======================================================================> ] 5,523,417 1014K/s eta(英国中部时73% [============================================================================> ] 5,982,169 1.02M/s eta(英国中部时77% [=================================================================================> ] 6,326,233 1.01M/s eta(英国中部时83% [=======================================================================================> ] 6,850,521 1.10M/s eta(英国中部时87% [============================================================================================> ] 7,178,201 1.15M/s eta(英国中部时91% [================================================================================================> ] 7,505,881 1.25M/s eta(英国中部时96% [=====================================================================================================> ] 7,866,329 1.29M/s eta(英国中部时100%[=========================================================================================================>] 8,170,395 1.37M/s in 7.1s

2020-04-07 16:44:59 (1.09 MB/s) - 已保存 “percona-toolkit-3.0.10_x86_64.tar.gz” [8170395/8170395])

[root@zabbix_server percona-toolkit]#

解压

[root@zabbix_server percona-toolkit]# tar -zxvf percona-toolkit-3.0.10_x86_64.tar.gz

percona-toolkit-3.0.10/percona-toolkit-3.0.10/CONTRIBUTE.md

percona-toolkit-3.0.10/Makefile.PL

percona-toolkit-3.0.10/docker-compose.yml

percona-toolkit-3.0.10/CONTRIBUTING.md

percona-toolkit-3.0.10/Gopkg.lock

percona-toolkit-3.0.10/README.md

percona-toolkit-3.0.10/bin/percona-toolkit-3.0.10/bin/pt-summary

percona-toolkit-3.0.10/bin/pt-slave-delay

percona-toolkit-3.0.10/bin/pt-mongodb-query-digest

percona-toolkit-3.0.10/bin/pt-slave-restart

percona-toolkit-3.0.10/bin/pt-variable-advisor

percona-toolkit-3.0.10/bin/pt-fingerprint

percona-toolkit-3.0.10/bin/pt-secure-collect

percona-toolkit-3.0.10/bin/pt-index-usage

percona-toolkit-3.0.10/bin/pt-archiver

percona-toolkit-3.0.10/bin/pt-findpercona-toolkit-3.0.10/bin/pt-heartbeat

percona-toolkit-3.0.10/bin/pt-fifo-splitpercona-toolkit-3.0.10/bin/pt-fk-error-logger

percona-toolkit-3.0.10/bin/pt-mysql-summary

percona-toolkit-3.0.10/bin/pt-online-schema-change

percona-toolkit-3.0.10/bin/pt-table-usage

percona-toolkit-3.0.10/bin/pt-align

percona-toolkit-3.0.10/bin/pt-query-digest

percona-toolkit-3.0.10/bin/pt-ioprofile

percona-toolkit-3.0.10/bin/pt-visual-explain

percona-toolkit-3.0.10/bin/pt-stalk

percona-toolkit-3.0.10/bin/pt-mext

percona-toolkit-3.0.10/bin/pt-table-checksum

percona-toolkit-3.0.10/bin/pt-show-grants

percona-toolkit-3.0.10/bin/pt-pmp

percona-toolkit-3.0.10/bin/pt-upgrade

percona-toolkit-3.0.10/bin/pt-diskstats

percona-toolkit-3.0.10/bin/pt-sift

percona-toolkit-3.0.10/bin/pt-config-diffpercona-toolkit-3.0.10/bin/pt-slave-findpercona-toolkit-3.0.10/bin/pt-killpercona-toolkit-3.0.10/bin/pt-duplicate-key-checker

percona-toolkit-3.0.10/bin/pt-deadlock-logger

percona-toolkit-3.0.10/bin/pt-mongodb-summary

percona-toolkit-3.0.10/bin/pt-table-syncpercona-toolkit-3.0.10/lib/percona-toolkit-3.0.10/docs/percona-toolkit-3.0.10/docs/percona-toolkit.pod

percona-toolkit-3.0.10/Gopkg.toml

percona-toolkit-3.0.10/MANIFEST

percona-toolkit-3.0.10/COPYING

percona-toolkit-3.0.10/Changelog

percona-toolkit-3.0.10/INSTALL

[root@zabbix_server percona-toolkit]# mv percona-toolkit-3.0.10 /usr/local/

3、运行查看版本

[root@zabbix_server bin]# ./pt-query-digest --version

pt-query-digest 3.0.10[root@zabbix_server bin]#

pt-query-digest: 慢查询日志分析统计

pt-summary:服务器摘要

pt-diskstats:服务器磁盘监测

pt-msyql-summary:mysql服务状态摘要

三、pt-query-digest语法及重要选项

pt-query-digest [OPTIONS] [FILES] [DSN]

--create-review-table：当使用--review参数把分析结果输出到表中时，如果没有表就自动创建。

--create-history-table：当使用--history参数把分析结果输出到表中时，如果没有表就自动创建。

--filter：对输入的慢查询按指定的字符串进行匹配过滤后再进行分析

--limit：限制输出结果百分比或数量，默认值是20,即将最慢的20条语句输出，如果是50%则按总响应时间占比从大到小排序，输出到总和达到50%位置截止。

--host：mysql服务器地址

--user：mysql用户名

--password：mysql用户密码

--history：将分析结果保存到表中，分析结果比较详细，下次再使用--history时，如果存在相同的语句，且查询所在的时间区间和历史表中的不同，则会记录到数据表中，可以通过查询同一CHECKSUM来比较某类型查询的历史变化。

--review：将分析结果保存到表中，这个分析只是对查询条件进行参数化，一个类型的查询一条记录，比较简单。当下次使用--review时，如果存在相同的语句分析，就不会记录到数据表中。

--output：分析结果输出类型，值可以是report(标准分析报告)、slowlog(Mysql slow log)、json、json-anon，一般使用report，以便于阅读。

--since：从什么时间开始分析，值为字符串，可以是指定的某个”yyyy-mm-dd [hh:mm:ss]”格式的时间点，也可以是简单的一个时间值：s(秒)、h(小时)、m(分钟)、d(天)，如12h就表示从12小时前开始统计。

--until：截止时间，配合—since可以分析一段时间内的慢查询。

四、pt-query-digest输出结果的分析

第一部分：总体统计结果

Overall：总共有多少条查询

Time range：查询执行的时间范围

unique：唯一查询数量，即对查询条件进行参数化以后，总共有多少个不同的查询

total：总计   min：最小   max：最大  avg：平均

95%：把所有值从小到大排列，位置位于95%的那个数，这个数一般最具有参考价值

median：中位数，把所有值从小到大排列，位置位于中间那个数

[root@zabbix_server bin]# ./pt-query-digest /home/mysql_data/mysql/zabbix_server-slow.log

# A software update is available:

# 490ms usertime, 40ms system time, 26.75M rss, 223.77Mvsz

# Currentdate: Wed Apr 8 09:50:22 2020# Hostname: zabbix_server.jinglong

# Files:/home/mysql_data/mysql/zabbix_server-slow.log

# Overall:4 total, 4 unique, 0.00 QPS, 0.06x concurrency ________________

# Time range:2020-04-07T06:34:40 to 2020-04-07T09:16:18# Attribute total min max avg95%stddev median

#============ ======= ======= ======= ======= ======= ======= =======# Exectime628s 106ms 536s 157s 511s 212s 300s

# Locktime 368us 0146us 92us 144us 54us 132us

# Rows sent3 0 1 0.75 0.99 0.43 0.99# Rows examine161.34M 0 146.78M 40.34M 142.90M 60.09M 78.66M# Query size527 27 425 131.75 420.77 167.83 231.62# Profile

# Rank Query ID Responsetime Calls R/Call V/M Item

#==== ================== ============== ===== ======== ===== ============#1 0x99E696CEDECCBA36 536.4558 85.4% 1 536.4558 0.00SELECT history

#2 0x47C7D572627422FB 91.3777 14.5% 1 91.3777 0.00SELECT trends

# MISC 0xMISC0.3991 0.1% 2 0.1996 0.0 <2 ITEMS># Query1: 0 QPS, 0x concurrency, ID 0x99E696CEDECCBA36 at byte 483______

# This item is includedin the report because it matches --limit.

# Scores: V/M = 0.00# Time range: all events occurred at2020-04-07T06:42:47# Attribute pct total min max avg95%stddev median

#============ === ======= ======= ======= ======= ======= ======= =======# Count25 1# Exectime 85 536s 536s 536s 536s 536s 0536s

# Locktime 39 146us 146us 146us 146us 146us 0146us

# Rows sent33 1 1 1 1 1 0 1# Rows examine90 146.78M 146.78M 146.78M 146.78M 146.78M 0 146.78M# Query size8 43 43 43 43 43 0 43# String:

# Hosts172.28.146.109# Users root

# Query_time distribution

# 1us

# 10us

# 100us

# 1ms

# 10ms

# 100ms

# 1s

# 10s+################################################################

# Tables

# SHOW TABLE STATUS LIKE'history'\G

# SHOW CREATE TABLE `history`\G

# EXPLAIN/*!50100 PARTITIONS*/

select count(*) from history

LIMIT0, 1000\G

# Query2: 0 QPS, 0x concurrency, ID 0x47C7D572627422FB at byte 241______

# This item is includedin the report because it matches --limit.

# Scores: V/M = 0.00# Time range: all events occurred at2020-04-07T06:38:39# Attribute pct total min max avg95%stddev median

#============ === ======= ======= ======= ======= ======= ======= =======# Count25 1# Exectime 14 91s 91s 91s 91s 91s 091s

# Locktime 27 102us 102us 102us 102us 102us 0102us

# Rows sent33 1 1 1 1 1 0 1# Rows examine9 14.56M 14.56M 14.56M 14.56M 14.56M 0 14.56M# Query size5 27 27 27 27 27 0 27# String:

# Hosts zabbix_server

# Users root

# Query_time distribution

# 1us

# 10us

# 100us

# 1ms

# 10ms

# 100ms

# 1s

# 10s+################################################################

# Tables

# SHOW TABLE STATUS LIKE'trends'\G

# SHOW CREATE TABLE `trends`\G

# EXPLAIN/*!50100 PARTITIONS*/

select count(*) from trends\G

[root@zabbix_server bin]#

1、总体统计结果

# 490ms user time, 40ms system time, 26.75M rss, 223.77Mvsz

# Currentdate: Wed Apr 8 09:50:22 2020# Hostname: zabbix_server.jinglong

# Files:/home/mysql_data/mysql/zabbix_server-slow.log

# Overall:4 total, 4 unique, 0.00 QPS, 0.06x concurrency ________________

# Time range:2020-04-07T06:34:40 to 2020-04-07T09:16:18# Attribute total min max avg95%stddev median

#============ ======= ======= ======= ======= ======= ======= =======# Exectime628s 106ms 536s 157s 511s 212s 300s

# Locktime 368us 0146us 92us 144us 54us 132us

# Rows sent3 0 1 0.75 0.99 0.43 0.99# Rows examine161.34M 0 146.78M 40.34M 142.90M 60.09M 78.66M# Query size527 27 425 131.75 420.77 167.83 231.62

该工具执行日志分析的用户时间，系统时间，物理内存占用大小，虚拟内存占用大小

#490ms user time, 40ms system time, 26.75M rss, 223.77Mvsz

工具执行时间

Current date: Wed Apr 8 09:50:22 2020

运行分析工具的主机名

Hostname: zabbix_server.jinglong

被分析的文件名

Files: /home/mysql_data/mysql/zabbix_server-slow.log

语句总数量，唯一的语句数量，QPS，并发数

Overall: 4 total, 4 unique, 0.00 QPS, 0.06x concurrency

查询执行的时间范围

Time range: 2020-04-07T06:34:40 to 2020-04-07T09:16:18

属性 属性占整个报告百分比 总计 最小 最大 平均 95% 标准 中等

Attribute pct total min max avg 95%stddev median

语句执行时间 锁占用时间语句返回行数 语句扫描行数 查询的字符数

Exec time Lock time Rows sent Rows examine Query size

2、分组统计结果

# Profile

# Rank Query ID Responsetime Calls R/Call V/M Item

#==== ================== ============== ===== ======== ===== ============#1 0x99E696CEDECCBA36 536.4558 85.4% 1 536.4558 0.00SELECT history

#2 0x47C7D572627422FB 91.3777 14.5% 1 91.3777 0.00SELECT trends

# MISC 0xMISC0.3991 0.1% 2 0.1996 0.0 <2 ITEMS>

Rank:所有语句的排名，默认按查询时间降序排列，通过--order-by指定

Query ID:语句的ID，(去掉多余空格和文本字符，计算hash值)

Response:总的响应时间

time:该查询在本次分析中总的时间占比

calls：执行次数，即本次分析总共有多少条这种类型的查询语句

R/Call：平均每次执行的响应时间

V/M：响应时间Variance-to-mean的比率

Item：查询对象

3、每一种查询的详细统计结果

# Query 1: 0 QPS, 0x concurrency, ID 0x99E696CEDECCBA36 at byte 483______

# This item is includedin the report because it matches --limit.

# Scores: V/M = 0.00# Time range: all events occurred at2020-04-07T06:42:47# Attribute pct total min max avg95%stddev median

#============ === ======= ======= ======= ======= ======= ======= =======# Count25 1# Exectime 85 536s 536s 536s 536s 536s 0536s

# Locktime 39 146us 146us 146us 146us 146us 0146us

# Rows sent33 1 1 1 1 1 0 1# Rows examine90 146.78M 146.78M 146.78M 146.78M 146.78M 0 146.78M# Query size8 43 43 43 43 43 0 43# String:

# Hosts172.28.146.109# Users root

# Query_time distribution

# 1us

# 10us

# 100us

# 1ms

# 10ms

# 100ms

# 1s

# 10s+################################################################

# Tables

# SHOW TABLE STATUS LIKE'history'\G

# SHOW CREATE TABLE `history`\G

# EXPLAIN/*!50100 PARTITIONS*/

select count(*) from history

LIMIT0, 1000\G

# Query2: 0 QPS, 0x concurrency, ID 0x47C7D572627422FB at byte 241______

# This item is includedin the report because it matches --limit.

# Scores: V/M = 0.00# Time range: all events occurred at2020-04-07T06:38:39# Attribute pct total min max avg95%stddev median

#============ === ======= ======= ======= ======= ======= ======= =======# Count25 1# Exectime 14 91s 91s 91s 91s 91s 091s

# Locktime 27 102us 102us 102us 102us 102us 0102us

# Rows sent33 1 1 1 1 1 0 1# Rows examine9 14.56M 14.56M 14.56M 14.56M 14.56M 0 14.56M# Query size5 27 27 27 27 27 0 27# String:

# Hosts zabbix_server

# Users root

# Query_time distribution

# 1us

# 10us

# 100us

# 1ms

# 10ms

# 100ms

# 1s

# 10s+################################################################

# Tables

# SHOW TABLE STATUS LIKE'trends'\G

# SHOW CREATE TABLE `trends`\G

# EXPLAIN/*!50100 PARTITIONS*/

select count(*) from trends\G

[root@zabbix_server bin]#

Query 1: 0 QPS, 0x concurrency, ID 0x99E696CEDECCBA36 at byte 483

ID：查询的ID号，和上图的Query ID对应

Count->total 表示查询执行了25次

Exec time->pct表示执行时间总共站了所有查询的百分之十四

Exec time->total 表示执行时间总共91s

Exec time->min 表示最小执行时间

Exec time->max 表示最大执行时间

Exec time->avg 表示平均执行时间

Exec time->95% 表示有百分之95的执行时间小于91s

Exec time->stddev 标准偏差，表示所有值偏离平均值的波动程度 (计算这个是从百分之95来算出的，排除了特别大的数)

Exec time->median 中间的那个值 (计算这个是从百分之95来算出的，排除了特别大的数)

Query_time distribution：查询时间分布, 长短体现区间占比

Tables：查询中涉及到的表

EXPLAIN：SQL语句

五、用法示例

1、将结果输出到报告文件

[root@zabbix_server bin]# ./pt-query-digest /home/mysql_data/mysql/zabbix_server-slow.log >/home/slow_report.log

[root@zabbix_server bin]# vim /home/slow_report.log1

2 # 450ms user time, 50ms system time, 24.53M rss, 209.02Mvsz3 # Current date: Wed Apr 8 10:49:23 2020

4# Hostname: zabbix_server.jinglong5 # Files: /home/mysql_data/mysql/zabbix_server-slow.log6 # Overall: 6 total, 5 unique, 0.00 QPS, 0.01x concurrency ________________7 # Time range: 2020-04-07T06:34:40 to 2020-04-08T02:38:33

8 # Attribute total min max avg 95%stddev median9 # ============ ======= ======= ======= ======= ======= ======= =======

10 # Exec time642s 106ms 536s 107s 511s 186s 49s11 # Lock time 368us 0146us 61us 144us 61us 108us12 # Rows sent 5 0 1 0.83 0.99 0.37 0.99

13 # Rows examine 161.34M 0 146.78M 26.89M 142.90M 52.45M 0

14 # Query size 558 15 425 93 420.77 147.43 37.09

15

16# Profile17 # Rank Query ID Response time Calls R/Call V/M Item18 # ==== ================== ============== ===== ======== ===== ============

19 # 1 0x99E696CEDECCBA36 536.4558 83.5% 1 536.4558 0.00SELECT history20 # 2 0x47C7D572627422FB 91.3777 14.2% 1 91.3777 0.00SELECT trends21 # MISC 0xMISC 14.3996 2.2% 4 3.5999 0.0 <3 ITEMS>

22

23 # Query 1: 0 QPS, 0x concurrency, ID 0x99E696CEDECCBA36 at byte 483______24 # This item is included in the report because it matches --limit.25 # Scores: V/M = 0.00

26 # Time range: all events occurred at 2020-04-07T06:42:47

27 # Attribute pct total min max avg 95%stddev median28 # ============ === ======= ======= ======= ======= ======= ======= =======

29 # Count 16 1

30 # Exec time 83 536s 536s 536s 536s 536s 0536s31 # Lock time 39 146us 146us 146us 146us 146us 0146us32 # Rows sent 20 1 1 1 1 1 0 1

33 # Rows examine 90 146.78M 146.78M 146.78M 146.78M 146.78M 0 146.78M

34 # Query size 7 43 43 43 43 43 0 43

35# String:36 # Hosts 172.28.146.109

37# Users root38# Query_time distribution39# 1us40# 10us41# 100us42# 1ms43# 10ms44# 100ms45# 1s46 # 10s+################################################################47# Tables48 # SHOW TABLE STATUS LIKE 'history'\G49# SHOW CREATE TABLE `history`\G50 # EXPLAIN /*!50100 PARTITIONS*/

51 select count(*) from history52 LIMIT 0, 1000\G53

54 # Query 2: 0 QPS, 0x concurrency, ID 0x47C7D572627422FB at byte 241______55 # This item is included in the report because it matches --limit.56 # Scores: V/M = 0.00

57 # Time range: all events occurred at 2020-04-07T06:38:39

58 # Attribute pct total min max avg 95%stddev median59 # ============ === ======= ======= ======= ======= ======= ======= =======

60 # Count 16 1

61 # Exec time 14 91s 91s 91s 91s 91s 091s62 # Lock time 27 102us 102us 102us 102us 102us 0102us63 # Rows sent 20 1 1 1 1 1 0 1

64 # Rows examine 9 14.56M 14.56M 14.56M 14.56M 14.56M 0 14.56M

65 # Query size 4 27 27 27 27 27 0 27

66# String:67# Hosts zabbix_server68# Users root69# Query_time distribution70# 1us71# 10us72# 100us73# 1ms74# 10ms75# 100ms76# 1s77 # 10s+################################################################78# Tables79 # SHOW TABLE STATUS LIKE 'trends'\G80# SHOW CREATE TABLE `trends`\G81 # EXPLAIN /*!50100 PARTITIONS*/

82 select count(*) from trends\G

[root@zabbix_server bin]#

2、分析最近10小时内的查询

[root@zabbix_server bin]# ./pt-query-digest --since=10h /home/mysql_data/mysql/zabbix_server-slow.log

3.分析指定时间范围内的查询

[root@zabbix_server bin]# ./pt-query-digest --since='2020-04-08 00:00:00' --until='2020-04-08 11:00:00' /home/mysql_data/mysql/zabbix_server-slow.log

4.分析指含有select语句的慢查询

[root@zabbix_server bin]# ./pt-query-digest --filter '$event->{fingerprint}=~ m/^select/i' /home/mysql_data/mysql/zabbix_server-slow.log

5.针对某个用户的慢查询

[root@zabbix_server bin]# ./pt-query-digest --filter '($event->{user}||"")=~ m/^root/i' /home/mysql_data/mysql/zabbix_server-slow.log

6.查询所有所有的全表扫描或full join的慢查询

[root@zabbix_server bin]# ./pt-query-digest --filter '(($event->{Full_scan}||"") eq "yes")||(($event->{Full_join}||"") eq "yes")' /home/mysql_data/mysql/zabbix_server-slow.log

7.把查询保存到指定数据库的query_review表

[root@zabbix_server bin]# ./pt-query-digest --user=root --password=xxxxxxx --review h=172.28.18.75,D=slow_query_log,t=global_query_review /home/mysql_data/mysql/zabbix_server-slow.log

mysql>use slow_query_log;

Reading table informationforcompletion of table and column names

You can turn off this feature to get a quicker startup with-A

Database changed

mysql> select *from global_query_view;

ERROR1146 (42S02): Table 'slow_query_log.global_query_view' doesn't exist

mysql> select *from global_query_review;+----------------------+---------------------------------------------+----------------------------------------------------+---------------------+---------------------+-------------+-------------+----------+-----------------+

| checksum | fingerprint | sample | first_seen | last_seen | reviewed_by | reviewed_on | comments | reviewed_status |

+----------------------+---------------------------------------------+----------------------------------------------------+---------------------+---------------------+-------------+-------------+----------+-----------------+

| 5172337384313070331 | select count(*) from trends | select count(*) from trends | 2020-04-07 06:38:39 | 2020-04-07 06:38:39 | NULL | NULL | NULL | NULL |

| 6514775613177967797 | select count(*) from `history_uint` limit ? | select count(*) from `history_uint`

LIMIT0, 1000 | 2020-04-08 02:56:46 | 2020-04-08 02:56:46 | NULL | NULL | NULL | NULL |

| 11089716947691813430 | select count(*) from history limit ? | select count(*) from history

LIMIT0, 1000 | 2020-04-07 06:42:47 | 2020-04-07 06:42:47 | NULL | NULL | NULL | NULL |

+----------------------+---------------------------------------------+----------------------------------------------------+---------------------+---------------------+-------------+-------------+----------+-----------------+

3 rows in set (0.00 sec

已经保存到数据表里了