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

Detailed explanation of MySQL slow log (part two) option parameters section:

Http://blog.itpub.net/29773961/viewspace-2147352/

0 long_query_time

Scene:

As shown in the following figure, this figure shows partial binlog capture:

After 9:42:25, there are several 6:35:30 event

But these event are like the last one in the figure.

The exec_time is 11216, but it is not recorded in slow log.

Long_query_time is a MySQL option parameter.

Needless to say, record the SQL that exceeds the execution time and exceeds this value.

But the hole is that it is based on the real time of execution (real time), excluding the time to wait for the lock.

Take a simple example:

If long_query_time is set to 1 second

An insert is lock for 10 seconds, and execution takes only half a second, so it will not be recorded in a slow log. Test, the following is divided into three sessions, named lock >, query >, slow_log >, the same as below:

Lock > FLUSH TABLE WITH READ LOCK

Query OK, 0 rows affected (0. 00 sec)

Query > SET profiling = 1, SESSION long_query_time = 0. 5

Query OK, 0 rows affected, 1 warning (0. 00 sec)

Query > INSERT INTO t0 SELECT null, create_time, uuid FROM T1 LIMIT 1

{hang lives at this time}

Lock > UNLOCK TABLE

Query > {return}

Query OK, 1 row affected (9. 42 sec)

Records: 1 Duplicates: 0 Warnings: 0

As you can see here, the entire SQL took 9.42 seconds to complete, including a long lock wait.

Take another look at the specific profile:

Query > SHOW PROFILES

+-- -+

| | Query_ID | Duration | Query | |

+-- -+

| 1 | 9. 41687900 | INSERT INTO T0 SELECT null, create_time, uuid FROM T1 LIMIT 1 |

+-- -+

1 row in set, 1 warning (0. 00 sec)

Query > SHOW PROFILE FOR QUERY 1

+-+ +

| | Status | Duration |

+-+ +

| starting | 0. 000101 |

| checking permissions | 0. 000009 |

| checking permissions | 0. 000005 |

| Opening tables | 0. 000016 |

| Waiting for global read lock | 9. 412835 |

| Opening tables | 0. 000540 |

| init | 0. 000033 |

| System lock | 0. 000014 |

| optimizing | 0. 000006 |

| statistics | 0. 000020 |

| preparing | 0. 000016 |

| executing | 0. 000004 |

| Sending data | 0. 000241 |

| end | 0. 000006 |

| query end | 0. 002504 |

| closing tables | 0. 000012 |

| freeing items | 0. 000025 |

| logging slow query | 0. 000009 |

| Opening tables | 0. 000113 |

| System lock | 0. 000362 |

| cleaning up | 0. 000011 |

+-+ +

21 rows in set, 1 warning (0. 00 sec)

As you can see, it took 9.412835s to wait for the global read lock, and the total execution time was about 9.42.

Check the slow_ log table again. There is nothing:

Slow_log > SELECT start_time, query_time, lock_time, sql_text FROM mysql. Slow_log

Empty set (0. 00 sec)

Query > SELECT 9. 41687900-9. 412835

+-+

| 9. 41687900-9. 412835 |

+-+

| 0. 00404400 |

+-+

1 row in set (0. 00 sec)

Tips:

At this time, the execution time of SQL is 0.00404400s, so it is not recorded in slow log.

It can also be explained that some event in the figure has been executed for 3 hours, but cannot be queried in slow log.

0 lock_time and query_time

Are the two attributes recorded in slow log:

Time of lock_time:waiting for xxx lock

Total time of query_time:real time + lock time

Query > SET SESSION long_query_time = 0

Query OK, 0 rows affected (0. 00 sec)

Lock > LOCK TABLE test. T0 WRITE

Query OK, 0 rows affected (0. 00 sec)

Query > SELECT * FROM t0 LIMIT 1

{hang lives at this time}

Lock > LOCK TABLE test. T0 WRITE

Query OK, 0 rows affected (0. 00 sec)

Query > {return}

+-+

| | id | create_time | uuid | |

+-+

| | 2 | 2017-11-14 15:13:33 | 994e4592-93b4-11e7-bff9-525400b3819a |

+-+

1 row in set (28. 89 sec)

Slow_log > SELECT start_time, query_time, lock_time, sql_text FROM mysql. Slow_log

+- -- +

| | start_time | query_time | lock_time | sql_text | |

+- -- +

| 2017-11-15 17:13:12. 252836 | 00:00:28. 894675 | 00:00:28. 894516 | SELECT * FROM t0 LIMIT 1 |

+- -- +

As you can see, the query_time is also very long to make a simple query:

In fact, query_time records lock_time + real time.

Query_time ≥ lock_time

0 start_time

For the attributes recorded in slow log:

Start_time: literally, it can easily be mistaken for "sql start time".

But what is actually recorded is the time when the sql ends. Test it:

Query > SET SESSION long_query_time = 0

Query OK, 0 rows affected (0. 00 sec)

Query > SELECT sysdate (), sleep (8), sysdate ()

+-+

| | sysdate () | sleep (8) | sysdate () | |

+-+

| | 2017-11-15 17:05:15 | 0 | 2017-11-15 17:05:23 |

+-+

1 row in set (8. 00 sec)

As you can see, the sql starts at 17:05:15 and ends at 17:05:23

So the record in slow log is actually:

Slow_log > SELECT start_time, query_time, lock_time, sql_text FROM mysql. Slow_log

+- -- +

| | start_time | query_time | lock_time | sql_text | |

+- -- +

| 2017-11-15 17:05:23. 633771 | 00:00:08. 000359 | 00:00:00. 000000 | SELECT sysdate (), sleep (8), sysdate () |

+- -- +

1 row in set (0. 00 sec)

As you can see, the start_time is actually the time when the sql execution is completed.

The real method of calculating the start time is also simple:

Start_time-query_time is the time when the sql actually starts.

Tips:

In general, in OLTP scenarios, most of the query_time will be very short.

But in some bad scenarios, such as an OLAP statement that takes a long time to execute, such as 30 minutes.

If you need to confirm the sql for a certain period of time and specify the wrong start_time when querying slow log, you may not be able to find the appropriate sql.

Author's official account on Wechat (continuously updated)

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.