Mysql开启、查看慢查询日志

前言

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

关于查询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-loglong_query_time来调整慢查询日志的开关和具体阈值
  • 通过mysqldumpshow工具可以格式化慢查询日志,方便定位问题和分析问题
Albert Shi wechat
欢迎您扫一扫上面的微信公众号,订阅我的博客