MySQL慢查询日志

慢查询日志可以把超过参数 long_query_time 时间的所有SQL语句记录进来，帮助优化有问题的SQL语句，慢查询日志默认是不被开启的，如果需要，可以手动开启。

启用慢查询日志

# vim /etc/my.cnf

slow_query_log = 1
slow_query_log_file = /usr/local/mysql/data/slow.log

root@localhost 13:13: [(none)]> show variables like 'slow_query%';
+---------------------+--------------------------------+
| Variable_name       | Value                          |
+---------------------+--------------------------------+
| slow_query_log      | ON                             |
| slow_query_log_file | /usr/local/mysql/data/slow.log |
+---------------------+--------------------------------+
2 rows in set (0.01 sec)

long_query_time默认是 10s，从 MySQL 5.1 开始，该参数就以微妙为单位记录SQL语句的运行时间了，之前仅仅只能使用秒为单位记录。建议生产线上慢查询日志时间的设置可以不用太小，小数点后面一位数就可以了（0.1s-0.5s之间都可以）。

在生产线上我们通常会将分析慢查询日志的工作写成脚本，在计划任何中定期执行（比如每天0点），然后将抓取到的慢SQL生成报表的形式，往老大、开发、DBA、高级运维那里各发一份，然后一块儿来讨论一下这个问题。

root@localhost 13:37: [(none)]> set global long_query_time = 0.1;
Query OK, 0 rows affected (0.00 sec)

 

如何查看慢查询日志呢？随着数据量的增大，业务增多，可能慢查询日志中记录的慢SQL语句就会越来越多。通过 vi 或 cat 命令查看不能直观地反映出有哪些慢SQL。当然了，也可以用MySQL带的 mysqldumpslow 命令来查看，但它在生产线上并不是那么方便的分析。这里推荐一下 Percona 的 percona-toolkit 工具。我们通过命令集合下的 pt-query-digest 命令来捕获线上的慢SQL语句，对其进行分析。以一种生成慢SQL报告的形式，来帮助进行优化SQL的工作。

下载地址： https://www.percona.com/downloads/percona-toolkit/3.0.11/binary/redhat/

# rpm -ivh http://dl.fedoraproject.org/pub/epel/epel-release-latest-7.noarch.rpm

# yum -y install perl-DBD-MySQL perl-Config-Tiny perl-Log-Dispatch perl-Parallel-ForkManager perl-Config-IniFiles ncftp perl-Params-Validate perl-CPAN perl-Test-Mock-LWP.noarch perl-LWP-Authen-Negotiate.noarch perl-devel perl-ExtUtils-CBuilder perl-ExtUtils-MakeMaker

# wget  https://www.percona.com/downloads/percona-toolkit/3.0.11/binary/tarball/percona-toolkit-3.0.11_x86_64.tar.gz

# tar -zxf percona-toolkit-3.0.11_x86_64.tar.gz

以下是pt-query-digest的一些重要参数的含义：

--create-review-table，当使用--review参数把分析结果输出到表中时，如果没有表就自动创建

--create-history-table，当使用--history参数把分析结果输出到表中时，如果没有表就自动创建。

--filter，对输入的慢查询按指定的字符串进行匹配过滤后再进行分析。

--limit，限制输出结果百分比或数量，默认值是20，即将最慢的20条语句输出，如果是50%，则按总响应时间占比从大到小排序，输出到总和达到50%位置截止。

--host，数据库服务器地址。

--user，数据库用户名。

--password，数据库用户密码。

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

生成慢SQL报告

# /usr/local/percona-toolkit-3.0.11/bin/pt-query-digest --since=24h /usr/local/mysql/data/slow.log > query.log

查看内容

# cat query.log

# 140ms user time, 10ms system time, 25.95M rss, 220.38M vsz
# Current date: Wed Sep 19 14:32:57 2018
# Hostname: db161
# Files: /usr/local/mysql/data/slow.log
# Overall: 12 total, 7 unique, 0.21 QPS, 0.00x concurrency _______________
# Time range: 2018-09-19T05:41:55 to 2018-09-19T05:42:53
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time          108ms    24us   101ms     9ms     5ms    28ms   194us
# Lock time            1ms       0   555us    94us   108us   141us    63us
# Rows sent            102       0      15    8.50   13.83    6.58   13.83
# Rows examine          99       0      15    8.25   13.83    6.87   13.83
# Query size           264      13      47      22   31.70    9.28   16.81

# Profile
# Rank Query ID                         Response time Calls R/Call V/M   I
# ==== ================================ ============= ===== ====== ===== =
#    1 0x898255B1BE4F8C3044AE35A1828...  0.1008 93.7%     1 0.1008  0.00 ADMIN INIT DB
#    2 0xE5FE37ACE952C6483141B7B8B3F...  0.0050  4.7%     1 0.0050  0.00 INSERT emp
# MISC 0xMISC                            0.0018  1.6%    10 0.0002   0.0 <5 ITEMS>

# Query 1: 0 QPS, 0x concurrency, ID 0x898255B1BE4F8C3044AE35A182869033 at byte 1019
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2018-09-19T05:42:00
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          8       1
# Exec time     93   101ms   101ms   101ms   101ms   101ms       0   101ms
# Lock time      0       0       0       0       0       0       0       0
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       0       0       0       0       0       0       0
# Query size    11      30      30      30      30      30       0      30
# String:
# Databases    scott
# Hosts        localhost
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms
#  10ms
# 100ms  ################################################################
#    1s
#  10s+
administrator command: Init DB\G

# Query 2: 0 QPS, 0x concurrency, ID 0xE5FE37ACE952C6483141B7B8B3FBF3F7 at byte 2291
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2018-09-19T05:42:51
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          8       1
# Exec time      4     5ms     5ms     5ms     5ms     5ms       0     5ms
# Lock time     48   555us   555us   555us   555us   555us       0   555us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       0       0       0       0       0       0       0
# Query size    17      47      47      47      47      47       0      47
# String:
# Databases    scott
# Hosts        localhost
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `scott` LIKE 'emp'\G
#    SHOW CREATE TABLE `scott`.`emp`\G
insert into emp(empno,ename) values(8000,'qkc')\G

下面来将这段内容分开来看一下

Overall：总共有多少条查询，上面显示总共有 12 条。

unique：唯一查询数，即对查询条件进行参数化后，总共有多少个不同的查询，这里是 7 个。

Time range：查询执行的时间范围。

再看属性这边，总计时间 total（108ms）、最小时间 min（24us）、最大时间 max（101ms）、平均时间 avg（9ms）。

95%：把所有值从小到大排列，位置位于 95% 的那个数一般最具有参考价值。

median：中位数，把所有值从小到大排列，位置位于中间的数。

# 140ms user time, 10ms system time, 25.95M rss, 220.38M vsz
# Current date: Wed Sep 19 14:32:57 2018

# 140ms user time, 10ms system time, 25.95M rss, 220.38M vsz
# Current date: Wed Sep 19 14:32:57 2018
# Hostname: db161
# Files: /usr/local/mysql/data/slow.log
# Overall: 12 total, 7 unique, 0.21 QPS, 0.00x concurrency _______________
# Time range: 2018-09-19T05:41:55 to 2018-09-19T05:42:53
# Attribute          total     min     max     avg     95%  stddev  median
# ============     ======= ======= ======= ======= ======= ======= =======
# Exec time          108ms    24us   101ms     9ms     5ms    28ms   194us
# Lock time            1ms       0   555us    94us   108us   141us    63us
# Rows sent            102       0      15    8.50   13.83    6.58   13.83
# Rows examine          99       0      15    8.25   13.83    6.87   13.83
# Query size           264      13      47      22   31.70    9.28   16.81

Response：总的响应时间。

time：该查询在本次分析中总的时间占比。

Calls：执行次数。

R/Call：平均每次执行的响应时间。

Item（最后一项）：查询对象，即具体的SQL语句。

Profile
# Rank Query ID                                            Response  time Calls  R/Call    V/M   Item
# ==== ================================ ============= ===== ====== ===== =
#    1 0x898255B1BE4F8C3044AE35A1828...  0.1008   93.7%   1   0.1008  0.00  ADMIN INIT DB
#    2 0xE5FE37ACE952C6483141B7B8B3F...  0.0050  4.7%     1   0.0050  0.00  INSERT emp
# MISC 0xMISC                                                  0.0018  1.6%    10  0.0002   0.0   <5 ITEMS>

Databases：库名。

Users：各个用户执行的次数（占比）

Query_time distribution：查询时间分布，长短体现区间占比，以下的例子中 1ms 以上的查询占有比例很高

# Query 2: 0 QPS, 0x concurrency, ID 0xE5FE37ACE952C6483141B7B8B3FBF3F7 at byte 2291
# This item is included in the report because it matches --limit.
# Scores: V/M = 0.00
# Time range: all events occurred at 2018-09-19T05:42:51
# Attribute    pct   total     min     max     avg     95%  stddev  median
# ============ === ======= ======= ======= ======= ======= ======= =======
# Count          8       1
# Exec time      4     5ms     5ms     5ms     5ms     5ms       0     5ms
# Lock time     48   555us   555us   555us   555us   555us       0   555us
# Rows sent      0       0       0       0       0       0       0       0
# Rows examine   0       0       0       0       0       0       0       0
# Query size    17      47      47      47      47      47       0      47
# String:
# Databases    scott
# Hosts        localhost
# Users        root
# Query_time distribution
#   1us
#  10us
# 100us
#   1ms  ################################################################
#  10ms
# 100ms
#    1s
#  10s+
# Tables
#    SHOW TABLE STATUS FROM `scott` LIKE 'emp'\G
#    SHOW CREATE TABLE `scott`.`emp`\G
insert into emp(empno,ename) values(8000,'qkc')\G