Bug #101142 Queries long due to Lock_time not logged in the slow log

• Submitted: 12 Oct 2020 22:49
• Modified: 13 Oct 2020 12:50
• Reporter: Przemyslaw Malkowski
• Status: Not a Bug
• Category: MySQL Server: Logging
• Severity: S3 (Non-critical)
• Version: 5.7.31, 8.0.20
• OS: Any
• CPU Architecture: Any
• Tags: Lock_time, slow log

[12 Oct 2020 22:49] Przemyslaw Malkowski

Description:
I noticed inconsistent slow log behavior. 
Queries that have Query_time longer than long_query_time only due to Lock_time, are not logged if long_query_time>0. It happens for both SELECTs and DMLs.

How to repeat:
mysql [localhost:8021] {msandbox} (test) > show variables where Variable_name in ('long_query_time','slow_query_log','version');
+-----------------+----------+
| Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 1.000000 |
| slow_query_log  | ON       |
| version         | 8.0.20   |
+-----------------+----------+
3 rows in set (0.00 sec)

// session 1
mysql [localhost:8021] {msandbox} (test) > begin; select count(*) from t1 for update;
Query OK, 0 rows affected (0.00 sec)

+----------+
| count(*) |
+----------+
|      992 |
+----------+
1 row in set (0.00 sec)

// session 2
mysql [localhost:8021] {msandbox} (test) > select count(*) from t1 for update;
... 

// session 1
mysql [localhost:8021] {msandbox} (test) > commit;
Query OK, 0 rows affected (0.00 sec)

// session 2
+----------+
| count(*) |
+----------+
|      992 |
+----------+
1 row in set (4.87 sec)

The query is NOT logged in slow log.

Now, when I set long_query_time=0 and repeat the same sequence, the query is logged, and looks like this:

# Time: 2020-10-12T22:44:39.521425Z
# User@Host: msandbox[msandbox] @ localhost []  Id:     8
# Query_time: 5.537417  Lock_time: 5.536248 Rows_sent: 1  Rows_examined: 0
SET timestamp=1602542673;
select count(*) from t1 for update;

Suggested fix:
I don't see any explanation why a query affected by lock wait should not be logged if exceed the long_query_time unless I miss something. So it should be probably fixed.

[13 Oct 2020 12:50] MySQL Verification Team

Hi Mr. Malkowski,

Thank you for your bug report.

However, it is not a bug.

The purpose of the slow query log is to catch the queries that are not optimised. Hence, it took us a lot of time to implement the feature, that was demanded by so many users, which is not to count lock time as a part of the query execution time.

For the lock time you can use various InnoDB tools, as well as Performance Schema.

Not a bug.