pt-query-digest 属于 Percona Toolkit 工具集中较为常用的工具,可以用于分析binlog、general log、slow log,同时也可以使用 show processlist 或从 tcpdump 抓取的 MySQL 协议数据来进行分析。另外简单分析的话可以使用MySQL 官方慢查询分析工具mysqlslap。
目录
一、工具下载安装
- 官网下载 percona-toolkit工具
# 可以通过这个界面下载其他版本
# https://www.percona.com/downloads/percona-toolkit/LATEST/
# wget https://downloads.percona.com/downloads/percona-toolkit/3.3.0/binary/redhat/7/x86_64/percona-toolkit-3.3.0-1.el7.x86_64.rpm
- percona-toolkit rpm包安装
# PT 工具是使用Perl语言编写和执行的,所以需要系统中有Perl环境,安装相关的依赖包。
# yum install perl-DBI perl-DBD-MySQL perl-IO-Socket-SSL perl-Digest-MD5 perl-TermReadKey -y
# yum install percona-toolkit-3.3.0-1.el7.x86_64.rpm
二、分析慢查询日志
2.1、pt-query-digest 参数说明
# pt-query-digest --help
--ask-pass FALSE #连接到MySQL时提示输入密码
--attribute-aliases db|Schema #属性列表|别名等(默认db | Schema)
--attribute-value-limit 0 #属性值的限制(默认为0)
--charset (No value) #默认字符集
#逗号分隔的配置文件列表;如果指定,则必须是命令行上的第一个选项
--config /etc/percona-toolkit/percona-toolkit.conf,/etc/percona-toolkit/pt-query-digest.conf,/root/.percona-toolkit.conf,/root/.pt-query-digest.conf
--continue-on-error TRUE #即使有错误也继续解析(默认为是)
--create-history-table TRUE #创建--history表(如果不存在)(默认为yes)
--create-review-table TRUE #创建--review表(如果不存在)(默认为yes)
--daemonize FALSE #Fork到后台并从shell分离
--database (No value) #连接到该数据库
--defaults-file (No value) #仅从给定文件读取mysql选项
--embedded-attributes (No value) #两个Perl正则表达式模式,用于捕获查询中嵌入的伪属性
--expected-range 5,10 #当数量多于或少于预期时解释项目(默认值为5,10)
--explain (No value) #使用此DSN对示例查询运行EXPLAIN并打印结果
--filter (No value) #丢弃此Perl代码未返回true的事件
--group-by fingerprint #要对事件的哪个属性进行分组(默认fingerprint)
--help TRUE #显示帮助并退出
--history (No value) #在给定表中保存每个查询类的指标。 pt-query-digest将查询指标(查询时间,锁定时间等)保存到此表中,以便您查看查询类如何随时间变化
--host (No value) #连接到主机
--ignore-attributes arg,cmd,insert_id,ip,port,Thread_id,timestamp,exptime,flags,key,res,val,server_id,offset,end_log_pos,Xid #不要聚合这些属性
--inherit-attributes db,ts #如果丢失,则从具有属性的最后一个事件继承这些属性(默认db,ts)
--interval .1 #轮询show processlist的频率,以秒为单位(默认为.1)
--iterations 1 #在收集和报告周期中迭代多少次(默认为1)
--limit 95%:20 #将输出限制为给定的百分比或计数(默认为95%:20)
--log (No value) #守护进程时将所有输出打印到此文件
--max-hostname-length 10 #将报告中的主机名修剪到此长度。 0 =不修剪主机名(默认为10)
--max-line-length 74 #将行修剪到此长度。 0 =不修剪线条(默认74)
--order-by Query_time:sum #按此属性:聚合函数对事件进行排序(默认Query_time:sum)
--outliers Query_time:1:10 #按属性:百分比:计数报告异常值(默认查询时间:1:10)
--output report #如何格式化和打印查询分析结果(默认report)
--password (No value) #连接时使用的密码
--pid (No value) #创建给定的PID文件
--port (No value) #用于连接的端口号
--preserve-embedded-numbers FALSE #查询时保留数据库/表名中的数字
--processlist (No value) #使用--interval sleep轮询此DSN的进程列表以进行查询
--progress time,30 #将进度报告打印到STDERR(默认时间30)
--read-timeout 0 #等待的超时时间,等待来自输入的事件; 0表示永远等待(默认值为0)。 可选后缀s =秒,m =分钟,h =小时,d =天; 如果没有后缀,则使用s。
--report TRUE #打印每个--group-by属性的查询分析报告(默认为yes)
--report-all FALSE #报告所有查询,甚至包括已审核的查询
--report-format rusage,date,hostname,files,header,profile,query_report,prepared #打印查询分析报告的这些部分
--report-histogram Query_time #绘制此属性值的分布图(默认Query_time)
--resume (No value) #如果指定,该工具会将最后一个文件偏移(如果有的话)写入给定的文件名
--review (No value) #保存查询以供以后查看,并且不报告已查看的
--run-time (No value) #每个迭代要运行多长时间。可选后缀s =秒,m =分钟,h =小时,d =天;如果没有后缀,则使用s。
--run-time-mode clock #设置--run-time的值所用的值(默认clock)
--sample (No value) #过滤掉每个查询中除前N个事件外的所有事件
--set-vars #在此以逗号分隔的(变量=值对)列表中设置MySQL变量
--show-all #显示这些属性的所有值
--since (No value) #解析仅查询比该值新的查询(自此日期以来解析查询)
--slave-password (No value) #设置用于连接到从的密码
--slave-user (No value) #设置用于连接到从的用户
--socket (No value) #用于连接的套接字文件
--timeline FALSE #显示事件的时间表
--type slowlog #要解析的输入的类型(默认慢日志)
--until (No value) #仅解析早于此值的查询(直到此日期为止解析查询)
--user (No value) #用于登录的用户(如果不是当前用户)
--variations #报告这些属性值的变化数量
--version FALSE #显示版本并退出
--version-check TRUE #检查最新版本的Percona Toolkit,MySQL和其他程序(默认为是)
--vertical-format TRUE #在报告的SQL查询中输出尾随的“ \ G”(默认为是)
--watch-server (No value) #此选项告诉pt-query-digest在解析tcpdump时要监视哪个服务器IP地址和端口(例如“ 10.0.0.1:3306”)(对于--type tcpdump);其他所有服务器均被忽略
2.2、pt-query-digest 示例输出
# pt-query-digest slow.log
# 7.8s user time, 740ms system time, 28.80M rss, 223.33M vsz
# Current date: Mon Aug 8 10:14:16 2021
# Hostname: xxx
# Files: /data/mysql/slow.log
# Overall: 336 total, 35 unique, 336 QPS, 4.01kx concurrency _____________
# Time range: 2021-08-07T21:39:41 to 2021-08-07T21:39:42
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 4015s 1s 1194s 12s 2s 110s 1s
# Lock time 72ms 40us 8ms 214us 445us 659us 93us
# Rows sent 173 0 1 0.51 0.99 0.50 0.99
# Rows examine 438.64M 0 146.21M 1.31M 0.99 13.44M 0.99
# Query size 57.97k 42 599 176.68 381.65 125.12 107.34
# Profile
# Rank Query ID Response time Calls R/Call V/M
# ==== ============================= =============== ===== ========= =====
# 1 0xE276FD458CDE3A2BEFAFA628... 3552.8886 88.5% 3 1184.2962 0.00 SELECT UNION pay_bills_?_? pay_bills
# 2 0x48DF84D46DBA7222E4B120D1... 64.1399 1.6% 46 1.3943 0.10 SELECT userInfo_?
# 3 0xA4AA4EBFEF14D0981CE16FF8... 45.0811 1.1% 34 1.3259 0.06 SELECT app_registerInfo
# 4 0xF55AC8F826405CD9F245CF14... 41.4674 1.0% 27 1.5358 0.15 SELECT channel_userInfo
# 5 0x1BEFDF48494EED2CE28C76F6... 36.0614 0.9% 24 1.5026 0.07 UPDATE userInfo_?
# 6 0x39FAE9762E32ABA68766744A... 34.1417 0.9% 22 1.5519 0.13 SELECT registerInfo
# 7 0x18B3AAF6970D138A9EF41D0E... 31.8459 0.8% 24 1.3269 0.10 SELECT exchange_userInfo
# 8 0x45C4C6258F787802EA0DD427... 25.6024 0.6% 19 1.3475 0.06 SELECT users_groups
# 9 0xC1BF73020E2185A41AAD5111... 22.8496 0.6% 18 1.2694 0.04 SELECT userInfo_?
# 10 0x610890AAE7777CD028843B03... 20.5777 0.5% 15 1.3718 0.06 SELECT t_ex_deal_?
# 11 0x6CBCC9F13EA3769364F0580A... 18.6494 0.5% 15 1.2433 0.04 SELECT channel_register_?
# 12 0xEB3A690C2D5259EF7F8F8629... 14.8725 0.4% 10 1.4872 0.08 SELECT user_blackList
# MISC 0xMISC 106.3317 2.6% 79 1.3460 0.0 <23 ITEMS>
# Query 1: 0 QPS, 0x concurrency, ID 0xE276FD458CDE3A2BEFAFA628DDB9439E at byte 59496990
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2021-08-07T21:39:42
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 3
# Exec time 88 3553s 1174s 1194s 1184s 1172s 0 1172s
# Lock time 0 693us 201us 248us 231us 247us 23us 236us
# Rows sent 1 3 1 1 1 1 0 1
# Rows examine 99 438.64M 146.21M 146.21M 146.21M 142.90M 0 142.90M
# Query size 1 960 320 320 320 320 0 320
# String:
# Hosts 10.10.195.243 (1/33%), 10.10.35.98 (1/33%)... 1 more
# Users xxx
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+ ################################################################
# Tables
# SHOW TABLE STATUS LIKE 'pay_bills_2020'\G
# SHOW CREATE TABLE `pay_bills_2020`\G
# SHOW TABLE STATUS LIKE 'pay_bills'\G
# SHOW CREATE TABLE `pay_bills`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT sum(sumPay) as sumPay FROM (
SELECT SUM(PaymentMoney) as sumPay FROM pay_bills_2020 WHERE UserID = 16134138<1 and paymentstatus in (1,3)
union all
SELECT SUM(PaymentMoney) as sumPay FROM pay_bills WHERE UserID = 16134138<1 and paymentstatus in (1,3)
) as t\G
# Query 2: 46 QPS, 64.14x concurrency, ID 0x48DF84D46DBA7222E4B120D148706D73 at byte 59471897
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.10
# Time range: 2021-08-07T21:39:41 to 2021-08-07T21:39:42
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 13 46
# Exec time 1 64s 1s 3s 1s 2s 374ms 1s
# Lock time 8 6ms 92us 466us 137us 176us 69us 119us
# Rows sent 26 46 1 1 1 1 0 1
# Rows examine 0 46 1 1 1 1 0 1
# Query size 29 16.96k 377 378 377.63 363.48 0 363.48
# String:
# Hosts 10.10.206.52 (14/30%), 10.10.231.166 (14/30%)... 2 more
# Users xxx
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s ################################################################
# 10s+
# Tables
# SHOW TABLE STATUS LIKE 'userInfo_4'\G
# SHOW CREATE TABLE `userInfo_4`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT UserID,LoginName, date_format(LastLoginTime,'%Y-%m-%d %H:%i:%s') as LastLoginTime , date_format(CreateTime,'%Y-%m-%d %H:%i:%s') as CreateTime ,TrueName,IDCard,Mobile FROM userInfo_4 WHERE UserID = 1403012254\G
......
2.3、pt-query-digest 输出分析
2.3.1 第一部分:输出结果的总体信息
# 7.8s user time, 740ms system time, 28.80M rss, 223.33M vsz
# 说明:
# 执行过程中在用户中所花费的所有时间
# 执行过程中内核空间中所花费的所有时间
# pt-query-digest进程所分配的内存大小
# pt-query-digest进程所分配的虚拟内存大小
# Current date: Mon Aug 8 10:14:16 2021
# 说明:当前日期
# Hostname: xxx
# 说明:当前主机名
# Files: /data/mysql/slow.log
# 说明:执行pt-query-digest的主机名
# Overall: 336 total, 35 unique, 336 QPS, 4.01kx concurrency _____________
# 说明:语句总数量,唯一语句数量,每秒查询量,查询的并发
# Time range: 2021-08-07T21:39:41 to 2021-08-07T21:39:42
# 说明:执行过程中日志记录的时间范围
# Attribute total min max avg 95% stddev median
说明:属性 总计 最小值 最大值 平均值 95% 标准差 中位数
# ============ ======= ======= ======= ======= ======= ======= =======
# Exec time 4015s 1s 1194s 12s 2s 110s 1s
# 说明:执行时间
# Lock time 72ms 40us 8ms 214us 445us 659us 93us
# 说明:锁占用时间
# Rows sent 173 0 1 0.51 0.99 0.50 0.99
# 说明:发送到客户端的行数
# Rows examine 438.64M 0 146.21M 1.31M 0.99 13.44M 0.99
# 说明:语句扫描行数
# Query size 57.97k 42 599 176.68 381.65 125.12 107.34
# 说明:查询的字符数
2.3.2 第二部分:输出队列组的统计信息
# Profile
# Rank Query ID Response time Calls R/Call V/M
# ==== ============================= =============== ===== ========= =====
# 1 0xE276FD458CDE3A2BEFAFA628... 3552.8886 88.5% 3 1184.2962 0.00 SELECT UNION pay_bills_?_? pay_bills
# 2 0x48DF84D46DBA7222E4B120D1... 64.1399 1.6% 46 1.3943 0.10 SELECT userInfo_?
# 3 0xA4AA4EBFEF14D0981CE16FF8... 45.0811 1.1% 34 1.3259 0.06 SELECT app_registerInfo
# 4 0xF55AC8F826405CD9F245CF14... 41.4674 1.0% 27 1.5358 0.15 SELECT channel_userInfo
# 5 0x1BEFDF48494EED2CE28C76F6... 36.0614 0.9% 24 1.5026 0.07 UPDATE userInfo_?
# 6 0x39FAE9762E32ABA68766744A... 34.1417 0.9% 22 1.5519 0.13 SELECT registerInfo
# 7 0x18B3AAF6970D138A9EF41D0E... 31.8459 0.8% 24 1.3269 0.10 SELECT exchange_userInfo
# 8 0x45C4C6258F787802EA0DD427... 25.6024 0.6% 19 1.3475 0.06 SELECT users_groups
# 9 0xC1BF73020E2185A41AAD5111... 22.8496 0.6% 18 1.2694 0.04 SELECT userInfo_?
# 10 0x610890AAE7777CD028843B03... 20.5777 0.5% 15 1.3718 0.06 SELECT t_ex_deal_?
# 11 0x6CBCC9F13EA3769364F0580A... 18.6494 0.5% 15 1.2433 0.04 SELECT channel_register_?
# 12 0xEB3A690C2D5259EF7F8F8629... 14.8725 0.4% 10 1.4872 0.08 SELECT user_blackList
# MISC 0xMISC 106.3317 2.6% 79 1.3460 0.0 <23 ITEMS>
参数 说明
============ ==========================================================
Rank 查询在分析的整个查询集中的排名
Query ID 语句ID信息
Response time 响应时间
Calls 执行次数,在本次分析中一共有多少这样的查询次数
R/Call 平均每次执行的响应时间
V/M 响应时间Variance-to-mean的比率
2.3.3 第三部分:输出每列查询的详细信息
# Query 1: 0 QPS, 0x concurrency, ID 0xE276FD458CDE3A2BEFAFA628DDB9439E at byte 59496990
说明:查询队列1:每秒查询量,查询的并发,队列1的ID值,59496990:表示文件中偏移量,后可根据这个偏移量进行快速定位
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2021-08-07T21:39:42
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 0 3
# Exec time 88 3553s 1174s 1194s 1184s 1172s 0 1172s
# Lock time 0 693us 201us 248us 231us 247us 23us 236us
# Rows sent 1 3 1 1 1 1 0 1
# Rows examine 99 438.64M 146.21M 146.21M 146.21M 142.90M 0 142.90M
# Query size 1 960 320 320 320 320 0 320
# String:
# Hosts 10.10.195.243 (1/33%), 10.10.35.98 (1/33%)... 1 more
# 说明:客户端主机IP
# Users xxx
# 说明:使用的用户名
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s
# 10s+ ################################################################
# 说明:查询时间的分布
# Tables
# SHOW TABLE STATUS LIKE 'pay_bills_2020'\G
# SHOW CREATE TABLE `pay_bills_2020`\G
# SHOW TABLE STATUS LIKE 'pay_bills'\G
# SHOW CREATE TABLE `pay_bills`\G
# EXPLAIN /*!50100 PARTITIONS*/
SELECT sum(sumPay) as sumPay FROM (
SELECT SUM(PaymentMoney) as sumPay FROM pay_bills_2020 WHERE UserID = 16134138<1 and paymentstatus in (1,3)
union all
SELECT SUM(PaymentMoney) as sumPay FROM pay_bills WHERE UserID = 16134138<1 and paymentstatus in (1,3)
) as t\G
- 可以利用上述偏移量快速查找具体SQL
# tail -c +26111916 ./slow.log | head
# Time: 2021-08-07T21:39:42.804225+08:00
# User@Host: xxx[xxx] @ [10.10.35.98] Id: 10183855
# Query_time: 1194.294524 Lock_time: 0.000248 Rows_sent: 1 Rows_examined: 153315154
SET timestamp=1628343582;
SELECT sum(sumPay) as sumPay FROM (
SELECT SUM(PaymentMoney) as sumPay FROM pay_bills_2020 WHERE UserID = 16134138<1 and paymentstatus in (1,3)
union all
SELECT SUM(PaymentMoney) as sumPay FROM pay_bills WHERE UserID = 16134138<1 and paymentstatus in (1,3)
) as t\G
三、常用语句示例
- 直接分析慢查询日志
# pt-query-digest slow.log > slow_report.log
- 分析最近12小时内的查询
# pt-query-digest --since=12h slow.log > slow_report.log
- 分析指定时间范围内的查询
# pt-query-digest --since '2021-08-07 21:19:00' --until '2021-08-07 21:42:00' slow.log > slow_report.log
- 分析指含有select语句的慢查询
# pt-query-digest --filter '$event->{fingerprint} =~ m/^select/i' slow.log > slow_report.log
- 针对某个IP的慢查询
# pt-query-digest --filter '($event->{host} || $event->{ip} || "") =~ m/10.0.0.1/' slow.log > slow_report.log
- 针对某个用户的慢查询
# pt-query-digest --filter '($event->{user} || "") =~ m/^john/i' slow.log > slow_report.log
- 查询全表扫描或全连接的慢查询
# pt-query-digest --filter '(($event->{Full_scan} || "") eq "yes") ||(($event->{Full_join} || "") eq "yes")' slow.log > slow_report.log
- 把查询保存到query_review表,数据库中标记为已审核的查询不会打印在报告中
# pt-query-digest --user=xxx --password=xxx --review h=localhost,D=test,t=query_review --create-review-table slow.log
- 把查询保存到query_history表, 可以加 --no-report 结果不打印到控制台,只输出到表中
# pt-query-digest --user=xxx --password=xxx --review h=localhost,D=test,t=query_history --create-history-table slow.log
- 通过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.log
- 分析binlog
# mysqlbinlog mysqlbin-log.002617 > mysqlbin-log.002617.sql
# pt-query-digest --type=binlog mysqlbin-log.002617 > slow.log
- 分析general log
# pt-query-digest --type=genlog localhost.log > slow_report11.log
- 查看当前会话慢查询并打印出
# pt-query-digest --processlist h=localhost,u=xxx,p=xxx --interval=1 --output=slowlog
Reference