关于long_query_time参数的一个测试

创建测试表，其建表语句如下：

mysql> show create table test1;

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

| Table | Create Table                                                                                                                                       |

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

| test1 | CREATE TABLE `test1` (

  `a` int(10) DEFAULT NULL,

  `b` varchar(10) DEFAULT NULL,

  KEY `test_index_a` (`a`)

) ENGINE=InnoDB DEFAULT CHARSET=utf8 |

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

1 row in set (0.00 sec)

插入测试数据：

mysql> insert into test1 values (1,'a'),(2,'a'),(3,'a'),(4,'d'),(5,'e'),(6,'f'),(7,'g'),(8,'h'),(9,'i'),(10,'j'); 

Query OK, 10 rows affected (0.00 sec)

Records: 10  Duplicates: 0  Warnings: 0

mysql> select * from test1;

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

| a    | b    |

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

|    1 | a    |

|    2 | a    |

|    3 | a    |

|    4 | d    |

|    5 | e    |

|    6 | f    |

|    7 | g    |

|    8 | h    |

|    9 | i    |

|   10 | j    |

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

10 rows in set (0.00 sec)

数据库slow日志相关参数配置：

slow_query_log = 1

slow_query_log_file = /data/mysql/mysql3306/slow_statement.log

long_query_time = 0

log_queries_not_using_indexes = 0

session A：

mysql> set autocommit=0;

Query OK, 0 rows affected (0.00 sec)

mysql> update test1 set b='xx' where b='a';

Query OK, 3 rows affected (0.00 sec)

Rows matched: 3  Changed: 3  Warnings: 0

mysql> commit;

Query OK, 0 rows affected (0.01 sec)

session B：

mysql> update test1 set b='yy' where b='a';

Query OK, 0 rows affected (9.38 sec)

Rows matched: 0  Changed: 0  Warnings: 0

mysql> commit;

Query OK, 0 rows affected (0.00 sec)

慢日志记录：

# Time: 2018-03-30T02:42:16.027553Z

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

# Query_time: 0.001280  Lock_time: 0.000310 Rows_sent: 0  Rows_examined: 10

SET timestamp=1522377736;

update test1 set b='xx' where b='a';

# Time: 2018-03-30T02:42:29.785509Z

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

# Query_time: 0.008619  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0

SET timestamp=1522377749;

commit;

# Time: 2018-03-30T02:42:29.785817Z

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

# Query_time: 9.375238  Lock_time: 9.374875 Rows_sent: 0  Rows_examined: 11

SET timestamp=1522377749;

update test1 set b='yy' where b='a';

小结1：当参数long_query_time设置为0，则执行时长大于0s的语句都会记录到slowlog里面。

============================================================================

数据库slow日志相关参数配置：

slow_query_log = 1

slow_query_log_file = /data/mysql/mysql3306/slow_statement.log

long_query_time = 0.0001

log_queries_not_using_indexes = 0

session A：

mysql> set autocommit=0;

Query OK, 0 rows affected (0.00 sec)

mysql> update test1 set b='xx' where b='a';

Query OK, 3 rows affected (0.01 sec)

Rows matched: 3  Changed: 3  Warnings: 0

mysql> commit;

Query OK, 0 rows affected (0.01 sec)

session B;

mysql> set autocommit=0;

Query OK, 0 rows affected (0.00 sec)

mysql> update test1 set b='yy' where b='a';

Query OK, 0 rows affected (8.63 sec)

Rows matched: 0  Changed: 0  Warnings: 0

mysql> commit;

Query OK, 0 rows affected (0.00 sec)

慢日志记录：

# Time: 2018-03-30T02:52:11.214300Z

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

# Query_time: 0.001435  Lock_time: 0.000561 Rows_sent: 0  Rows_examined: 10

SET timestamp=1522378331;

update test1 set b='xx' where b='a';

# Time: 2018-03-30T02:52:25.326360Z

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

# Query_time: 0.007641  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0

SET timestamp=1522378345;

commit;

# Time: 2018-03-30T02:52:25.327693Z

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

# Query_time: 8.629981  Lock_time: 8.629332 Rows_sent: 0  Rows_examined: 11

SET timestamp=1522378345;

update test1 set b='yy' where b='a';

小结2：当参数long_query_time设置为0.0001，则执行时长大于0.0001s的语句都会记录到slowlog里面。

=============================================================================

数据库slow日志相关参数配置：

slow_query_log = 1

slow_query_log_file = /data/mysql/mysql3306/slow_statement.log

long_query_time = 1

log_queries_not_using_indexes = 0

session A：

mysql> set autocommit=0;

Query OK, 0 rows affected (0.00 sec)

mysql> update test1 set b='xx' where b='a';

Query OK, 3 rows affected (0.00 sec)

Rows matched: 3  Changed: 3  Warnings: 0

mysql> commit;

Query OK, 0 rows affected (0.00 sec)

session B：

mysql> set autocommit=0;

Query OK, 0 rows affected (0.00 sec)

mysql> update test1 set b='yy' where b='a';

Query OK, 0 rows affected (10.13 sec)

Rows matched: 0  Changed: 0  Warnings: 0

mysql> commit;

Query OK, 0 rows affected (0.00 sec)

慢日志记录：

# Time: 2018-03-30T02:56:32.433616Z

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

# Query_time: 0.001227  Lock_time: 0.000149 Rows_sent: 1  Rows_examined: 1050

SET timestamp=1522378592;

SHOW VARIABLES LIKE 'pid_file';

/usr/local/mysql/bin/mysqld, Version: 5.7.20-log (MySQL Community Server (GPL)). started with:

Tcp port: 3306  Unix socket: /data/mysql/mysql3306/mysql3306.sock

Time                 Id Command    Argument

小结3：当参数long_query_time设置为1，则执行时长不大于1s的语句不会记录到slowlog里面。

总结：从上面3个实验可以发现，参数long_query_time影响了慢SQL在slowlog的记录。只有运行时长大于long_query_time参数的SQL，才会记录到slowlog。这个运行时长，是不包括由于事务锁等待消耗的时间的。

也就是说，exec_time= query_time - lock_time。 当exec_time >= long_query_time的SQL才会被记录到慢SQL里面。很多人会误认为只有query_time>= long_query_time就会记录到slowlog，需要纠正这个认知。