Shulou(Shulou.com)06/01 Report--

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.

Welcome to subscribe "Shulou Technology Information " to get latest news, interesting things and hot topics in the IT industry, and controls the hottest and latest Internet news, technology news and IT industry trends.