mysql> show variables like "%slow%";
+---------------------------+-------------------------------+
| Variable_name | Value |
+---------------------------+-------------------------------+
| log_slow_admin_statements | OFF |
| log_slow_slave_statements | OFF |
| slow_launch_time | 2 |
| slow_query_log | OFF |
| slow_query_log_file | /mysql/data/nagiosdb-slow.log |
+---------------------------+-------------------------------+
5 rows in set (0.00 sec)
slow_query_log: off关闭状态 on开启状态
slow_launch_time 默认超过2s为慢查询
slow_query_log_file 慢查询日志存放地点
这三个参数,在不同的mysql版本中,不太一样,不过都可以通过 show variables like "%slow%" 查看出来
2. 运行如下命令即可运行慢查询日志
mysql> set global slow_query_log=ON;
Query OK, 0 rows affected (0.03 sec)
mysql> set global slow_launch_time=5;
Query OK, 0 rows affected (0.00 sec)
mysql> show variables like "%slow%";
+---------------------------+-------------------------------+
| Variable_name | Value |
+---------------------------+-------------------------------+
| log_slow_admin_statements | OFF |
| log_slow_slave_statements | OFF |
| slow_launch_time | 5 |
| slow_query_log | ON |
| slow_query_log_file | /mysql/data/nagiosdb-slow.log |
+---------------------------+-------------------------------+
5 rows in set (0.00 sec)
mysql 5.1.6版本起,slow_query_log 和 slow_launch_time 支持写文件或写数据库表两种方式,并且日志的开启,输出方式的修改,都可以在global级别动态修改。
只需简单通过set global slow_query_log=ON;即可开启慢查询,而不需要重启数据库!
3. 可以直接写到配置文件中 my.cnf
slow_query_log_file=/mysql/log/nagiosdb-slow.log
slow_launch_time=5
可以完成配置!!
*************************************************************
PS:所有的前提,慢查询时间设置为3s
1 log_output参数为TABLE时,慢查询记录到mysql.slow_log表里,但这时这个系统表没有任何索引,我们一般可以在start_time列自行加上索引方便检索,类似这样
mysql> show create table mysql.slow_log\G
*************************** 1. row ***************************
Table: slow_log
Create Table: CREATE TABLE `slow_log` (
`start_time` timestamp NOT NULL DEFAULT CURRENT_TIMESTAMP ON UPDATE CURRENT_TIMESTAMP,
`user_host` mediumtext NOT NULL,
`query_time` time NOT NULL,
`lock_time` time NOT NULL,
`rows_sent` int(11) NOT NULL,
`rows_examined` int(11) NOT NULL,
`db` varchar(512) NOT NULL,
`last_insert_id` int(11) NOT NULL,
`insert_id` int(11) NOT NULL,
`server_id` int(10) unsigned NOT NULL,
`sql_text` mediumtext NOT NULL,
KEY `start_time` (`start_time`)
) ENGINE=MyISAM DEFAULT CHARSET=utf8 COMMENT='Slow log'
1 row in set (0.00 sec)
2 start_time指的是SQL结束时间,而不是开始执行时间。
mysql> select now();
+---------------------+
| now() |
+---------------------+
| 2016-06-13 11:34:12 |
+---------------------+
1 row in set (0.00 sec)
mysql> select sleep(20);
+-----------+
| sleep(20) |
+-----------+
| 0 |
+-----------+
1 row in set (19.99 sec)
mysql> select now();
+---------------------+
| now() |
+---------------------+
| 2016-06-13 11:34:47 |
+---------------------+
1 row in set (0.00 sec)
start_time: 2016-06-13 11:34:46
user_host: ucloudbackup[ucloudbackup] @ [10.10.249.91]
query_time: 00:00:20
lock_time: 00:00:00
rows_sent: 1
rows_examined: 0
db: test
last_insert_id: 0
insert_id: 0
server_id: 168491355
sql_text: select sleep(20)
10 rows in set (0.00 sec)
3 log_queries_not_using_indexes为1时,会记录任何不使用索引的sql,从而无视long_query_time参数
mysql> set global log_queries_not_using_indexes=1;
Query OK, 0 rows affected (0.00 sec)
虽然是global变量,但不用重开session
mysql> select * from xx limit 1;
+------+------+
| id | dd |
+------+------+
| 123 | NULL |
+------+------+
1 row in set (0.00 sec)
start_time: 2016-06-13 11:38:04
user_host: ucloudbackup[ucloudbackup] @ [10.10.249.91]
query_time: 00:00:00
lock_time: 00:00:00
rows_sent: 1
rows_examined: 1
db: test
last_insert_id: 0
insert_id: 0
server_id: 168491355
sql_text: select * from xx limit 1
12 rows in set (0.00 sec)
4 默认情况下不会记录DDL操作,不管执行时间多长,除非将log_slow_admin_statements参数设置为1,而这个参数只在5.6.11后支持
mysql> alter table xx add column dd varchar(100);
Query OK, 8388608 rows affected (1 min 4.47 sec)
Records: 8388608 Duplicates: 0 Warnings: 0
mysql> select * from mysql.slow_log where sql_text like '%alter%';
Empty set (0.00 sec)
5 在log_queries_not_using_indexes为1的情况下,默认没走索引的sql有多少就记录多少,而设置了log_throttle_queries_not_using_indexes为N后,表示1分钟内该SQL最多记录N条,这个参数在5.6.5后支持
set global log_queries_not_using_indexes=1;
set global log_queries_not_using_indexes=1;
mysql> select * from xx;
Empty set (0.00 sec)
mysql> select * from xx;
Empty set (0.00 sec)
mysql> select * from xx;
Empty set (0.00 sec)
mysql> select * from mysql.slow_log where sql_text like '%xx%';
+---------------------+----------------------------------------------+------------+-----------+-----------+---------------+------+----------------+-----------+-----------+------------------+-----------+
| start_time | user_host | query_time | lock_time | rows_sent | rows_examined | db | last_insert_id | insert_id | server_id | sql_text | thread_id |
+---------------------+----------------------------------------------+------------+-----------+-----------+---------------+------+----------------+-----------+-----------+------------------+-----------+
| 2016-06-13 11:45:50 | ucloudbackup[ucloudbackup] @ [10.10.218.80] | 00:00:00 | 00:00:00 | 0 | 0 | test | 0 | 0 | 168483408 | select * from xx | 29 |
+---------------------+----------------------------------------------+------------+-----------+-----------+---------------+------+----------------+-----------+-----------+------------------+-----------+
1 row in set (0.00 sec)
6 默认情况下有记录就记录,而设置了min_examined_row_limit为N后,表示只有返回条数大于N才记录到慢查询
mysql> set min_examined_row_limit=1;
Query OK, 0 rows affected (0.00 sec)
mysql> select sleep(4.5);
+------------+
| sleep(4.5) |
+------------+
| 0 |
+------------+
1 row in set (4.50 sec)
mysql> select * from mysql.slow_log where sql_text like '%sleep(4.5)%';
Empty set (0.00 sec)
mysql> show variables like '%long%';
+---------------------------------------------------+----------+
| Variable_name | Value |
+---------------------------------------------------+----------+
| long_query_time | 3.000000 |
| max_long_data_size | 16777216 |
| performance_schema_events_waits_history_long_size | 10000 |
+---------------------------------------------------+----------+
3 rows in set (0.00 sec)
mysql> set min_examined_row_limit=0;
Query OK, 0 rows affected (0.00 sec)
mysql> select sleep(4.5);
+------------+
| sleep(4.5) |
+------------+
| 0 |
+------------+
1 row in set (4.50 sec)
mysql> select * from mysql.slow_log where sql_text like '%sleep(4.5)%';
+---------------------+----------------------------------------------+------------+-----------+-----------+---------------+------+----------------+-----------+-----------+-------------------+
| start_time | user_host | query_time | lock_time | rows_sent | rows_examined | db | last_insert_id | insert_id | server_id | sql_text |
+---------------------+----------------------------------------------+------------+-----------+-----------+---------------+------+----------------+-----------+-----------+-------------------+
| 2016-06-13 11:27:07 | ucloudbackup[ucloudbackup] @ [10.10.249.91] | 00:00:04 | 00:00:00 | 1 | 0 | test | 0 | 0 | 168491355 | select sleep(4.5) |
+---------------------+----------------------------------------------+------------+-----------+-----------+---------------+------+----------------+-----------+-----------+-------------------+
1 row in set (0.00 sec)
7 只有sql的实际执行时间超过long_query_time,才会记录到慢查询(这里的实际执行时间排除了lock的时间),而当记录到slow_log后,query_time列记录的时间是实际执行时间+lock_time的时间。
case 1 实际执行时间为5s,lock时间为40s,记录到慢查询
session 1 执行
mysql> flush tables with read lock;
Query OK, 0 rows affected (0.00 sec)
session 2执行以下sql,这时sql被锁住
mysql> insert into xx values (sleep(5));
session1断开连接释放全局读锁
session2 经过5s后执行完成
mysql> insert into xx values (sleep(5));
Query OK, 1 row affected (45.27 sec)
这时查看mysql.slow_log
start_time: 2016-06-13 11:54:15
user_host: ucloudbackup[ucloudbackup] @ [10.10.218.80]
query_time: 00:00:45
lock_time: 00:00:40
rows_sent: 0
rows_examined: 0
db: test
last_insert_id: 0
insert_id: 0
server_id: 168483408
sql_text: insert into xx values (sleep(5))
thread_id: 34
14 rows in set (0.00 sec)
可以看到query_time为45s,locktime为40s,query_time是40+5,包括了lock时间和实际执行时间
case 2 实际执行时间为1s,locktime为5s,不记录慢查询
session 1执行flush tables with read lock;
session 2 执行mysql> insert into xx values (sleep(1));
断开session1释放全局读锁
session2过1s后执行完成,总耗时为6s
mysql> insert into xx values (sleep(1));
Query OK, 1 row affected (6.02 sec)
查看慢查询,无session2的记录
mysql> select * from mysql.slow_log where sql_text like '%sleep(1)%';
Empty set (0.00 sec)