Bug #115841 Lock_time in slow log does not correctly record the lock waiting time
Submitted: 15 Aug 2024 4:15 Modified: 15 Aug 2024 7:01
Reporter: Ruyi Zhang (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Logging Severity:S3 (Non-critical)
Version:8.0.39, 8.4.2 OS:Any
Assigned to: CPU Architecture:Any
Tags: slow-log

[15 Aug 2024 4:15] Ruyi Zhang
Description:
We found that in 8.0.39, the time spent waiting for the lock was not correctly recorded in the Lock_time of the slow log. 

In other words, even if the execution time of the query itself is very short, if the waiting time for the lock is relatively long, it will still be recorded in the slow log.

The following MTR can help reproduce this problem.

How to repeat:
--long_query_time=0
--slow_query_log=ON
```
--connect (con1, localhost, root)
--connection default
create table t(id int);
lock table t write;
--connection con1
send select * from t;
--connection default
select sleep(5);
unlock tables;
--connection con1
reap;
--exec tail -20 $MYSQLTEST_VARDIR/mysqld.1/mysqld-slow.log
--disable_query_log
drop table t;

```
In The Result, Lock_time is only 0.000019 for query select * from t;
```
create table t(id int);
lock table t write;
select * from t;
select sleep(5);
sleep(5)
0
unlock tables;
id
# Time: 2024-08-15T04:09:21.312677Z
# User@Host: root[root] @ localhost []  Id:     9
# Query_time: 0.009279  Lock_time: 0.000043 Rows_sent: 0  Rows_examined: 0
SET timestamp=1723694961;
lock table t write;
# Time: 2024-08-15T04:09:26.313059Z
# User@Host: root[root] @ localhost []  Id:     9
# Query_time: 5.000313  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 1
SET timestamp=1723694961;
select sleep(5);
# Time: 2024-08-15T04:09:26.313409Z
# User@Host: root[root] @ localhost []  Id:     9
# Query_time: 0.000220  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1723694966;
unlock tables;
# Time: 2024-08-15T04:09:26.314167Z
# User@Host: root[root] @ localhost []  Id:    10
# Query_time: 5.001421  Lock_time: 0.000019 Rows_sent: 0  Rows_examined: 0
SET timestamp=1723694961;
select * from t;
```
[15 Aug 2024 7:01] MySQL Verification Team
Hello Zhang Ruyi,

Thank you for the report and test case.

regards,
Umesh