MySQL慢查询日志

The slow query log consists of SQL statements that took more than long_query_time seconds to execute and required at least min_examined_row_limit rows to be examined. The minimum and default values of long_query_time are 0 and 10, respectively. The value can be specified to a resolution of microseconds. For logging to a file, times are written including the microseconds part. For logging to tables, only integer times are written; the microseconds part is ignored.

By default, administrative statements are not logged, nor are queries that do not use indexes for lookups. This behavior can be changed using log_slow_admin_statements and log_queries_not_using_indexes, as described later.

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

long_query_time 默认值是 10 ,单位是 s,即默认是 10秒 。默认情况下,MySQL数据库并不会开启慢查询日志,需要手动设置这个参数。

通过慢查询日志,可以查找出哪些查询语句的执行效率很低,以便进行优化。一般建议开启,它对服务器性能的影响微乎其微,但是可以记录MySQL服务器上执行了很长时间的查询语句。慢查询日志可以帮助我们定位mysql性能问题所在。

MySQL慢查询日志

慢查询日志相关参数

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
slow_query_log : 是否启用慢查询日志,[1 | 0] 或者 [ON | OFF]
slow_query_log_file : MySQL数据库(5.6及以上版本)慢查询日志存储路径。
可以不设置该参数,系统则会默认给一个缺省的文件 HOST_NAME-slow.log
long_query_time : 慢查询的阈值,当查询时间超过设定的阈值时,记录该SQL语句到慢查询日志。
log_queries_not_using_indexes :设置为 ON ,可以捕获到所有未使用索引的SQL语句(不建议启用),默认为 OFF 。
log_slow_admin_statements : 是否将慢管理语句(例如ANALYZE TABLE和ALTER TABLE等)记录进慢查询日志中,默认为 OFF 。
log_output : 日志存储方式。
log_output='FILE',表示将日志存入文件,默认值是'FILE'。
log_output='TABLE',表示将日志存入数据库,这样日志信息就会被写入到 mysql.slow_log 表中。
MySQL数据库支持同时两种日志存储方式,配置的时候以逗号隔开即可,如:log_output='FILE,TABLE'。
日志记录到系统的专用日志表中,要比记录到文件耗费更多的系统资源,因此对于需要启用慢查询日志,又需要能够获得更高的系统性能,那么建议优先记录到文件。

5.6之前的版本,有些参数名字不一样:

1
log-slow-queries : MySQL数据库(5.6以下版本)慢查询日志存储路径。

开启日志

立即生效,重启失效

1
2
3
mysql> set global slow_query_log=ON;
mysql> set global slow_query_log_file='/xxx/mysql-slow.log';
mysql> set global long_query_time=1;

永久生效

修改 my.cnf

1
2
3
4
5
6
7
8
9
[mysqld]
slow_query_log = 1
slow_query_log_file = /xxx/mysql-slow.log
long_query_time = 1
# 也可以写成这种形式
slow-query-log = 1
slow-query-log-file = /xxx/mysql-slow.log
long-query-time = 1

重启mysql服务。

关闭日志

临时关闭,重启失效:

1
mysql> set global slow_query_log=OFF;

永久关闭,修改 my.cnf,重启mysql服务:

1
2
[mysqld]
slow_query_log = 0

MySQL慢查询日志分析

慢查询日志格式说明

打开慢查询日志 mysql-slow.log ,内容都是以下格式:

1
2
3
4
5
# Time: 2017-11-22T12:22:32.554299Z
# User@Host: www[www] @ [192.168.10.2] Id: 580785559
# Query_time: 24.354270 Lock_time: 0.000238 Rows_sent: 1 Rows_examined: 511156
SET timestamp=1511353352;
SELECT * FROM mo_user WHERE email = 'chxxx@hotmail.com' LIMIT 1;

其中参数说明如下:

  • log 记录的时间:# Time: 2017-11-22T12:22:32.554299Z
  • SQL 的执行主机:# User@Host: www[www] @ [192.168.10.2] Id: 580785559
  • SQL 的执行信息(执行时间(单位:s),锁时间,返回结果行数,查询总行数):# Query_time: 24.354270 Lock_time: 0.000238 Rows_sent: 1 Rows_examined: 511156;
  • SQL 执行发生的时间:SET timestamp=1511353352;
  • SQL 的执行内容:SELECT * FROM mo_user WHERE email = 'chxxx@hotmail.com' LIMIT 1;

新增参数log_timestamps说明

# Time: 2017-11-22T12:22:32.554299Z用的是 UTC 时间,国内标准时间是 CSTUTC 时间比 CST 时间慢8个小时。

This variable was added in MySQL 5.7.2. Before 5.7.2, timestamps in log messages were written using the local system time zone by default, not UTC. If you want the previous log message time zone default, set log_timestamps=SYSTEM.

根据官网介绍,在 MySQL 5.7.2 新增了 log_timestamps 这个参数,该参数主要是控制 error loggenera logslow log等等记录日志的显示时间参数。
5.7.2及其以后的版本,新增了该参数,该参数默认为 UTC ,这样会导致日志中记录的时间比中国这边的慢8个小时,使得查看日志不方便。解决方案,如下:

1
2
3
4
5
6
7
mysql> SHOW GLOBAL VARIABLES LIKE 'log_timestamps';
+----------------+--------+
| Variable_name | Value |
+----------------+--------+
| log_timestamps | UTC |
+----------------+--------+
mysql> SET GLOBAL log_timestamps=SYSTEM;

要想永久生效,就在 my.cnfmysqld段下,加入:

1
log_timestamps = SYSTEM

mysqldumpslow

mysqldumpslow 是MySQL自带的慢查询日志分析工具(perl脚本)。执行命令 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
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

参数说明:

  • -v、–verbose : 在详细模式下运行,打印有关该程序的更多信息。
  • -d、–debug : 在调试模式下运行。
  • –help : 显示帮助信息并退出程序
  • -s [sort_type] : sort_type 是信息排序的依据

    al:average lock time,按平均等待锁的时间排序
    ar:average rows sent,按平均发给客户端的行总数排序
    at:average query time,按平均查询时间排序
    c:count,按出现总次数排序
    l:lock time,按等待锁的时间排序
    r:rows sent,按扫描的行总数排序
    t:query time,按累计总耗费时间排序

  • -r : 倒序信息排序
  • -t NUM: 只显示前 n 个查询,降序
  • -a : 不把数字抽象为’N’,不把字符串抽象为’S’
  • -n NUM : 「abstract numbers with at least n digits within names」
  • -g PATTERN : 根据字符串筛选慢查询日志,可写正则匹配,大小写不敏感。
  • -h HOSTNAME : 根据服务器名称选择慢查询日志
  • -i NAME : 根据服务器 MySQL 实例名称选择慢查询日志
  • -l : 不要将总时间减去锁定时间

mysqldumpslow 分析的结果如下:

  • Count : 出现次数(Count)
  • Time : 执行最长时间(Time) 和 累计总耗费时间(Time)
  • Lock : 等待锁的时间(Lock)
  • Rows : 发送给客户端的行总数(Rows) 和 扫描的行总数(Rows)
  • root[root]@localhost : 用户
  • SHOW FULL … : SQL语句本身(抽象了格式, 比如 limit 1, 20 用 limit N,N 表示。’N’表示数字,’S’表示字符串)。

例子:
返回出现次数最多的10个SQL

mysqldumpslow -s c -t 10 mysql-slow.log

返回按照总时间排序的前10条里边含有左连接的SQL

mysqldumpslow -s t -t 10 -g “left join” mysql-slow.log

mysqlsla

mysqlsla是 hackmysql.com 推出的一款日志分析工具,Perl脚本(该网站还维护了 mysqlreport, mysqlidxchk 等比较实用的mysql工具)。
整体来说, 功能非常强大。数据报表,非常有利于分析慢查询的原因, 包括执行频率, 数据量, 查询消耗等。

但是,hackmysql.com官方已经在2015年1月份放弃了对 mysqlsla(项目地址)的维护,官方推荐用 Percona Toolkit。

安装

解决依赖关系

1
# yum install perl-DBI perl-DBD-MySQL

可能会遇到的问题:Can't locate ExtUtils/MakeMaker.pm,解决如下:

1
# yum install perl-ExtUtils-CBuilder perl-ExtUtils-MakeMaker

可能会遇到的问题:Can't locate Time/HiRes.pm in @INC,解决如下:

1
# yum install perl-Time-HiRes

下载mysqlsla

当前 mysqlsla 的最新版本为 2.03,到官网下载(官方链接已经失效),可以去这个 有效下载地址 下载。

编译安装

1
2
3
4
5
# tar xvfz mysqlsla-2.03.tar.gz
# cd mysqlsla-2.03
# perl Makefile.PL
# make
# make install

使用

1
2
3
4
# mysqlsla -lt slow mysql-slow.log
或者
# mysqlsla -lt slow mysql-slow.log -sf "+SELECT" -db dbName -top 10 -sort t_sum

参数意义 :

  • -lt :表示日志类型,有: slow, general, binary, msl, udl
  • -sf :[+-][TYPE],包括|不包括,过滤sql语句的类型 [TYPE]有 SELECT, CREATE, DROP, UPDATE, INSERT,例如 “+SELECT,INSERT”,不出现的默认是 - ,即不包括。
  • -db :要处理哪个库的日志。
  • -top :表示取按规则排序的前多少条。
  • -sort :按某种规则排序,t_sum 按总时间排序, c_sum 按总次数排序。c_sum_p : sql语句执行次数占总执行次数的百分比。

对慢查询日志文件的分析,最简化的调用方式如下:

1
# mysqlsla -lt slow [SlowLogFilePath] > [ResultFilePath]

格式说明如下:

  • 总查询次数 (queries total), 去重后的sql数量 (unique)
  • 输出报表的内容排序方式(sorted by)
  • 最重大的慢sql统计信息, 包括平均执行时间, 等待锁时间, 结果行的总数, 扫描的行总数。

  • Count: sql的执行次数及占总的slow log数量的百分比.
  • Time:执行时间, 包括总时间, 平均时间, 最小, 最大时间, 时间占总慢sql时间的百分比.
  • 95% of Time:去除最快和最慢的sql, 覆盖率占95%的sql的执行时间.
  • Lock Time:等待锁的时间.
  • 95% of Lock :95%的慢sql等待锁时间.
  • Rows sent:结果行统计数量, 包括平均, 最小, 最大数量.
  • Rows examined: 扫描的行数量.
  • Database:属于哪个数据库
  • Users:哪个用户,IP, 占到所有用户执行的sql百分比

  • Query abstract:抽象后的sql语句
  • Query sample:sql语句个例

pt-query-digest

percona-toolkit 工具介绍

percona-toolkit 是一组高级命令行工具的集合,用来执行各种通过手工执行非常复杂和麻烦的mysql和系统任务。这些任务包括:

  • 检查master和slave数据的一致性
  • 有效地对记录进行归档
  • 查找重复的索引
  • 对服务器信息进行汇总
  • 分析来自日志和tcpdump的查询
  • 当系统出问题的时候收集重要的系统信息

Percona Toolkit整个工具箱提供了非常多实用的工具,具体的使用方法可以参看 官方文档

percona-toolkit安装

安装 percona-toolkit 非常简单,到 官网 下载 .tar.gz 包:

1
2
# wget percona.com/get/percona-toolkit.tar.gz
# tar -zxvf percona-toolkit-2.2.5.tar.gz

然后依次执行下面的命令:

1
2
3
# perl Makefile.PL
# make
# make install

默认的会被安装在 /usr/local/bin 目录下。执行 man percona-toolkit 可以查看安装了哪些工具。

运行工具可能会遇到下面的错误:


这是因为缺少相应包,.pm包实际上是perl的包,运行下面的命令安装即可:

1
yum install -y perl-Time-HiRes

如果安装过程中出现 Error Downloading Packages 错误,尝试 yum clean all 后再安装。使用其Percona Toolkit中其他工具也可能会遇到类似的问题,按照提示安装相应的perl包就可以了。

问题:Can’t locate Digest/MD5.pm in @INC
解决:# yum install perl-Digest-MD5

问题:Can’t locate ExtUtils/MakeMaker.pm in @INC
解决:# yum install perl-ExtUtils-CBuilder perl-ExtUtils-MakeMaker

pt-query-digest使用

pt-query-digest 可以从普通MySQL日志,慢查询日志以及二进制日志中分析查询,甚至可以从 SHOW PROCESSLIST; 和MySQL协议的tcpdump中进行分析,如果没有指定文件,它从标准输入流(STDIN)中读取数据。

命令用法

1
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可以分析一段时间内的慢查询。

输出信息详情

最简单的用法如下:

1
# pt-query-digest mysql-slow.log

输出信息大致如下:

整个输出分为三大部分:

整体概要(Overall)

这个部分是一个大致的概要信息(类似loadrunner给出的概要信息),通过它可以对当前MySQL的查询性能做一个初步的评估,比如各个指标的最大值(max),平均值(min),95%分布值,中位数(median),标准偏差(stddev)。
这些指标有查询的执行时间(Exec time),锁占用的时间(Lock time),MySQL执行器需要检查的行数(Rows examine),最后返回给客户端的行数(Rows sent),查询的大小。

查询的汇总信息(Profile)

这个部分对所有 “重要” 的查询(通常是比较慢的查询)做了个一览表:


每个查询都有一个Query ID,这个ID通过Hash计算出来的。pt-query-digest 是根据这个所谓的Fingerprint来group by的。举例下面两个查询的Fingerprint是一样的都是 select * from table1 where column1 = ?,工具箱中也有一个与之相关的工具 pt-fingerprint

1
2
select * from table1 where column1 = 2
select * from table1 where column1 = 3
  • Rank整个分析中该“语句”的排名,一般也就是性能最常的。
  • Response time “语句”的响应时间以及整体占比情况。
  • Calls 该“语句”的执行次数。
  • R/Call 每次执行的平均响应时间。
  • V/M 响应时间的差异平均对比率。

在尾部有一行输出,显示了其他2个占比较低而不值得单独显示的查询的统计数据。

详细信息

这个部分会列出Profile表中每个查询的详细信息:(默认是按照总的Exec time排序,降序)

包括Overall中有的信息、查询响应时间的分布情况以及该查询 “入榜” 的理由,最底下会显示该查询SQL语句(真实显示,非抽象格式)。

用例示范

分析最近12小时内的查询

1
# pt-query-digest --since=12h mysql-slow.log > slow_report1.log

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

1
# pt-query-digest mysql-slow.log --since '2014-05-17 09:30:00' --until '2014-06-17 10:00:00' > slow_report2.log

分析只含有select语句的慢查询

1
# pt-query-digest --filter '$event->{fingerprint} =~ m/^select/i' mysql-slow.log> slow_report3.log

通过tcpdump抓取mysql的tcp协议数据,然后分析

1
2
# 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_report4.log

还可以跟一些过滤条件。详见 官方文档

另外结合一些第三方工具还能生成相应的报表。

建议 :当 slow log 很大的时候最好还是将日志文件移到其他机器上进行分析,避免分析时过度消耗该服务器资源。

参考:关于 MySQL 慢日志,你想知道的都在这