MySQL Bugs: #116651: slow log start

Bug #116651	slow log start_time is incorrect
Submitted:	14 Nov 2024 11:27	Modified:	14 Nov 2024 13:04
Reporter:	karry zhang (OCA)	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S3 (Non-critical)
Version:	8.0	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
I found slow log using TABLE format, the start_time is is the end time of sql.
I found a similar bug report before. For the file format slow log, after setting log_slow_extra, the Start field was changed to the start time of the sql.
But unfortunately, for the table format, the start_time field value has not changed.

How to repeat:
Set slow_query_log = ON and log_output=TABLE in cnf.

Execute the following statement:

set long_query_time = 1;
select now();
select sleep(10);
select * from mysql.slow_log;

Suggested fix:
Set the start_time field to the sql start time.

Hi Mr. zhang,

Thank you for your bug report.

We have managed to repeat the behaviour your reported:

mysql> select now();
+---------------------+
| now()               |
+---------------------+
| 2024-11-14 14:57:20 |
+---------------------+
1 row in set (0.00 sec)

mysql> select sleep(3);
+----------+
| sleep(3) |
+----------+
|        0 |
+----------+
1 row in set (3.00 sec)

mysql> select sleep(3);
+----------+
| sleep(3) |
+----------+
|        0 |
+----------+
1 row in set (3.00 sec)

mysql> select * from mysql.slow_log;
+----------------------------+-------------------------------+-----------------+-----------------+-----------+---------------+------+----------------+-----------+-----------+----------------------------------+-----------+
| start_time                 | user_host                     | query_time      | lock_time       | rows_sent | rows_examined | db   | last_insert_id | insert_id | server_id | sql_text                         | thread_id |
+----------------------------+-------------------------------+-----------------+-----------------+-----------+---------------+------+----------------+-----------+-----------+----------------------------------+-----------+
| 2024-11-14 14:57:27.793828 | xxx[xxx] @xxxxx [] | 00:00:03.002395 | 00:00:00.000000 |         1 |             1 | test |              0 |         0 |     82721 | 0x73656C65637420736C656570283329 |         8 |
| 2024-11-14 14:57:32.471752 | xxx[xxx] @xxxxt [] | 00:00:03.001056 | 00:00:00.000000 |         1 |             1 | test |              0 |         0 |     82721 | 0x73656C65637420736C656570283329 |         8 |
+----------------------------+-------------------------------+-----------------+-----------------+-----------+---------------+------+----------------+-----------+-----------+----------------------------------+-----------+
4 rows in set (0.00 sec)

Verified as reported for version 8.0 and higher.

Setting category ......

Fix patch (*) I confirm the code being submitted is offered under the terms of the OCA, and that I am authorized to contribute it.

Contribution: fix.patch (application/octet-stream, text), 503 bytes.

Thank you, Mr. zhang, for your contribution.