Mysql 慢查询日志分析
2024-10-28 08:52:07 # Technical # MySQL

MySQL 的慢查询日志是 MySQL 提供的一种日志记录,它用来记录在 MySQL 中响应时间超过阀值的语句,具体指运行时间超过 long_query_time 值的 SQL,则会被记录到慢查询日志中

默认情况下,Mysql 数据库并不启动慢查询日志,需要我们手动来设置这个参数,当然,如果不是调优需要的话,一般不建议启动该参数,因为 开启慢查询日志会带来一定的性能影响

相关配置

/etc/my.cnf 中相关配置

  • slow_query_log:是否开启慢查询日志,1表示开启,0表示关闭
  • log-slow-queries:旧版(5.6以下版本)MySQL数据库慢查询日志存储路径
  • slow-query-log-file:新版(5.6及以上版本)MySQL数据库慢查询日志存储路径
  • long_query_time:慢查询阈值,当查询时间多于设定的阈值时,记录日志
  • log_queries_not_using_indexes:是否将未使用索引的查询也被记录到慢查询日志中
  • log_output:日志存储方式。log_output='FILE' 表示将日志存入文件,默认值是 FILElog_output='TABLE' 表示将日志存入数据库,这样日志信息就会被写入到 mysql.slow_log 表中。MySQL 支持同时两种日志存储方式,配置的时候以逗号隔开即可,如:log_output='FILE,TABLE'。日志记录到系统的专用日志表中,要比记录到文件耗费更多的系统资源,因此对于需要启用慢查询日志,又需要能够获得更高的系统性能,那么建议优先记录到文件

修改 /etc/my.cnf 可以使配置永久生效,但是不能及时生效,及时生效还需重启 Mysql,这在生产环境中是不可能的,所以还可以通过修改变量及时生效,不过不是永久的,Mysql 重启后就会恢复成 /etc/my.cnf 中的配置

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
# 查询是否开启慢查询
mysql> show variables like '%slow_query_log%';
+---------------------+-----------------------------------------------+
| Variable_name | Value |
+---------------------+-----------------------------------------------+
| slow_query_log | OFF |
| slow_query_log_file | /home/WDPM/MysqlData/mysql/DB-Server-slow.log |
+---------------------+-----------------------------------------------+
2 rows in set (0.00 sec)

# 开启慢查询
mysql> set global slow_query_log=1;
Query OK, 0 rows affected (0.09 sec)

mysql> show variables like 'slow_query_log%';
+---------------------+-----------------------------------------------+
| Variable_name | Value |
+---------------------+-----------------------------------------------+
| slow_query_log | ON |
| slow_query_log_file | /home/WDPM/MysqlData/mysql/DB-Server-slow.log |
+---------------------+-----------------------------------------------+
2 rows in set (0.00 sec)

# 查询慢查询日志记录阈值
mysql> show variables like 'long_query_time';
+-----------------+-----------+
| Variable_name | Value |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)

# 设置新的阈值
mysql> set global long_query_time=5;
Query OK, 0 rows affected (0.00 sec)

# 新的阈值在新的连接中才会生效,这里需要断开重连或者使用新的连接查询
mysql> show variables like 'long_query_time';
+-----------------+-----------+
| Variable_name | Value |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)

# 查询是否将未使用索引的查询也被记录到慢查询日志中
mysql> show variables like 'log_queries_not_using_indexes';
+-------------------------------+-----------+
| Variable_name | Value |
+-------------------------------+-----------+
| log_queries_not_using_indexes | ON |
+-------------------------------+-----------+
1 row in set (0.00 sec)

# 查询日志存储方式
mysql> show variables like 'log_output';
+-----------------+-----------+
| Variable_name | Value |
+-----------------+-----------+
| log_output | FILE |
+-----------------+-----------+
1 row in set (0.00 sec)

# 查询有多少条慢查询记录
mysql> show global status like '%Slow_queries%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Slow_queries | 2104 |
+---------------+-------+
1 row in set (0.00 sec)

慢查询日志分析

慢查询日志分析工具基本分为两种,一种是 Mysql 自带的 mysqldumpslow 一种是第三方的 pt-query-digest

mysqldumpslow

执行 mysqldumpslow --help 查看相关命令信息

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
[root@DB-Server ~]# mysqldumpslow --help
Usage: mysqldumpslow [ OPTS... ] [ LOGS... ]

Parse and summarize the MySQL slow query log. Options are

--verbose verbose
--debug debug
--help write this text to standard output

-v verbose
-d debug
-s ORDER what to sort by (al, at, ar, c, l, r, t), 'at' is default
al: average lock time
ar: average rows sent
at: average query time
c: count
l: lock time
r: rows sent
t: query time
-r reverse the sort order (largest last instead of first)
-t NUM just show the top n queries
-a don't abstract all numbers to N and strings to 'S'
-n NUM abstract numbers with at least n digits within names
-g PATTERN grep: only consider stmts that include this string
-h HOSTNAME hostname of db server for *-slow.log filename (can be wildcard),
default is '*', i.e. match all
-i NAME name of server instance (if using mysql.server startup script)
-l don't subtract lock time from total time
  • -s:是表示按照何种方式排序
    • c:查询次数
    • l:锁定时间
    • r:返回行数
    • t:查询时间
    • al:平均锁定时间
    • ar:平均返回行数
    • at:平均查询时间
  • -t:表示 top n,返回前 n 条数据
  • -g:匹配一个查询,可以匹配正则,忽略大小写
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
# 返回记录集最多的10个SQL。
> mysqldumpslow -s r -t 10 /database/mysql/mysql06_slow.log

# 访问次数最多的10个SQL
> mysqldumpslow -s c -t 10 /database/mysql/mysql06_slow.log

# 按照时间排序的前10条里面含有左连接的查询语句
> mysqldumpslow -s t -t 10 -g “left join” /database/mysql/mysql06_slow.log

# 使用这些命令时结合 | 和 more 使用 ,否则有可能出现刷屏的情况。
mysqldumpslow -s r -t 20 /mysqldata/mysql/mysql06-slow.log | more

# 取出一天时间的慢查询日志
awk '/# Time: 2024-10-27/,/# Time: 2024-10-28/' DB-Server-slow.log > DB-Server-slow.log.20181114

# 取出 2024-10-28 4点到6点之间两个小时的数据
awk '/# Time: 2024-10-28T04/,/# Time: 2024-10-28T06/' DB-Server-slow.log > slow_04_06.log

pt-query-digest

pt-query-digest 是 Percona Toolkit 工具包中的一种,Percona Toolkit 用于执行各种难以手动执行的 MySQL、MongoDB 和系统任务

Percona Toolkit

pt-query-digest 是一个 perl 语言编写的脚本,所以要使用 pt-query-digest 需要先安装 perl

Windows 下安装

草莓 Perl 下载安装适用于 windows 环境的 Perl

strawberryperl.com

然后再将 pt-query_digest 脚本 另存为 pt-query-digest.pl

Linux 下安装

可以直接安装 Percona Toolkit 完整的工具包

1
2
$ apt-get update
$ apt-get install -y percona-toolkit

或者去 percona 下载页 下载指定版本的工具包

percona downloads

或者安装带有 Percona Toolkit 的独立容器

1
2
3
4
$ docker run --rm -it \
-v /path/to/slow/log/on/host:/logs \
percona/percona-toolkit \
pt-query-digest /logs/slow.log

使用

参数说明:pt-query-digest --help

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
--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);其他所有服务器均被忽略

具体用法:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
# 直接分析慢查询文件
pt-query-digest slow.log > slow_report.log

# 分析最近12小时内的查询
pt-query-digest --since=12h slow.log > slow_report2.log

# 分析指定时间范围内的查询
pt-query-digest slow.log --since '2017-01-07 09:30:00' --until '2017-01-07 10:00:00' > slow_report3.log

# 分析指含有select语句的慢查询
pt-query-digest --filter '$event->{fingerprint} =~ m/^select/i' slow.log> slow_report4.log

# 针对某个用户的慢查询
pt-query-digest --filter '($event->{user} || "") =~ m/^root/i' slow.log> slow_report5.log

# 查询所有所有的全表扫描或 full join 的慢查询
pt-query-digest --filter '(($event->{Full_scan} || "") eq "yes") ||(($event->{Full_join} || "") eq "yes")' slow.log> slow_report6.log

# 把查询保存到 test.query_review 表
pt-query-digest --user=root –password=abc123 --review h=localhost,D=test,t=query_review --create-review-table slow.log

# 把查询保存到 test.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

# 通过 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

# 分析 binlog
mysqlbinlog mysql-bin.000093 > mysql-bin000093.sql
pt-query-digest --type=binlog mysql-bin000093.sql > slow_report10.log

# 分析 general log
pt-query-digest --type=genlog localhost.log > slow_report11.log

输出结果

第一部分:总体统计结果

  • Overall:总共有多少条查询
  • Time range:查询执行的时间范围
  • unique:唯一查询数量,即对查询条件进行参数化以后,总共有多少个不同的查询
  • total:总计 min:最小 max:最大 avg:平均
  • **95%**:把所有值从小到大排列,位置位于 95% 的那个数,这个数一般最具有参考价值
  • median:中位数,把所有值从小到大排列,位置位于中间那个数
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
# 该工具执行日志分析的用户时间,系统时间,物理内存占用大小,虚拟内存占用大小
# 340ms user time, 140ms system time, 23.99M rss, 203.11M vsz
# 工具执行时间
# Current date: Fri Nov 25 02:37:18 2016
# 运行分析工具的主机名
# Hostname: localhost.localdomain
# 被分析的文件名
# Files: slow.log
# 语句总数量,唯一的语句数量,QPS,并发数
# Overall: 2 total, 2 unique, 0.01 QPS, 0.01x concurrency ________________
# 日志记录的时间范围
# Time range: 2016-11-22 06:06:18 to 06:11:40
# 属性 总计 最小 最大 平均 95% 标准 中等
# Attribute total min max avg 95% stddev median
# ============ ======= ======= ======= ======= ======= ======= =======
# 语句执行时间
# Exec time 3s 640ms 2s 1s 2s 999ms 1s
# 锁占用时间
# Lock time 1ms 0 1ms 723us 1ms 1ms 723us
# 发送到客户端的行数
# Rows sent 5 1 4 2.50 4 2.12 2.50
# select语句扫描行数
# Rows examine 186.17k 0 186.17k 93.09k 186.17k 131.64k 93.09k
# 查询的字符数
# Query size 455 15 440 227.50 440 300.52 227.50

第二部分:查询分组统计结果

  • Rank:所有语句的排名,默认按查询时间降序排列,通过 --order-by 指定
  • Query ID:语句的 ID,(去掉多余空格和文本字符,计算hash值)
  • Response:总的响应时间
  • time:该查询在本次分析中总的时间占比
  • calls:执行次数,即本次分析总共有多少条这种类型的查询语句
  • R/Call:平均每次执行的响应时间
  • V/M:分数比例(Volume/Metric)。表示在查询的 消耗资源的表现 间的得分对比
  • Item:查询对象
1
2
3
4
5
# Profile
# Rank Query ID Response time Calls R/Call V/M Item
# ==== ================== ============= ===== ====== ===== ===============
# 1 0xF9A57DD5A41825CA 2.0529 76.2% 1 2.0529 0.00 SELECT
# 2 0x4194D8F83F4F9365 0.6401 23.8% 1 0.6401 0.00 SELECT wx_member_base

第三部分:每一种查询的详细统计结果

  • Query 1:对应上面 Rank 的 1
    • 0 QPS:查询每秒执行次数 (Queries Per Second)。这里为 0,意味着查询的频率较低
    • 0x concurrency:并发系数,表示该查询与其他查询在执行期间的重叠度
    • ID:对应上面的 Query ID
    • at byte 802:该查询在日志文件中的偏移位置
  • Scores: V/M:分数比例(Volume/Metric)。表示在查询的 消耗资源的表现 间的得分对比
  • pct:该指标占所有查询时间的百分比
  • total:查询执行的总和(以各指标的度量单位)
  • min:最小值
  • max:最大值
  • avg:平均值
  • **95%**:95% 的查询时间都在该数值以下
  • stddev:标准差,表示该值的波动范围
  • median:中位数
  • Count:查询的总执行次数
  • Exec time:查询占用时间
  • Lock time:锁定时间
  • Rows sent:查询返回的行数
  • Rows examine:被扫描的行数
  • Query size:查询文本的字节大小,15 字节,占所有查询的 3%
  • Databases:查询所针对的数据库,这里是 test 数据库
  • Hosts:执行查询的主机地址,这里是 192.168.8.1
  • Users:执行查询的用户,这里是 mysql
  • Query_time distribution:查询时间分布,通过 # 来表示指定范围内的执行耗时分布情况
  • **EXPLAIN /*!50100 PARTITIONS*/**:实际查询内容
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
# Query 1: 0 QPS, 0x concurrency, ID 0xF9A57DD5A41825CA at byte 802 ______
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2016-11-22 06:11:40
# Attribute pct total min max avg 95% stddev median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count 50 1
# Exec time 76 2s 2s 2s 2s 2s 0 2s
# Lock time 0 0 0 0 0 0 0 0
# Rows sent 20 1 1 1 1 1 0 1
# Rows examine 0 0 0 0 0 0 0 0
# Query size 3 15 15 15 15 15 0 15
# String:
# Databases test
# Hosts 192.168.8.1
# Users mysql
# Query_time distribution
# 1us
# 10us
# 100us
# 1ms
# 10ms
# 100ms
# 1s ################################################################
# 10s+
# EXPLAIN /*!50100 PARTITIONS*/
select sleep(2)\G