查看: 1720|回复: 0

[Mysql数据库] 关于long_query_time参数的一个测试

发表于 2018-4-4 08:00:02

创建测试表,其建表语句如下:

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,需要纠正这个认知。




回复

使用道具 举报