Bug #84662 check whether a query be slow log should add lock time.

• Submitted: 25 Jan 2017 8:18
• Reporter: rj03hou rj03hou
• Status: Open
• Category: MySQL Server: Logging
• Severity: S4 (Feature request)
• OS: Any
• CPU Architecture: Any

[25 Jan 2017 8:18] rj03hou rj03hou

Description:
The slow log output include Query_time and Lock_time, the Query_time is include exact execute time and lock time. But the judge whether a query be slow log don't include the lock waiting time, so is confused.

In the user's perspective, Query_time include lock waiting time, so I think the judge whether a query be slow log should include lock waiting time.

# Time: 170125  7:16:19
# User@Host: guest[guest] @ localhost [127.0.0.1]  Id:  5369
# Schema: test  Last_errno: 0  Killed: 0
# Query_time: 5.003378  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0  Rows_affected: 0
# Bytes_sent: 63
SET timestamp=1485328579;
select sleep(5);

If you agree this, I can write the code and PR in github. 

How to repeat:
CREATE TABLE `test` (
  `id` int(11) NOT NULL DEFAULT '0',
  `name` varchar(255) DEFAULT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB;

insert into test values(1,"xx");

set global slow_query_log=ON;
set global long_query_time=1;

session1:
mysql> begin;
Query OK, 0 rows affected (0.00 sec)

mysql> update test set name="xx" where id=4;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

mysql> select sleep(5);

mysql> rollback;
Query OK, 0 rows affected (0.03 sec)

session2:
mysql> update test set name="xx1" where id=4 and sleep(0.9);
Query OK, 0 rows affected (22.12 sec)
Rows matched: 0  Changed: 0  Warnings: 0

mysql> update test set name="xx1" where id=4 and sleep(1.1);
Query OK, 0 rows affected (15.38 sec)
Rows matched: 0  Changed: 0  Warnings: 0

Read the slow log, can find only the second query of session2 is log in slow log.

Suggested fix:
Modify the judge method of slow log, if you agree this, I can write the code and PR in github.