理解mysql的slow log

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）