MySQL慢查询日志分析

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

  • 0
    点赞
  • 0
    收藏
    觉得还不错? 一键收藏
  • 0
    评论

“相关推荐”对你有帮助么?

  • 非常没帮助
  • 没帮助
  • 一般
  • 有帮助
  • 非常有帮助
提交
评论
添加红包

请填写红包祝福语或标题

红包个数最小为10个

红包金额最低5元

当前余额3.43前往充值 >
需支付:10.00
成就一亿技术人!
领取后你会自动成为博主和红包主的粉丝 规则
hope_wisdom
发出的红包
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、付费专栏及课程。

余额充值