640?wx_fmt=gif

640?wx_fmt=jpeg

作者 | 阿文

责编 | 郭芮

今天和大家分享一下 MySQL 的慢日志。

在实际工作中,我面对很多用户会经常碰到一个问题,那就是在使用 MySQL 时,执行一条语句需要很长时间返回,这是为什么呢?当你在使用 MySQL 中,当发现一些性能问题的时,比如执行一个语句要很长时间才返回结果,我们称之为慢查询,一般来说,发生慢查询的原因有:

  • 你的索引设计有问题,可能会导致每次执行语句都是全表扫描,这样很耗费时间;

  • 你的 SQL 语句没有写好,可能会导致查询时间变长;

  • MySQL 选择了错误的索引,同样会导致全表扫描。

 

通常情况下,在业务上线之前,会在测试环境里面,把 MySQL 的慢查询打开,也就是把 longquerytime 设置为 0,这样确保每一条语句都被记录到慢日志中去,具体的配置可以参考下文。

 

MySQL 的慢查询日志是MySQL提供的一种日志记录,它是用来记录在MySQL中响应时间超过阀值的语句。系统默认情况下,MySQL 并不启动慢查询日志,需要我们手动来设置这个参数,当然,如果不是调优需要的话,一般不建议启动该参数,因为开启慢查询日志会或多或少带来一定的性能影响。

 

慢查询日志支持将日志记录写入文件,也支持将日志记录写入数据库表。

 

 

640?wx_fmt=png

慢查询配置

 

 

默认情况下slowquerylog的值为OFF,表示慢查询日志是禁用的,可以通过设置slowquerylog的值来开启,如下所示:

 

 
 mysql> show variables like '%slow_query_log%' -> ; +---------------------+-------------------------------+| Variable_name       | Value                         | +---------------------+-------------------------------+ | slow_query_log      | OFF                           || slow_query_log_file | /var/lib/mysql/mysql-slow.log | +---------------------+-------------------------------+2 rows in set (0.00 sec)
 -> ;
 +---------------------+-------------------------------+
| Variable_name       | Value                         |
 +---------------------+-------------------------------+
 | slow_query_log      | OFF                           |
| slow_query_log_file | /var/lib/mysql/mysql-slow.log |
 +---------------------+-------------------------------+
2 rows in set (0.00 sec)

 

开启慢查询日志:

 

 

 
mysql> set global slow_query_log=1;Query OK, 0 rows affected (0.00 sec)global slow_query_log=1;
Query OK, 0 rows affected (0.00 sec)

 

然后看状态:

 

 
mysql> show variables like '%slow_query_log%';+---------------------+-------------------------------+| Variable_name       | Value                         |+---------------------+-------------------------------+| slow_query_log      | ON                            || slow_query_log_file | /var/lib/mysql/mysql-slow.log |+---------------------+-------------------------------+2 rows in set (0.00 sec)
+---------------------+-------------------------------+
| Variable_name       | Value                         |
+---------------------+-------------------------------+
| slow_query_log      | ON                            |
| slow_query_log_file | /var/lib/mysql/mysql-slow.log |
+---------------------+-------------------------------+
2 rows in set (0.00 sec)

 

使用set global slowquerylog=1开启了慢查询日志只对当前数据库生效,如果MySQL重启后则会失效。如果要永久生效,就必须修改配置文件my.cnf(其它系统变量也是如此)。

 

例如如下所示:

 

 

 
[root@mysql ~]# vim /etc/my.cnfslow_query_log=1slow_query_log_file=/var/lib/mysql/mysql-slow.log# vim /etc/my.cnf
slow_query_log=1
slow_query_log_file=/var/lib/mysql/mysql-slow.log

 

参数说明:

 

  • slowquerylog 慢查询开启状态;

  • slowquerylog_file 慢查询日志存放的位置;

  • longquerytime 查询超过多少秒才记录。

 

那么开启了慢查询日志后,什么样的SQL才会记录到慢查询日志里面呢? 是否会被写入到慢日志是由参数longquerytime控制,默认情况下longquerytime的值为10秒,可以使用命令修改,也可以在my.cnf参数里面修改。关于运行时间正好等于longquerytime的情况,并不会被记录下来。也就是说,在MySQL源码里是判断大于longquerytime,而非大于等于。从MySQL 5.1开始,longquerytime开始以微秒记录SQL语句运行时间,之前仅用秒为单位记录。如果记录到表里面,只会记录整数部分,不会记录微秒部分。

 

查看long_time 值,默认是 10 秒。

 

 
    mysql> show variables like '%long_query_time%';    +-----------------+-----------+    | Variable_name   | Value     |    +-----------------+-----------+    | long_query_time | 10.000000 |    +-----------------+-----------+    1 row in set (0.00 sec)
    +-----------------+-----------+
    | Variable_name   | Value     |
    +-----------------+-----------+
    | long_query_time | 10.000000 |
    +-----------------+-----------+
    1 row in set (0.00 sec)

 

设置值,例如这里设置为 5 秒:

 

 

 
    mysql> set global long_query_time=5;    Query OK, 0 rows affected (0.00 sec)    mysql> show variables like '%long_query_time%';    +-----------------+-----------+    | Variable_name   | Value     |    +-----------------+-----------+    | long_query_time | 10.000000 |    +-----------------+-----------+    1 row in set (0.01 sec)global long_query_time=5;
    Query OK, 0 rows affected (0.00 sec)

    mysql> show variables like '%long_query_time%';
    +-----------------+-----------+
    | Variable_name   | Value     |
    +-----------------+-----------+
    | long_query_time | 10.000000 |
    +-----------------+-----------+
    1 row in set (0.01 sec)

 

如上所示,修改了变量longquerytime,但是查询变量longquerytime的值还是10。

 

使用命令 set global longquerytime=5修改后,需要重新连接或新开一个会话才能看到修改值。因为通过用show variables like 'longquerytime'查看是当前会话的变量值。

 

也可以不用重新连接会话,而是用 show global variables like 'longquerytime'; 如下所示:

 

 
    mysql> show global variables like 'long_query_time';    +-----------------+----------+    | Variable_name   | Value    |    +-----------------+----------+    | long_query_time | 5.000000 |    +-----------------+----------+    1 row in set (0.00 sec)
    +-----------------+----------+
    | Variable_name   | Value    |
    +-----------------+----------+
    | long_query_time | 5.000000 |
    +-----------------+----------+
    1 row in set (0.00 sec)

 

我们设置longquerytime的值为2:

 

 

 
    mysql> set global long_query_time=2;    Query OK, 0 rows affected (0.00 sec)    mysql> show global variables like 'long_query_time';    +-----------------+----------+    | Variable_name   | Value    |    +-----------------+----------+    | long_query_time | 2.000000 |    +-----------------+----------+    1 row in set (0.00 sec)global long_query_time=2;
    Query OK, 0 rows affected (0.00 sec)

    mysql> show global variables like 'long_query_time';
    +-----------------+----------+
    | Variable_name   | Value    |
    +-----------------+----------+
    | long_query_time | 2.000000 |
    +-----------------+----------+
    1 row in set (0.00 sec)

 

然后执行一条超时5秒的语句(需要重新连接MySQL):

 

 

 
    [root@mysql ~]# mysql -u root -p    Enter password:    Welcome to the MySQL monitor.  Commands end with ; or \g.    Your MySQL connection id is 4    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> show variables like 'long_query_time';    +-----------------+----------+    | Variable_name   | Value    |    +-----------------+----------+    | long_query_time | 2.000000 |    +-----------------+----------+    1 row in set (0.02 sec)    mysql> select sleep(5)        -> ;    +----------+    | sleep(5) |    +----------+    |        0 |    +----------+    1 row in set (5.01 sec)
    Enter password:
    Welcome to the MySQL monitor.  Commands end with ; or \g.
    Your MySQL connection id is 4
    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> show variables like 'long_query_time';
    +-----------------+----------+
    | Variable_name   | Value    |
    +-----------------+----------+
    | long_query_time | 2.000000 |
    +-----------------+----------+
    1 row in set (0.02 sec)

    mysql> select sleep(5)
        -> ;
    +----------+
    | sleep(5) |
    +----------+
    |        0 |
    +----------+
    1 row in set (5.01 sec)

 

然后查看慢日志可以看到类似信息:

 

 
    [root@mysql ~]# cat /var/lib/mysql/mysql-slow.log    /usr/sbin/mysqld, Version: 5.7.21 (MySQL Community Server (GPL)). started with:    Tcp port: 3306  Unix socket: /var/lib/mysql/mysql.sock    Time                 Id Command    Argument    /usr/sbin/mysqld, Version: 5.7.21-log (MySQL Community Server (GPL)). started with:    Tcp port: 0  Unix socket: /var/lib/mysql/mysql.sock    Time                 Id Command    Argument    # Time: 2018-02-09T06:59:47.782111Z    # User@Host: root[root] @ localhost []  Id:     4    # Query_time: 5.000252  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0    SET timestamp=1518159587;    select sleep(5);
    /usr/sbin/mysqld, Version: 5.7.21 (MySQL Community Server (GPL)). started with:
    Tcp port: 3306  Unix socket: /var/lib/mysql/mysql.sock
    Time                 Id Command    Argument
    /usr/sbin/mysqld, Version: 5.7.21-log (MySQL Community Server (GPL)). started with:
    Tcp port: 0  Unix socket: /var/lib/mysql/mysql.sock
    Time                 Id Command    Argument
    # Time2018-02-09T06:59:47.782111Z
    # User@Host: root[root] @ localhost []  Id:     4
    # Query_time: 5.000252  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 0
    SET timestamp=1518159587;
    select sleep(5);

 

logoutput 参数是指定日志的存储方式。logoutput='FILE'表示将日志存入文件,默认值是'FILE'。log_output='TABLE'表示将日志存入数据库,这样日志信息就会被写入到mysql.slowlog表中。MySQL数据库支持同时两种日志存储方式,配置的时候以逗号隔开即可,如:logoutput='FILE,TABLE'。日志记录到系统的专用日志表中,要比记录到文件耗费更多的系统资源,因此对于需要启用慢查询日志,又需要能够获得更高的系统性能,那么建议优先记录到文件。

25岁转行人工智能靠谱吗?

https://edu.csdn.net/topic/ai30?utm_source=csdn_bw

 
    mysql> show variables like '%log_output%';    +---------------+-------+    | Variable_name | Value |    +---------------+-------+    | log_output    | FILE  |    +---------------+-------+    1 row in set (0.01 sec)
    +---------------+-------+
    | Variable_name | Value |
    +---------------+-------+
    | log_output    | FILE  |
    +---------------+-------+
    1 row in set (0.01 sec)

 

设置为表:

 

 
    mysql> set global log_output='TABLE';    Query OK, 0 rows affected (0.00 sec)    mysql> show variables like '%log_output%';    +---------------+-------+    | Variable_name | Value |    +---------------+-------+    | log_output    | TABLE |    +---------------+-------+    1 row in set (0.00 sec)    mysql> select sleep(5);    +----------+    | sleep(5) |    +----------+    |        0 |    +----------+    1 row in set (5.00 sec)
    Query OK, 0 rows affected (0.00 sec)

    mysql> show variables like '%log_output%';
    +---------------+-------+
    | Variable_name | Value |
    +---------------+-------+
    | log_output    | TABLE |
    +---------------+-------+
    1 row in set (0.00 sec)
    mysql> select sleep(5);
    +----------+
    | sleep(5) |
    +----------+
    |        0 |
    +----------+
    1 row in set (5.00 sec)

 

执行 select * from mysql.slowlog; 观察慢查询日志里每类语句的输出,其中querytime表示query语句的执行时间,单位是为秒,lock time是锁定的时间,rowssent是query语句执行返回的记录数,而rowsexamined则是优化器估算的扫描行数,querytime、rowsexamined、rowssent 三个值可以大致衡量一条查询的成本,特别留意 rowsexamined 字段是否与预期一致。

 

系统变量log-queries-not-using-indexes:未使用索引的查询也被记录到慢查询日志中(可选项)。如果调优的话,建议开启这个选项。另外,开启了这个参数,其实使用full index scan的sql也会被记录到慢查询日志。

 

 
    mysql> show variables like 'log_queries_not_using_indexes';    +-------------------------------+-------+    | Variable_name                 | Value |    +-------------------------------+-------+    | log_queries_not_using_indexes | OFF   |    +-------------------------------+-------+    1 row in set (0.00 sec)    mysql> set global log_queries_not_using_indexes=1;    Query OK, 0 rows affected (0.00 sec)    mysql> show variables like 'log_queries_not_using_indexes';    +-------------------------------+-------+    | Variable_name                 | Value |    +-------------------------------+-------+    | log_queries_not_using_indexes | ON    |    +-------------------------------+-------+    1 row in set (0.00 sec)    mysql>'log_queries_not_using_indexes';
    +-------------------------------+-------+
    | Variable_name                 | Value |
    +-------------------------------+-------+
    | log_queries_not_using_indexes | OFF   |
    +-------------------------------+-------+
    1 row in set (0.00 sec)

    mysql> set global log_queries_not_using_indexes=1;
    Query OK, 0 rows affected (0.00 sec)

    mysql> show variables like 'log_queries_not_using_indexes';
    +-------------------------------+-------+
    | Variable_name                 | Value |
    +-------------------------------+-------+
    | log_queries_not_using_indexes | ON    |
    +-------------------------------+-------+
    1 row in set (0.00 sec)

    mysql>

 

系统变量logslowadmin_statements表示是否将慢管理语句例如ANALYZE TABLE和ALTER TABLE等记入慢查询日志:

 

 
    mysql> show variables like 'log_slow_admin_statements';    +---------------------------+-------+    | Variable_name             | Value |    +---------------------------+-------+    | log_slow_admin_statements | OFF   |    +---------------------------+-------+    1 row in set (0.00 sec)    mysql>    mysql> set global log_slow_admin_statements=1;    Query OK, 0 rows affected (0.01 sec)    mysql> show variables like 'log_slow_admin_statements';    +---------------------------+-------+    | Variable_name             | Value |    +---------------------------+-------+    | log_slow_admin_statements | ON    |    +---------------------------+-------+    1 row in set (0.00 sec)'log_slow_admin_statements';
    +---------------------------+-------+
    | Variable_name             | Value |
    +---------------------------+-------+
    | log_slow_admin_statements | OFF   |
    +---------------------------+-------+
    1 row in set (0.00 sec)

    mysql>

    mysql> set global log_slow_admin_statements=1;
    Query OK, 0 rows affected (0.01 sec)

    mysql> show variables like 'log_slow_admin_statements';
    +---------------------------+-------+
    | Variable_name             | Value |
    +---------------------------+-------+
    | log_slow_admin_statements | ON    |
    +---------------------------+-------+
    1 row in set (0.00 sec)

 

查询有多少条慢日志,可以使用系统变量:

 

 

 
    mysql> show global status like '%slow_queries%';    +---------------+-------+    | Variable_name | Value |    +---------------+-------+    | Slow_queries  | 2     |    +---------------+-------+    1 row in set (0.01 sec)'%slow_queries%';
    +---------------+-------+
    | Variable_name | Value |
    +---------------+-------+
    | Slow_queries  | 2     |
    +---------------+-------+
    1 row in set (0.01 sec)

 

 

640?wx_fmt=png

日志分析工具mysqldumpslow

 

 

MySQL 自带了一个查看慢日志的工具 mysqldumpslow,执行mysqldumpslow --help 可以查看其相关参数和说明:

 

 
    [root@mysql ~]# mysqldumpslow --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
    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

 

参数解释:

 

  • -s:是表示按照何种方式排序;

  • c: 访问计数;

  • l: 锁定时间;

  • r: 返回记录;

  • t: 查询时间;

  • al:平均锁定时间;

  • ar:平均返回记录数;

  • at:平均查询时间;

  • -t:是top n的意思,即为返回前面多少条的数据;

  • -g:后边可以写一个正则匹配模式,大小写不敏感的。

 

例如,得到返回记录集最多的10个SQL:

 

 

 
    mysqldumpslow -s r -t 10 /mysql/mysql_slow.loglog

 

得到访问次数最多的10个SQL:

 

 
    mysqldumpslow -s c -t 10 /mysql/mysql_slow.loglog

 

通过以上方式我们可以配置和发现慢 SQL,那么在发现慢 SQL 语句之后,我们可以通过对数据库进行优化来提升 SQL 的执行速度,比如加索引或修改该应用的实现方式等。

 看完就懂!这样学python最高效

https://edu.csdn.net/topic/python115?utm_source=csdn_bw


 

640?wx_fmt=jpeg

 热 文 推 荐 

华为最强自研 NPU 问世,麒麟 810 测评远超骁龙系列!

马自达 3 为什么抛弃了触摸屏?

腾讯、阿里能像 Facebook 一样发币吗?

10分钟读懂什么是容器云?

☞媲美Pandas?Python的Datatable包怎么用?

西交出身,辛书冕获CVPR 2019最佳论文,李飞飞团队获经典论文奖

倒计时10天 | 堪称年度中国最具影响力的以太坊技术盛宴,为何不容错过?

技术面试别扯智力题!

她说:程序员离开电脑就是 “废物” !

640?wx_fmt=png你点的每个“在看”,我都认真当成了喜欢

Logo

20年前,《新程序员》创刊时,我们的心愿是全面关注程序员成长,中国将拥有新一代世界级的程序员。20年后的今天,我们有了新的使命:助力中国IT技术人成长,成就一亿技术人!

更多推荐