MySQL慢查询功能详解

有人的地方就有江湖，数据库也是，sql优化这个问题，任重道远，我们总是禁不住有烂sql。怎么办呢，还好各大数据库都有相关烂sql的收集功能，而MySQL的慢查询收集也是异曲同工，配合分析sql的执行计划，这个优化就有了搞头了。

开启MySQL慢查询日志

1.查看当前慢查询设置情况

#查看慢查询时间，默认10s，建议降到1s或以下， mysql> show variables like "long_query_time"; +-----------------+----------+ | Variable_name  | Value    | +-----------------+----------+ | long_query_time | 1.000000 | +-----------------+----------+ 1 row in set (0.00 sec) #查看慢查询配置情况 mysql> show variables like "%slow%"; +-----------------------------------+----------------------+ | Variable_name                    | Value                | +-----------------------------------+----------------------+ | log_slow_admin_statements        | OFF                  | | log_slow_filter                  |                      | | log_slow_rate_limit              | 1                    | | log_slow_rate_type                | session              | | log_slow_slave_statements        | OFF                  | | log_slow_sp_statements            | ON                  | | log_slow_verbosity                |                      | | max_slowlog_files                | 0                    | | max_slowlog_size                  | 0                    | | slow_launch_time                  | 2                    | | slow_query_log                    | ON                  | | slow_query_log_always_write_time  | 10.000000            | | slow_query_log_file              | /tmp/slow_querys.log | | slow_query_log_use_global_control |                      | +-----------------------------------+----------------------+ 14 rows in set (0.01 sec)

其中，slow_query_log的值是on就是已开启功能了。

2.如何开启慢查询功能 方法一：在服务器上找到mysql的配置文件my.cnf , 然后再mysqld模块里追加一下内容，这样的好处是会一直生效，不好就是需要重启mysql进程。

vim my.cnf [mysqld] slow_query_log = ON #定义慢查询日志的路径 slow_query_log_file = /tmp/slow_querys.log #定义查过多少秒的查询算是慢查询，我这里定义的是1秒，5.6之后允许设置少于1秒，例如0.1秒 long_query_time = 1 #用来设置是否记录没有使用索引的查询到慢查询记录,默认关闭,看需求开启,会产生很多日志,可动态修改 #log-queries-not-using-indexes 管理指令也会被记录到慢查询。比如OPTIMEZE TABLE, ALTER TABLE,默认关闭,看需求开启,会产生很多日志,可动态修改 #log-slow-admin-statements

然后重启mysql服务器即可，这是通过一下命令看一下慢查询日志的情况：

tail -f /tmp/slow_querys.log

方法二：通过修改mysql的全局变量来处理，这样做的好处是，不用重启mysql服务器，登陆到mysql上执行一下sql脚本即可，不过重启后就失效了。

#开启慢查询功能，1是开启，0是关闭 mysql> set global slow_query_log=1; #定义查过多少秒的查询算是慢查询，我这里定义的是1秒，5.6之后允许设置少于1秒，例如0.1秒 mysql> set global long_query_time=1; #定义慢查询日志的路径 mysql> set global slow_query_log_file='/tmp/slow_querys.log'; #关闭功能：set global slow_query_log=0; 然后通过一下命令查看是否成功 mysql> show variables like 'long%'; mysql> show variables like 'slow%'; #设置慢查询记录到表中 #set global log_output='TABLE';

当然了，你也可以两者合一，一方面不用重启mysql进程就能生效，另一方面也不用怕重启后参数失效，效果也是一致的。

特别要注意的是long_query_time的设置，5.6之后支持设置低于0.1秒，所以记录的详细程度，就看你自己的需求，数据库容量比较大的，超过0.1秒还是比较多，所以就变得有点不合理了。

慢查询日志的记录定义

直接查看mysql的慢查询日志分析，比如我们可以tail -f  slow_query.log查看里面的内容

tail -f  slow_query.log # Time: 110107 16:22:11 # User@Host: root[root] @ localhost [] # Query_time: 9.869362 Lock_time: 0.000035 Rows_sent: 1 Rows_examined: 6261774 SET timestamp=1294388531; select count(*) from ep_friends;

字段意义解析：

第一行,SQL查询执行的时间 第二行,执行SQL查询的连接信息，用户和连接IP 第三行,记录了一些我们比较有用的信息，如下解析     Query_time,这条SQL执行的时间,越长则越慢     Lock_time,在MySQL服务器阶段(不是在存储引擎阶段)等待表锁时间     Rows_sent,查询返回的行数     Rows_examined,查询检查的行数，越长就当然越费时间

第四行,设置时间戳，没有实际意义，只是和第一行对应执行时间。

第五行及后面所有行（第二个# Time:之前）,执行的sql语句记录信息，因为sql可能会很长。

分析慢查询的软件

虽然慢查询日志已经够清晰，但是往往我们的日志记录到的不是只有一条sql，可能有很多很多条，如果不加以统计，估计要看到猴年马月，这个时候就需要做统计分析了。

方法一：使用mysql程序自带的mysqldumpslow命令分析，例如： mysqldumpslow -s c -t 10 /tmp/slow-log 这会输出记录次数最多的10条SQL语句，得出的结果和上面一般慢查询记录的格式没什么太大差别，这里就不展开来详细解析了。

参数解析： -s：是表示按照何种方式排序，子参数如下：

    c、t、l、r：分别是按照记录次数、时间、查询时间、返回的记录数来排序，

    ac、at、al、ar：表示相应的倒叙；

-t：返回前面多少条的数据，这里意思就是返回10条数据了（也可以说是前十）

-g：后边可以写一个正则匹配模式，大小写不敏感的，比如：     /path/mysqldumpslow -s r -t 10 /tmp/slow-log，得到返回记录集最多的10个查询。     /path/mysqldumpslow -s t -t 10 -g “left join” /tmp/slow-log，得到按照时间排序的前10条里面含有左连接的查询语句。

方法二：使用pt(Percona Toolkit)工具的pt-query-digest进行统计分析。这个是由Percona公司出品的一个用perl编写的脚本，只有安装上pt工具集才会存在，有兴趣的朋友就要先安装pt工具了。直接分析慢查询文件，执行如下：

pt-query-digest slow_querys.log >t.txt

因为记录里还是可能有很多sql在，看起来还是费劲，所以建议输出到文件来看了。输出的信息会分成三部分，

第一部分：总体统计结果

# 580ms user time, 0 system time, 35.46M rss, 100.01M vsz # Current date: Wed Jul 19 14:32:40 2017 # Hostname: yztserver1 # Files: slow_querys.log # Overall: 2.63k total, 36 unique, 0.03 QPS, 0.03x concurrency ___________ # Time range: 2017-07-18T03:17:17 to 2017-07-19T06:30:18 # Attribute          total    min    max    avg    95%  stddev  median # ============    ======= ======= ======= ======= ======= ======= ======= # Exec time          3145s      1s      5s      1s      2s  258ms      1s # Lock time          677ms      0    64ms  257us  260us    2ms  144us # Rows sent          8.44k      0  5.50k    3.29    0.99  108.92    0.99 # Rows examine      1.06G      0  2.12M 421.02k 619.64k 155.33k 419.40k # Rows affecte          0      0      0      0      0      0      0 # Bytes sent        9.00M      11  6.24M  3.51k  13.78k 119.76k  65.89 # Query size      735.85k      6  2.19k  286.72  463.90  128.05  246.02

记录这个慢日志文件里面的所有慢查询统计信息，通常粗略看看就好了:

Overall: 这个文件里总共有多少条查询，上例为总共2.63k个查询，也就是2.63k条慢查询。 Time range: 查询执行的时间范围。 unique: 唯一查询数量，即对查询条件进行参数化以后，统计的总共有多少个不同的查询，该例为36。也就是说这2.63K条慢查询，实际归类为36条。

Attribute：属性解析，其他子项：

    total: 总计，min:最小，max: 最大，avg:平均，

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

    median: 中位数，把所有值从小到大排列，位置位于中间那个数。

其他就字面意思，去翻译一下就好。

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

# Profile # Rank Query ID          Response time  Calls R/Call V/M  Item # ==== ================== =============== ===== ====== ===== ============= #    1 0x8965CC929FB1C7B2 2080.0546 66.1%  1816 1.1454  0.03 SELECT 1 #    2 0x9C57D04CEA1970B4  228.4754  7.3%  131 1.7441  0.10 SELECT 2 #    3 0x94B4D7AA44982464  138.5964  4.4%  112 1.2375  0.05 SELECT 3 #    4 0x6BD09392D1D0B5D7  84.1681  2.7%    70 1.2024  0.03 SELECT 4 #    5 0x1E9926677DBA3657  81.2260  2.6%    68 1.1945  0.03 SELECT 5 #    6 0xBBCE31227D8C6A93  69.6594  2.2%    56 1.2439  0.05 SELECT 6 #    7 0x9A691CB1A14640F4  60.4517  1.9%    51 1.1853  0.04 SELECT 7 #    8 0xDA99A20C8BE81B9C  55.7751  1.8%    46 1.2125  0.05 SELECT 8 #    9 0x1F53AC684A365326  55.6378  1.8%    45 1.2364  0.03 SELECT 9_ #  10 0x664E0C18531443A5  38.6894  1.2%    31 1.2480  0.05 SELECT way_bill_main #  11 0xF591153EC390D8CA  32.5370  1.0%    28 1.1620  0.01 SELECT way_bill_main #  12 0xA3A82D5207F1BC2E  24.6582  0.8%    20 1.2329  0.06 SELECT way_bill_main #  13 0xFCED276145371CE4  22.2543  0.7%    18 1.2363  0.05 SELECT way_bill_main #  14 0x4895DF4252D5A600  21.3184  0.7%    17 1.2540  0.07 SELECT way_bill_main #  16 0xA4DD833DF8C96D04  14.6107  0.5%    13 1.1239  0.01 SELECT way_bill_main #  17 0x0426A3C3538CBBA8  13.9799  0.4%    13 1.0754  0.00 SELECT way_bill_main #  18 0x2C52F334EF3D8D2D  12.5960  0.4%    10 1.2596  0.03 SELECT way_bill_main # MISC 0xMISC              110.2030  3.5%    83 1.3277  0.0 <19 ITEMS>

这部分对查询进行参数化并分组，然后对各类查询的执行情况进行分析，结果按总执行时长，从大到小排序，恕我改了些显示。 Response: 总的响应时间。 time: 该查询在本次分析中总的时间占比。 calls: 执行次数，即本次分析总共有多少条这种类型的查询语句。 R/Call: 平均每次执行的响应时间。 Item : 查询对象

第三部分：每一种查询的详细统计结果，这是其中一个

# Query 1: 0.02 QPS, 0.02x concurrency, ID 0x8965CC929FB1C7B2 at byte 868609 # This item is included in the report because it matches --limit. # Scores: V/M = 0.03 # Time range: 2017-07-18T03:17:56 to 2017-07-19T06:30:18 # Attribute    pct  total    min    max    avg    95%  stddev  median # ============ === ======= ======= ======= ======= ======= ======= ======= # Count        69    1816 # Exec time    66  2080s      1s      4s      1s      1s  189ms      1s # Lock time    51  349ms    67us    19ms  192us  194us  760us  144us # Rows sent    21  1.77k      1      1      1      1      0      1 # Rows examine  71 771.37M 262.54k 440.03k 434.96k 419.40k  24.34k 419.40k # Rows affecte  0      0      0      0      0      0      0      0 # Bytes sent    1 120.49k      65      68  67.94  65.89    0.35  65.89 # Query size    60 443.31k    248    250  249.97  246.02    0.00  246.02 # String: # Databases    ytttt # Hosts        10.25.28.2 # Last errno  0 # Users        gztttttt # Query_time distribution #  1us #  10us # 100us #  1ms #  10ms # 100ms #    1s  ################################################################ #  10s+ # Tables #    SHOW TABLE STATUS FROM `ytttt` LIKE 'way_bill_main'\G #    SHOW CREATE TABLE `ytttt`.`way_bill_main`\G #    SHOW TABLE STATUS FROM `ytttt` LIKE 'scheduler_task'\G #    SHOW CREATE TABLE `ytttt`.`scheduler_task`\G # EXPLAIN /*!50100 PARTITIONS*/ SELECT COUNT(1) FROM 1 as w inner join  .....此处省略。。。

这部分的上面一部分和第一部分信息类似，统计该记录sql的总运行效率信息，下面一部分的解析如下：

Databases: 库名 Users: 各个用户执行的次数（占比），现在只有一个用户，因为我授权的就是一个库一个独立用户。 Query_time distribution : 查询时间分布, 长短体现区间占比，本例中基本上都是1s。 Tables: 查询中涉及到的表 Explain: 示例，也就是这条sql本身的信息。

后面其他信息也大体和这个类似，只是显示不同的sql信息而已，都属于这个第三部分。

pt-query-digest参数说明：

--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.分析最近12小时内的查询：pt-query-digest  --since=12h  slow.log > slow_report2.log2.分析指定时间范围内的查询：pt-query-digest slow.log --since '2014-04-17 09:30:00' --until '2014-04-17  10:00:00'>>slow_report3.log3.分析指含有select语句的慢查询pt-query-digest--filter 'event->{Full_scan} || "") eq "yes") ||((

其实pt-query-digest虽然信息很多，但是输出的有用信息不见得就比mysqldumpslow好很多，反而眼花缭乱的，而且还要装多个工具才能用。不过可以甩问题给开发看到效率有多差也算是一个好事，可以说清楚着个sql执行了多少次慢查询，所以实际使用上还是见仁见智，自己看着办。

题外话 一般慢查询日志解决不了问题的话，就建议开查询日志general-log来跟踪sql了 大体和上面操作差不多，先查看当前状态 show variables like 'general%'; 可以在my.cnf里添加 general-log = 1开启（0关闭） log = /log/mysql_query.log路径 也可以设置变量那样更改 set global general_log=1开启（0关闭）