mysql slow-query-log_MySQL 日志之--慢查询日志（slow-query-log）

MySQL 日志之--慢查询日志(slow-query-log)

慢查询日志：MySQL慢查询日志记录下所有执行超过long_query_time时间的SQL语句，帮你找到执行慢的SQL，方便我们对这些SQL进行优化。

慢查询日志的配置：

默认情况下，mysql没有启用慢查询日志。

[root@rh64 ~]# mysql -u root -pEnter password:

Welcome to the MySQL monitor.  Commands end with ; or \g.

Your MySQL connection id is 1

Server version: 5.6.25-73.1 Percona Server (GPL), Release 73.1, Revision 07b797f

Copyright (c) 2009-2015 Percona LLC and/or its affiliates

Copyright (c) 2000, 2015, 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 '%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                     | OFF                          |

| slow_query_log_always_write_time   | 10.000000                    |

| slow_query_log_file                | /var/lib/mysql/rh64-slow.log |

| slow_query_log_timestamp_always    | OFF                          |

| slow_query_log_timestamp_precision | second                       |

| slow_query_log_use_global_control  |                              |

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

16 rows in set (0.01 sec)

1、可以配置my.cnf文件，服务启动时自动配置

[root@rh64 ~]# cat /etc/my.cnf[mysqld]

datadir=/var/lib/mysql

socket=/var/lib/mysql/mysql.sock

user=mysql

# Disabling symbolic-links is recommended to prevent assorted security risks

symbolic-links=0

innodb_data_file_path=ibdata1:12M;ibdata2:10M:autoextend

sql_mode=STRICT_TRANS_TABLES ,NO_ENGINE_SUBSTITUTION

slow_query_log=true

slow_query_log_file = "/var/lib/mysql/rh64-slow.log"

long_query_time=1

log-queries-not-using-indexes=true

[mysqld_safe]

log-error=/var/log/mysqld.log

pid-file=/var/run/mysqld/mysqld.pid

explicit_defaults_for_timestamp=true

innodb_buffer_pool_size = 128M

join_buffer_size = 128M

sort_buffer_size = 2M

read_rnd_buffer_size = 2M

重启server后，查看：

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                | /var/lib/mysql/rh64-slow.log |

| slow_query_log_timestamp_always    | OFF                          |

| slow_query_log_timestamp_precision | second                       |

| slow_query_log_use_global_control  |                              |

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

16 rows in set (0.00 sec)

2、在系统中配置slow-query-log

mysql> set @@global.slow_query_log = on;

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                | /var/lib/mysql/rh64-slow.log |

| slow_query_log_timestamp_always    | OFF                          |

| slow_query_log_timestamp_precision | second                       |

| slow_query_log_use_global_control  |                              |

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

16 rows in set (0.00 sec)

3、查看慢查询日志信息

[root@rh64 mysql]# tail rh64-slow.loguse prod;

SET timestamp=1449476453;

insert into emp1 select * from emp1;

# Time: 151207 16:21:11

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

# Schema: prod  Last_errno: 0  Killed: 0

# Query_time: 16.748949  Lock_time: 0.000137  Rows_sent: 0  Rows_examined: 1236992  Rows_affected: 618496

# Bytes_sent: 58

SET timestamp=1449476471;

insert into emp1 select * from emp1;

[root@rh64 mysql]# tail -f rh64-slow.log

use prod;

SET timestamp=1449476453;

insert into emp1 select * from emp1;

# Time: 151207 16:21:11

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

# Schema: prod  Last_errno: 0  Killed: 0

# Query_time: 16.748949  Lock_time: 0.000137  Rows_sent: 0  Rows_examined: 1236992  Rows_affected: 618496

# Bytes_sent: 58

SET timestamp=1449476471;

insert into emp1 select * from emp1;

# Time: 151207 16:22:54

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

# Schema: prod  Last_errno: 0  Killed: 0

# Query_time: 44.036039  Lock_time: 0.000083  Rows_sent: 0  Rows_examined: 2473984  Rows_affected: 1236992

# Bytes_sent: 59

SET timestamp=1449476574;

insert into emp1 select * from emp1;

# Time: 151207 16:26:46

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

# Schema: prod  Last_errno: 0  Killed: 0

# Query_time: 106.674422  Lock_time: 0.000148  Rows_sent: 0  Rows_examined: 4947968  Rows_affected: 2473984

# Bytes_sent: 59

SET timestamp=1449476806;

insert into emp1 select * from emp1;

记录没有使用索引的语句：

mysql> set @@global.log_queries_not_using_indexes=on;

Query OK, 0 rows affected (0.00 sec)mysql> show variables like '%index%';

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

| Variable_name                          | Value |

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

| eq_range_index_dive_limit              | 10    |

| expand_fast_index_creation             | OFF   |

| innodb_adaptive_hash_index             | ON    |

| innodb_adaptive_hash_index_partitions  | 1     |

| innodb_cmp_per_index_enabled           | OFF   |

| log_bin_index                          |       |

| log_queries_not_using_indexes          | ON    |

| log_throttle_queries_not_using_indexes | 0     |

| relay_log_index                        |       |

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

9 rows in set (0.00 sec)

测试：

mysql> select count(*) from emp1 where empno=7788;

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

| count(*) |

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

|   688128 |

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

1 row in set (4.03 sec)

[root@rh64 mysql]# tail rh64-slow.logSET timestamp=1449476453;

insert into emp1 select * from emp1;

# Time: 151207 16:21:11

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

# Schema: prod  Last_errno: 0  Killed: 0

# Query_time: 16.748949  Lock_time: 0.000137  Rows_sent: 0  Rows_examined: 1236992  Rows_affected: 618496

# Bytes_sent: 58

SET timestamp=1449476471;

insert into emp1 select * from emp1;

# Time: 151207 16:22:54

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

# Schema: prod  Last_errno: 0  Killed: 0

# Query_time: 44.036039  Lock_time: 0.000083  Rows_sent: 0  Rows_examined: 2473984  Rows_affected: 1236992

# Bytes_sent: 59

SET timestamp=1449476574;

insert into emp1 select * from emp1;

# Time: 151207 16:26:46

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

# Schema: prod  Last_errno: 0  Killed: 0

# Query_time: 106.674422  Lock_time: 0.000148  Rows_sent: 0  Rows_examined: 4947968  Rows_affected: 2473984

# Bytes_sent: 59

SET timestamp=1449476806;

insert into emp1 select * from emp1;

# Time: 151207 16:30:44

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

# Schema: prod  Last_errno: 0  Killed: 0

# Query_time: 4.025612  Lock_time: 0.000098  Rows_sent: 1  Rows_examined: 4947968  Rows_affected: 0

# Bytes_sent: 68

SET timestamp=1449477044;

select count(*) from emp1 where empno=7788;

4、通过mysqldumpslow工具查看慢查询日志

[root@rh64 mysql]# mysqldumpslowCan't determine basedir from 'my_print_defaults mysqld' output: --datadir=/var/lib/mysql

--socket=/var/lib/mysql/mysql.sock

--user=mysql

--symbolic-links=0

--innodb_data_file_path=ibdata1:12M;ibdata2:10M:autoextend

--sql_mode=STRICT_TRANS_TABLES ,NO_ENGINE_SUBSTITUTION

[root@rh64 mysql]# mysqldumpslow --helpUsage: 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

[root@rh64 mysql]# mysqldumpslow rh64-slow.logReading mysql slow query log from rh64-slow.log

Count: 3  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost

# Schema: prod  Last_errno: N  Killed: N

# Query_time: N.N  Lock_time: N.N  Rows_sent: N  Rows_examined: N  Rows_affected: N

# Bytes_sent: N

SET timestamp=N;

insert into emp1 select * from emp1

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

# Schema: prod  Last_errno: N  Killed: N

# Query_time: N.N  Lock_time: N.N  Rows_sent: N  Rows_examined: N  Rows_affected: N

# Bytes_sent: N

use prod;

SET timestamp=N;

insert into emp1 select * from emp1

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

# Schema: prod  Last_errno: N  Killed: N

# Query_time: N.N  Lock_time: N.N  Rows_sent: N  Rows_examined: N  Rows_affected: N

# Bytes_sent: N

SET timestamp=N;

select count(*) from emp1 where empno=N

按照平均锁定时间进行排序，查找前10名：

[root@rh64 mysql]# mysqldumpslow -s al -n 10 rh64-slow.log

Reading mysql slow query log from rh64-slow.log

Count: 3  Time=0.00s (0s)  Lock=0.00s (0s)  Rows=0.0 (0), root[root]@localhost

# Schema: prod  Last_errno: N  Killed: N

# Query_time: N.N  Lock_time: N.N  Rows_sent: N  Rows_examined: N  Rows_affected: N

# Bytes_sent: N

SET timestamp=N;

insert into emp1 select * from emp1

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

# Schema: prod  Last_errno: N  Killed: N

# Query_time: N.N  Lock_time: N.N  Rows_sent: N  Rows_examined: N  Rows_affected: N

# Bytes_sent: N

use prod;

SET timestamp=N;

insert into emp1 select * from emp1

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

# Schema: prod  Last_errno: N  Killed: N

# Query_time: N.N  Lock_time: N.N  Rows_sent: N  Rows_examined: N  Rows_affected: N

# Bytes_sent: N

SET timestamp=N;

select count(*) from emp1 where empno=N