MySQL慢查询日志分析

傷城~ 2022-09-04 00:51 474阅读 0赞

> pt-query-digest 属于 Percona Toolkit 工具集中较为常用的工具，可以用于分析binlog、general log、slow log，同时也可以使用 show processlist 或从 tcpdump 抓取的 MySQL 协议数据来进行分析。另外简单分析的话可以使用MySQL 官方慢查询分析工具mysqlslap。

### 目录 ###

*   *   *  一、工具下载安装
         *  二、分析慢查询日志
         *   *  2.1、pt-query-digest 参数说明
             *  2.2、pt-query-digest 示例输出
             *  2.3、pt-query-digest 输出分析
             *   *  2.3.1 第一部分：输出结果的总体信息
                 *  2.3.2 第二部分：输出队列组的统计信息
                 *  2.3.3 第三部分：输出每列查询的详细信息
         *  三、常用语句示例

### 一、工具下载安装 ###

*  官网下载 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**

*  [https://www.percona.com/doc/percona-toolkit/LATEST/pt-query-digest.html][https_www.percona.com_doc_percona-toolkit_LATEST_pt-query-digest.html]
 *  [https://zhuanlan.zhihu.com/p/257975998][https_zhuanlan.zhihu.com_p_257975998]

[https_www.percona.com_doc_percona-toolkit_LATEST_pt-query-digest.html]: https://www.percona.com/doc/percona-toolkit/LATEST/pt-query-digest.html
[https_zhuanlan.zhihu.com_p_257975998]: https://zhuanlan.zhihu.com/p/257975998