MySQL优化之慢查询日志

database

慢查询日志概述

所谓慢查询日志,就是用于记录MySQL中响应时间超过设定阈值的SQL语句,通过打开慢查询开关,MySQL会将大于阈值的SQL记录在日志中,以便于分析性能。

慢查询日志选项默认是关闭的,如果要开启,则需要手动设置。

慢查询日志选项不建议一直开启,因为记录日志意味着IO操作,本身对性能有一定的影响,因此,建议在生产环境关闭该选项;而在开发环境调优阶段可以适当打开该选项。

检查是否开启了慢查询日志:

mysql> show variables like "%slow_query_log%";

+---------------------+-----------------------------------------+

| Variable_name | Value |

+---------------------+-----------------------------------------+

| slow_query_log | OFF |

| slow_query_log_file | /var/lib/mysql/DESKTOP-Q5J25HR-slow.log |

+---------------------+-----------------------------------------+

2 rows in set (0.03 sec)

slow_query_log选项即开启慢查询的开关,OFF为关闭,ON为开启。

slow_query_log_file即慢查询日志的名称。

如果要开启慢查询日志,则执行如下语句:

set global slow_query_log = ON;

/* 或者 */

set global slow_query_log = 1;

以上两句话是一个意思,执行任意一条都可以。执行完毕,再次查询,已经打开。

mysql> set global slow_query_log = ON;

Query OK, 0 rows affected (0.05 sec)

mysql> show variables like "%slow_query_log%";

+---------------------+-----------------------------------------+

| Variable_name | Value |

+---------------------+-----------------------------------------+

| slow_query_log | ON |

| slow_query_log_file | /var/lib/mysql/DESKTOP-Q5J25HR-slow.log |

+---------------------+-----------------------------------------+

2 rows in set (0.00 sec)

同样的,慢查询日志的文件名也可以重新指定,只需要设置set global slow_query_log_file = 文件名即可。

前面说过,慢查询日志只有当SQL语句响应时间超过一定阈值才会记录在日志中,那么这个阈值是多少,该如何设置呢?

可通过以下命令查看慢查询日志的阈值:

mysql> show variables like "%long_query_time%";

+-----------------+-----------+

| Variable_name | Value |

+-----------------+-----------+

| long_query_time | 10.000000 |

+-----------------+-----------+

1 row in set (0.00 sec)

可以看到,默认的阈值是10秒,该值同样可以通过设置来修改,如设置为0.1秒:

set global long_query_time = 0.1;

long_query_time设置完成后,需要退出MySQL客户端,重新登录后才生效,于是可以看到该值已经变成了0.1:

mysql> show variables like "%long_query_time%";

+-----------------+----------+

| Variable_name | Value |

+-----------------+----------+

| long_query_time | 0.100000 |

+-----------------+----------+

1 row in set (0.01 sec)

慢查询日志具体案例

接下来通过案例的方式来演示慢查询日志:

我在当前数据库里有一张test01表,表结构如下所示:

mysql> desc test01;

+--------+-------------+------+-----+---------+-------+

| Field | Type | Null | Key | Default | Extra |

+--------+-------------+------+-----+---------+-------+

| id | int(4) | YES | MUL | NULL | |

| name | varchar(20) | YES | | NULL | |

| passwd | char(20) | YES | | NULL | |

| inf | char(50) | YES | | NULL | |

+--------+-------------+------+-----+---------+-------+

4 rows in set (0.04 sec)

分别做如下查询:

select * from test01;

select sleep(1);

select id, sleep(2) from test01;

执行结果如下所示:

mysql> select * from test01;

+------+------+--------+--------+

| id | name | passwd | inf |

+------+------+--------+--------+

| 1 | zz | 123456 | asdfgh |

+------+------+--------+--------+

1 row in set (0.00 sec)

mysql> select sleep(1);

+----------+

| sleep(1) |

+----------+

| 0 |

+----------+

1 row in set (1.00 sec)

mysql> select id, sleep(2) from test01;

+------+----------+

| id | sleep(2) |

+------+----------+

| 1 | 0 |

+------+----------+

1 row in set (2.00 sec)

此时并需要去不关心SQL本身,而是看这三条SQL执行的时间,从上面可以看到,第一条SQL执行几乎不耗时间,显示0.00 sec,第二条SQL显示时间为 1.00 sec,第三条SQL为 2.00 sec

因为我们设置了阈值为0.1秒,因此后两条SQL应该都要记录在慢查询日志中,接下来验证是否如此:

通过如下命令,可查看慢查询SQL的条数:

mysql> show global status like "%slow_queries%";

+---------------+-------+

| Variable_name | Value |

+---------------+-------+

| Slow_queries | 2 |

+---------------+-------+

1 row in set (0.02 sec)

显示记录为2条,与实际情况一致。

通过show variables like "%slow_query_log%"命令,可以查看到日志的具体路径。

mysql> show variables like "%slow_query_log%";

+---------------------+-----------------------------------------+

| Variable_name | Value |

+---------------------+-----------------------------------------+

| slow_query_log | ON |

| slow_query_log_file | /var/lib/mysql/DESKTOP-Q5J25HR-slow.log |

+---------------------+-----------------------------------------+

2 rows in set (0.00 sec)

打开/var/lib/mysql/DESKTOP-Q5J25HR-slow.log,可以看到日志当中记录了时间超过阈值的那两条SQL语句:

/usr/sbin/mysqld, Version: 5.7.29-0ubuntu0.18.04.1 ((Ubuntu)). started with:

Tcp port: 3306 Unix socket: /var/run/mysqld/mysqld.sock

Time Id Command Argument

/usr/sbin/mysqld, Version: 5.7.29-0ubuntu0.18.04.1 ((Ubuntu)). started with:

Tcp port: 3306 Unix socket: /var/run/mysqld/mysqld.sock

Time Id Command Argument

# Time: 2020-03-31T13:41:25.726554Z

# User@Host: root[root] @ localhost [] Id: 6

# Query_time: 1.000644 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0

use testDB;

SET timestamp=1585662085;

select sleep(1);

# Time: 2020-03-31T13:41:34.246770Z

# User@Host: root[root] @ localhost [] Id: 6

# Query_time: 2.000536 Lock_time: 0.000057 Rows_sent: 1 Rows_examined: 1

SET timestamp=1585662094;

select id, sleep(2) from test01;

mysqldumpslow工具

以上介绍的方法虽然可以查看出所有慢SQL语句,但显然都记录在一个日志文件里,会显得很乱,而且一旦SQL比较多,定位起来还是比较麻烦的。

好在MySQL本身提供了一个专门用来查看慢查询日志的工具,即mysqldumpslow。

可通过MySQLdumpslow -help查看具体使用方法:

chenyc@DESKTOP-Q5J25HR:~$ 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

从以上文件中,可以知道,该工具用法如下:

mysqldumpslow [选项] [日志名]

常用选项说明:

  • -s 即order排序,后面可以有以下选项:

    • al 平均锁定时间
    • ar 平均返回记录时间
    • at 平均查询时间
    • c 计数
    • l 锁定时间
    • r 逆序排序
    • t 查询时间

  • -t,相当于top n,即返回前面n条语句
  • -g, 匹配正则表达式,大小写不敏感

    如:

sudo mysqldumpslow -s r -t 3 -g "select" /var/lib/mysql/DESKTOP-Q5J25HR-slow.log

以上命令表示:返回按逆序排序的其中三条语句,且语句中包含select的SQL语句。

结果如下所示:

chenyc@DESKTOP-Q5J25HR:~$ sudo mysqldumpslow -s r -t 3 -g "select" /var/lib/mysql/DESKTOP-Q5J25HR-slow.log

Reading mysql slow query log from /var/lib/mysql/DESKTOP-Q5J25HR-slow.log

Count: 1 Time=2.00s (2s) Lock=0.00s (0s) Rows=1.0 (1), root[root]@localhost

select id, sleep(N) from test01

Count: 1 Time=1.00s (1s) Lock=0.00s (0s) Rows=1.0 (1), root[root]@localhost

select sleep(N)

Died at /usr/bin/mysqldumpslow line 167, <> chunk 2.

Profiles工具

profiles最大的作用是用来分析海量数据,该命令会记录所有执行过的SQL语句。

这个选项默认也是关闭的,需要手动打开。

查询profiles选项命令:

mysql> show variables like "%profiling%";

+------------------------+-------+

| Variable_name | Value |

+------------------------+-------+

| have_profiling | YES |

| profiling | OFF |

| profiling_history_size | 15 |

+------------------------+-------+

3 rows in set (0.01 sec)

打开命令:

mysql> set profiling = ON;

Query OK, 0 rows affected, 1 warning (0.00 sec)

再次查看,可以换一种方式查看:

mysql> select @@profiling;

+-------------+

| @@profiling |

+-------------+

| 1 |

+-------------+

1 row in set, 1 warning (0.00 sec)

以上选项,1代表打开,0代表关闭。

为了更为直观的查看profile,我们再执行两条SQL:

mysql> select sleep(3);

+----------+

| sleep(3) |

+----------+

| 0 |

+----------+

1 row in set (3.00 sec)

mysql> select * from test01;

+------+------+--------+--------+

| id | name | passwd | inf |

+------+------+--------+--------+

| 1 | zz | 123456 | asdfgh |

+------+------+--------+--------+

1 row in set (0.00 sec)

好了,准备工作就到这里,现在来查看profile:

mysql> show profiles;

+----------+------------+-----------------------------------+

| Query_ID | Duration | Query |

+----------+------------+-----------------------------------+

| 1 | 0.00214400 | show variables like "%profiling%" |

| 2 | 0.00017400 | select @@profiling |

| 3 | 3.00062925 | select sleep(3) |

| 4 | 0.00023450 | select * from test01 |

+----------+------------+-----------------------------------+

4 rows in set, 1 warning (0.00 sec)

如上所示,它会记录所有的语句,其中第二列Duration代表的是执行时间。

以上虽然可以看到每条SQL的执行时间,但我们无法精确知道有多少时间花费在IO上,多少时间花费在CPU上,因此,还可使用以下语句查看更为精确的内容:

show profile all for query $(Query_ID);

上面的Query_IDshow profiles结果中第一列的id编号。如:

mysql> show profile all for query 4;

+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+

| Status | Duration | CPU_user | CPU_system | Context_voluntary | Context_involuntary | Block_ops_in | Block_ops_out | Messages_sent | Messages_received | Page_faults_major | Page_faults_minor | Swaps | Source_function | Source_file

| Source_line |

+----------------------+----------+----------+------------+-------------------+---------------------+--------------+---------------+---------------+-------------------+-------------------+-------------------+-------+-----------------------+----------------------+-------------+

| starting | 0.000045 | 0.000000 | 0.000000 | 0 | 0 | 0 |

0 | 0 | 0 | 0 | 0 | 0 | NULL | NULL

| NULL |

| checking permissions | 0.000008 | 0.000000 | 0.000000 | 0 | 0 | 0 |

0 | 0 | 0 | 0 | 0 | 0 | check_access | sql_authorization.cc | 809 |

| Opening tables | 0.000020 | 0.000000 | 0.000000 | 0 | 0 | 0 |

0 | 0 | 0 | 0 | 0 | 0 | open_tables | sql_base.cc

| 5781 |

| init | 0.000017 | 0.000000 | 0.000000 | 0 | 0 | 0 |

0 | 0 | 0 | 0 | 0 | 0 | handle_query | sql_select.cc

| 128 |

| System lock | 0.000016 | 0.000000 | 0.000000 | 0 | 0 | 0 |

0 | 0 | 0 | 0 | 2 | 0 | mysql_lock_tables | lock.cc

| 330 |

| optimizing | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | 0 |

0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc

| 158 |

| statistics | 0.000014 | 0.000000 | 0.000000 | 0 | 0 | 0 |

0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc

| 374 |

| preparing | 0.000010 | 0.000000 | 0.000000 | 0 | 0 | 0 |

0 | 0 | 0 | 0 | 0 | 0 | optimize | sql_optimizer.cc

| 482 |

| executing | 0.000004 | 0.000000 | 0.000000 | 0 | 0 | 0 |

0 | 0 | 0 | 0 | 0 | 0 | exec | sql_executor.cc

| 126 |

| Sending data | 0.000051 | 0.000000 | 0.000000 | 0 | 0 | 0 |

0 | 0 | 0 | 0 | 8 | 0 | exec | sql_executor.cc

| 202 |

| end | 0.000005 | 0.000000 | 0.000000 | 0 | 0 | 0 |

0 | 0 | 0 | 0 | 0 | 0 | handle_query | sql_select.cc

| 206 |

| query end | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | 0 |

0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc

| 4956 |

| closing tables | 0.000007 | 0.000000 | 0.000000 | 0 | 0 | 0 |

0 | 0 | 0 | 0 | 0 | 0 | mysql_execute_command | sql_parse.cc

| 5009 |

| freeing items | 0.000013 | 0.000000 | 0.000000 | 0 | 0 | 0 |

0 | 0 | 0 | 0 | 0 | 0 | mysql_parse | sql_parse.cc

| 5622 |

| cleaning up | 0.000013 | 0.000000 | 0.000000 | 0 | 0 | 0 |

0 | 0 | 0 | 0 | 0 | 0 | dispatch_command | sql_parse.cc

| 1931 |

+----------------------+----------+----------+------------+-------------------+---------------------+--------------+-------------

--+---------------+-------------------+-------------------+-------------------+-------+-----------------------+------------------

----+-------------+

15 rows in set, 1 warning (0.00 sec)

上面的结果由于选项太多,看起来还是有些乱,其实很多东西我们并不关注,而主要只关注CPU和IO情况,因此,可以进一步简化如下:

mysql> show profile cpu, block io for query 4;

+----------------------+----------+----------+------------+--------------+---------------+

| Status | Duration | CPU_user | CPU_system | Block_ops_in | Block_ops_out |

+----------------------+----------+----------+------------+--------------+---------------+

| starting | 0.000045 | 0.000000 | 0.000000 | 0 | 0 |

| checking permissions | 0.000008 | 0.000000 | 0.000000 | 0 | 0 |

| Opening tables | 0.000020 | 0.000000 | 0.000000 | 0 | 0 |

| init | 0.000017 | 0.000000 | 0.000000 | 0 | 0 |

| System lock | 0.000016 | 0.000000 | 0.000000 | 0 | 0 |

| optimizing | 0.000005 | 0.000000 | 0.000000 | 0 | 0 |

| statistics | 0.000014 | 0.000000 | 0.000000 | 0 | 0 |

| preparing | 0.000010 | 0.000000 | 0.000000 | 0 | 0 |

| executing | 0.000004 | 0.000000 | 0.000000 | 0 | 0 |

| Sending data | 0.000051 | 0.000000 | 0.000000 | 0 | 0 |

| end | 0.000005 | 0.000000 | 0.000000 | 0 | 0 |

| query end | 0.000007 | 0.000000 | 0.000000 | 0 | 0 |

| closing tables | 0.000007 | 0.000000 | 0.000000 | 0 | 0 |

| freeing items | 0.000013 | 0.000000 | 0.000000 | 0 | 0 |

| cleaning up | 0.000013 | 0.000000 | 0.000000 | 0 | 0 |

+----------------------+----------+----------+------------+--------------+---------------+

15 rows in set, 1 warning (0.00 sec)

全局查询日志

同profiles一样,打开全局查询日志选项以后,它会记录下所有SQL语句,但是由于该操作比较耗费性能,因此,只建议在开发环境临时打开该选项。

查看全局查询日志命令:

mysql> show variables like "%general_log%";

+------------------+------------------------------------+

| Variable_name | Value |

+------------------+------------------------------------+

| general_log | OFF |

| general_log_file | /var/lib/mysql/DESKTOP-Q5J25HR.log |

+------------------+------------------------------------+

2 rows in set (0.01 sec)

打开全局查询日志选项:

set global general_log = on;

再次查询:

mysql> show variables like "%general_log%";

+------------------+------------------------------------+

| Variable_name | Value |

+------------------+------------------------------------+

| general_log | ON |

| general_log_file | /var/lib/mysql/DESKTOP-Q5J25HR.log |

+------------------+------------------------------------+

2 rows in set (0.00 sec)

设置完以上之后,还需要做如下设置:

set global log_output = "table";

同样的,准备以下SQL:

select * from test01;

select id, name from test01 where id = 1;

全局查询日志记录在mysql.general_log表中。

mysql> select * from mysql.general_log;

+----------------------------+---------------------------+-----------+-----------+--------------+------------------------------------------+

| event_time | user_host | thread_id | server_id | command_type | argument

|

+----------------------------+---------------------------+-----------+-----------+--------------+------------------------------------------+

| 2020-03-31 22:31:24.750895 | root[root] @ localhost [] | 6 | 0 | Query | select * from test01

|

| 2020-03-31 22:31:26.128924 | root[root] @ localhost [] | 6 | 0 | Query | select id, name from test01 whe

re id = 1 |

| 2020-03-31 22:32:15.736558 | root[root] @ localhost [] | 6 | 0 | Query | select * from mysql.general_log

|

+----------------------------+---------------------------+-----------+-----------+--------------+--------------------------------

----------+

3 rows in set (0.01 sec)

既然有记录到表中,自然也有记录到文件中,只需要做如下设置:

set global general_log_file = "/tmp/mysql_general.log";		--设置文件路径

set global log_output = "file"; --设置记录到文件

可通过如下命令查看文件路径:

mysql> show variables like "%general_log%";

+------------------+------------------------+

| Variable_name | Value |

+------------------+------------------------+

| general_log | ON |

| general_log_file | /tmp/mysql_general.log |

+------------------+------------------------+

2 rows in set (0.00 sec)

同样执行以上两条SQL:

select * from test01;

select id, name from test01 where id = 1;

查看文件内容,得到如下结果:

chenyc@DESKTOP-Q5J25HR:~$ sudo cat /tmp/mysql_general.log

/usr/sbin/mysqld, Version: 5.7.29-0ubuntu0.18.04.1 ((Ubuntu)). started with:

Tcp port: 3306 Unix socket: /var/run/mysqld/mysqld.sock

Time Id Command Argument

2020-03-31T14:35:49.793176Z 6 Query show variables like "%general_log%"

2020-03-31T14:37:20.241374Z 6 Query select * from test01

2020-03-31T14:37:21.408617Z 6 Query select id, name from test01 where id = 1

以上是 MySQL优化之慢查询日志 的全部内容, 来源链接: utcz.com/z/532939.html

回到顶部