Mysql 启动慢查询日志 (不用重启) and 理解mysql的slow log

1. 查看mysql系统参数

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)

8 默认slave不会记录主库传过来的慢查询,除非开启log_slow_slave_statements为1(官方文档是这么说的),但是我在主从上都打开了这个参数,发现从库还是没有记录,这tmd是bug吧(5.6.11支持这个参数,我用的是5.6.20)


阅读更多
想对作者说点什么? 我来说一句

没有更多推荐了,返回首页