A test on the long_query_time parameter
Create a test table with the following statement:
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)
Insert test data:
Mysql > insert into test1 values (1), (2)), (3), (4), (5), (6), (7), (8), (9), (10)
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)
Configuration of database slow log related parameters:
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 breadcrumbs xx' where breadwinners
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 breadwinner yyy` where breadcrumbs'
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)
Slow logging:
# 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 breadwinner xx' where breadcracker 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 baccalaureate yyy' where breadcrumb
Summary 1: when the parameter long_query_time is set to 0, statements with execution time longer than 0s will be recorded in slowlog.
=
Configuration of database slow log related parameters:
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 breadcrumbs xx' where breadwinners
Query OK, 3 rows affected (0.01sec)
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 breadwinner yyy` where breadcrumbs'
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)
Slow logging:
# 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 breadwinner xx' where breadcracker 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 baccalaureate yyy' where breadcrumb
Summary 2: when the parameter long_query_time is set to 0.0001, statements with execution time longer than 0.0001s will be recorded in slowlog.
=
Configuration of database slow log related parameters:
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 breadcrumbs xx' where breadwinners
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 breadwinner yyy` where breadcrumbs'
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)
Slow logging:
# 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
Summary 3: when the parameter long_query_time is set to 1, statements with execution time not longer than 1 s will not be recorded in slowlog.
Summary: from the above three experiments, it can be found that the parameter long_query_time affects the recording of slow SQL in slowlog. Only SQL that runs longer than the long_query_time parameter will be logged to slowlog. This runtime does not include the time elapsed due to transaction lock waiting.
In other words, exec_time= query_time-lock_time. Only when exec_time > = long_query_time is the SQL recorded in the slow SQL. Many people will mistakenly think that only query_time > = long_query_time will be recorded to slowlog, and this perception needs to be corrected.
