關于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，需要糾正這個認知。