Mysql开启、查看慢查询日志

发表于 | 更新于 | 分类于 |
热度 ℃   |   字数统计: 2,403(字)   |   阅读时长: 10(分) |

前言

想要优化现有的数据库结构或者查询语句，首先要找到需要的优化的地方，不然就会出现费了很大精力优化却不达目的的情况，这就和上学考试一样，想要取得好的成绩，先要分析自己差在哪里，重点学习才会有快速的提升。

关于查询Mysql的瓶颈，或者说查询Mysql出现操作缓慢的问题，我们可以使用Mysql自带的慢查询日志来分析，优化不是改正错误，那种错误在开发过程中叫做BUG，伴随着软件开发工程师的一生，而优化是指在逻辑正确的前提下，让程序运行的更快更稳定，一般来说就是优化比较耗时的操作，提升用户体验。比如一个信息系统，如果输入账号密码后需要10分钟才能登录成功，我想基本上也不会有人使用了。

慢查询日志就是一种特殊的记录，用于统计Mysql操作过程中一些耗时的语句，生成文件或者表格，为优化Mysql操作提供分析数据，从名字也很好理解，慢查询日志就是记录一些查询的比较慢的记录，帮助使用者定位具体的问题，接下来就简单地描述一下慢查询日志是如何开启和查看的。

测试环境

Windows 10
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 7
Server version: 5.7.21-log MySQL Community Server (GPL)
Copyright (c) 2000, 2018, Oracle and/or its affiliates. All rights reserved.
Oracle is a registered trademark of Oracle Corporation and/or its affiliates. Other names may be trademarks of their respective owners.
Type ‘help;’ or ‘\h’ for help. Type ‘\c’ to clear the current input statement.

开启慢查询日志

修改过Mysql配置的小伙伴应该知道，Mysql的一些环境配置可以通过命令行直接修改，也可以修改配置文件后重新启动Mysql服务来生效，我们这次选择修改配置文件的方法，首先找到配置文件my.ini（Mysql5.7Windows版本，Linux版本应该叫my.cnf吧），一般在安装目录所在的ProgramData目录下，比如我的是在 C:/ProgramData/MySQL/MySQL Server 5.7 ，如果找不到可以下载一个叫Everything的软件搜一下（顺便安利一下，真的挺好用）。

用记事本或者其他编辑软件打开，搜索 long_query_time找到配置区域，其中有一些其他的配置，与慢查询无关已经剔除：

1
2
3
4
5
# General and Slow logging.
log-output=FILE
slow-query-log=1
slow_query_log_file="0491NPORIURNUYO-slow.log"
long_query_time=0.01

  • slow-query-log：慢查询日志的开关，1表示开启，0表示关闭。Mysql5.1之前貌似是默认关闭的，而我这个版本在安装完成后自动开启了，如果没有可以将其设置为1，重启服务后会自动开启
  • long_query_time：这个参数很关键，表示慢查询日志的阈值，花费时间超过这个值的sql语句才会被记录，单位是秒，这一点需要注意，网上有些文章说这个参数是毫秒，不知道是不是版本问题，使用时可以测试一下，经测试可以配置成小数
  • log-output：表示日志存储的方式。FILE 表示将日志存入文件，默认值是FILE，另外可以取值 TABLE ，表示将日志存入数据库表，当然也可以两者都选择，配成 FILE,TABLE 。需要注意的是将日志记录到数据库表中，需耗费更多的系统资源，建议优先记录到文件
  • log-slow_query_log_file：当配置将日志记录到文件中时，这个参数可以指定文件名，路径一般在配置文件的同级的Data目录下，比如我的是在C:/ProgramData/MySQL/MySQL Server 5.7/Data，当发现sql运行较慢时可以打开这个文件看一下

具体例子

  1. 首先我们将long_query_time设置为0.05，也就是记录查询时间超过50毫秒的sql操作，这是个很随意的值，具体的生产环境根据具体情况配置，重启Mysql服务使其生效

  2. 创建一张测试表格 slow_query_test

    1
    create table slow_query_test(id int, num int, money int);

  3. 然后创建一个存储过程，用来给数据表填充数据，命名为fill_slow_query_test

    1
    2
    3
    4
    5
    6
    7
    8
    9
    CREATE PROCEDURE `fill_slow_query_test`()
    BEGIN
        DECLARE i int default 1;

        WHILE i <= 100000 do
            insert into slow_query_test values(i, i, i);
            set i = i + 1;
        END WHILE;
    END

  4. 调用存储过程插入测试数并查询，得到以下结果

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    mysql> call fill_slow_query_test();
    Query OK, 1 row affected (24.45 sec)

    mysql> select * from  slow_query_test  where id = 9990;
    +------+------+-------+
    | id   | num  | money |
    +------+------+-------+
    | 9990 | 9990 |  9990 |
    +------+------+-------+
    1 row in set (0.09 sec)

  5. 通过观察结果可以发现，两次操作的时间都超过了0.05s，所以都应该被记录到慢查询日志日志中，打开日志查看内容

    1
    2
    3
    4
    5
    6
    7
    8
    9
    10
    11
    12
    13
    C:\Program Files\MySQL\MySQL Server 5.7\bin\mysqld.exe, Version: 5.7.21-log (MySQL Community Server (GPL)). started with:
    TCP Port: 3306, Named Pipe: (null)
    Time                 Id Command    Argument
    # Time: 2019-03-25T03:14:50.241968Z
    # User@Host: root[root] @ localhost [::1]  Id:     2
    # Query_time: 24.447215  Lock_time: 0.000364 Rows_sent: 0  Rows_examined: 0
    SET timestamp=1553483690;
    call fill_slow_query_test();
    # Time: 2019-03-25T03:15:27.862107Z
    # User@Host: root[root] @ localhost [::1]  Id:     2
    # Query_time: 0.050133  Lock_time: 0.000133 Rows_sent: 1  Rows_examined: 100000
    SET timestamp=1553483727;
    select * from  slow_query_test  where id = 9990;

日志中的内容与我们猜想的基本一致，但是还要多一些，首先前3行是Mysql服务启动的记录，接下来的是Mysql慢查询日志的正文，每组都通过3行注释分隔：

  • Time：记录执行操作时的日期和时间，默认没有包含时区信息，是标准的UTC时间
  • User@Host 记录执行操作的主机和用户，以及Mysql连接id等信息
  • Query_time 记录了查询消耗的时间，以及其他的一些操作信息
    接下来未被注释的内容就是真正执行的操作，包含当时的时间戳和具体执行的语句

简单优化

针对于上述的例子，我们可以运用上一篇文章《Mysql查询可通过给条件字段添加索引提高查询速度》 提到的方法，简单优化一下：

  1. 首先给id字段添加简单索引

    1
    2
    3
    mysql> ALTER TABLE slow_query_test ADD INDEX id_index(id);
    Query OK, 0 rows affected (0.14 sec)
    Records: 0  Duplicates: 0  Warnings: 0

  2. 然后使用相同的sql语句再次查询

    1
    2
    3
    4
    5
    6
    7
    mysql> select * from  slow_query_test  where id = 9990;
    +------+------+-------+
    | id   | num  | money |
    +------+------+-------+
    | 9990 | 9990 |  9990 |
    +------+------+-------+
    1 row in set (0.04 sec)

对比前后的查询我们发现，加了索引的表格查询耗时已经小于0.05s，所以该查询不会被记录到慢查询日志中了

慢查询日志格式化处理

有时面对慢查询日志文件内众多的数据确实无从下手，这是可以考虑使用mysql自带的mysqldumpslow工具来分析慢查询日志，该工具一般与mysql可执行文件在同一目录，比如我的是在C:/Program Files/MySQL/ySQL Server 5.7/bin>，直接运行发现会报错

1
2
C:\Program Files\MySQL\MySQL Server 5.7\bin>mysqldumpslow
'mysqldumpslow' 不是内部或外部命令，也不是可运行的程序或批处理文件。

仔细观察会发现，这个工具不知何时已经从可执行文件变成了一个Perl脚本mysqldumpslow.pl（之前使用linux版本是可执行文件）了，不能直接运行，需要安装Perl运行环境，这里有官方的下载地址，如果下载太慢的话可以下载我的备份文件，版本是一样的。

安装完成之后查看帮助（注意文件路径）

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
PS C:\Program Files\MySQL\MySQL Server 5.7\bin> perl mysqldumpslow.pl --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

看完使用方法，我们可以按照查询消耗的时间排序输出前两条日志（注意日志的路径，为方便可以拷贝到mysqldumpslow工具目录）:

1
2
3
4
5
6
7
8
PS C:\Program Files\MySQL\MySQL Server 5.7\bin> perl mysqldumpslow.pl -s t -v -t 2 0491NPORIURNUYO-slow.log

Reading mysql slow query log from 0491NPORIURNUYO-slow.log
Count: 1  Time=24.45s (24s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost
  call fill_slow_query_test()

Count: 1  Time=0.05s (0s)  Lock=0.00s (0s)  Rows=1.0 (1), root[root]@localhost
  select * from  slow_query_test  where id = N

可以发现还是很方便的，最耗时的操作已经排到了第一位，在实际的优化过程中，这或许就是我们需要拿来开刀的目标了。

总结

  • 通过修改配置文件my.ini中的slow-query-log、long_query_time来调整慢查询日志的开关和具体阈值
  • 通过mysqldumpshow工具可以格式化慢查询日志，方便定位问题和分析问题
Albert Shi wechat
欢迎您扫一扫上面的微信公众号，订阅我的博客