關(guān)于long_query_time參數(shù)的一個(gè)測(cè)試

創(chuàng)建測(cè)試表，其建表語(yǔ)句如下：

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)

插入測(cè)試數(shù)據(jù)：

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)

數(shù)據(jù)庫(kù)slow日志相關(guān)參數(shù)配置：

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';

小結(jié)1：當(dāng)參數(shù)long_query_time設(shè)置為0，則執(zhí)行時(shí)長(zhǎng)大于0s的語(yǔ)句都會(huì)記錄到slowlog里面。

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

數(shù)據(jù)庫(kù)slow日志相關(guān)參數(shù)配置：

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';

小結(jié)2：當(dāng)參數(shù)long_query_time設(shè)置為0.0001，則執(zhí)行時(shí)長(zhǎng)大于0.0001s的語(yǔ)句都會(huì)記錄到slowlog里面。

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

數(shù)據(jù)庫(kù)slow日志相關(guān)參數(shù)配置：

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

小結(jié)3：當(dāng)參數(shù)long_query_time設(shè)置為1，則執(zhí)行時(shí)長(zhǎng)不大于1s的語(yǔ)句不會(huì)記錄到slowlog里面。

總結(jié)：從上面3個(gè)實(shí)驗(yàn)可以發(fā)現(xiàn)，參數(shù)long_query_time影響了慢SQL在slowlog的記錄。只有運(yùn)行時(shí)長(zhǎng)大于long_query_time參數(shù)的SQL，才會(huì)記錄到slowlog。這個(gè)運(yùn)行時(shí)長(zhǎng)，是不包括由于事務(wù)鎖等待消耗的時(shí)間的。

也就是說(shuō)，exec_time= query_time - lock_time。 當(dāng)exec_time >= long_query_time的SQL才會(huì)被記錄到慢SQL里面。很多人會(huì)誤認(rèn)為只有query_time>= long_query_time就會(huì)記錄到slowlog，需要糾正這個(gè)認(rèn)知。