| Bug #117422 | The start_time is incorrect when call procedure | ||
|---|---|---|---|
| Submitted: | 10 Feb 9:12 | Modified: | 11 Feb 13:01 |
| Reporter: | karry zhang (OCA) | Email Updates: | |
| Status: | Verified | Impact on me: | |
| Category: | MySQL Server: Logging | Severity: | S3 (Non-critical) |
| Version: | MySQL8.0,8.0.41 | OS: | Any |
| Assigned to: | CPU Architecture: | Any | |
[11 Feb 7:44]
MySQL Verification Team
Hello karry zhang, Thank you for the report and feedback. regards, Umesh
[11 Feb 7:56]
MySQL Verification Team
Hello karry zhang,
I can confirm that "Time" is wrong in 5.7 but seems to be fine in 8.0.41, could you please confirm? Thank you.
-- 5.7.44 ( --log-slow-extra was introduced in 8.0.14)
BugNumber=117422
rm -rf $BugNumber/
bin/mysqld --no-defaults --initialize-insecure --basedir=$PWD --datadir=$PWD/$BugNumber --log-error-verbosity=3
bin/mysqld_safe --no-defaults --mysqld-version='' --basedir=$PWD --datadir=$PWD/$BugNumber --core-file --socket=/tmp/mysql.sock --port=3306 --log-error=$PWD/$BugNumber/log.err --mysqlx-port=33330 --mysqlx-socket=/tmp/mysql_x_ushastry.sock --log-error-verbosity=3 --secure-file-priv="" --local-infile=1 --slow_query_log=ON --long_query_time=1 --log_output=FILE 2>&1 &
bin/mysql -uroot -S/tmp/mysql.sock
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 2
Server version: 5.7.44-log MySQL Community Server (GPL)
Copyright (c) 2000, 2023, Oracle and/or its affiliates.
Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
mysql> use test
ERROR 1049 (42000): Unknown database 'test'
mysql> create database test;
Query OK, 1 row affected (0.00 sec)
mysql> use test;
Database changed
mysql> DELIMITER $$
mysql>
mysql> CREATE PROCEDURE SleepWithMessages()
-> BEGIN
-> SELECT 'Sleeping for 30 seconds...' AS Message;
->
-> DO SLEEP(30);
->
-> SELECT 'Woke up after 30 seconds!' AS Message;
-> END $$
Query OK, 0 rows affected (0.00 sec)
mysql>
mysql> DELIMITER ;
mysql>
mysql> select now();
+---------------------+
| now() |
+---------------------+
| 2025-02-11 08:47:05 |
+---------------------+
1 row in set (0.00 sec)
mysql>
mysql> call SleepWithMessages();
+----------------------------+
| Message |
+----------------------------+
| Sleeping for 30 seconds... |
+----------------------------+
1 row in set (0.00 sec)
+---------------------------+
| Message |
+---------------------------+
| Woke up after 30 seconds! |
+---------------------------+
1 row in set (30.00 sec)
Query OK, 0 rows affected (30.00 sec)
-- slow log contents
cat 117422/support-cluster03-slow.log
/export/home/tmp/ushastry/mysql-5.7.44/bin/mysqld, Version: 5.7.44-log (MySQL Community Server (GPL)). started with:
Tcp port: 3306 Unix socket: /tmp/mysql.sock
Time Id Command Argument
# Time: 2025-02-11T07:47:35.806507Z
# User@Host: root[root] @ localhost [] Id: 2
# Query_time: 30.000420 Lock_time: 0.000023 Rows_sent: 2 Rows_examined: 0
use test;
SET timestamp=1739260055;
call SleepWithMessages();
-- 8.0.41
mysql> select now();
+---------------------+
| now() |
+---------------------+
| 2025-02-11 08:33:09 |
+---------------------+
1 row in set (0.00 sec)
mysql>
mysql> call SleepWithMessages();
+----------------------------+
| Message |
+----------------------------+
| Sleeping for 30 seconds... |
+----------------------------+
1 row in set (0.00 sec)
+---------------------------+
| Message |
+---------------------------+
| Woke up after 30 seconds! |
+---------------------------+
1 row in set (30.00 sec)
-- slow query log ( pls ignore time diff )
cat 117422/support-cluster03-slow.log
/export/home/tmp/ushastry/mysql-8.0.41/bin/mysqld, Version: 8.0.41 (MySQL Community Server - GPL). started with:
Tcp port: 3306 Unix socket: /tmp/mysql.sock
Time Id Command Argument
# Time: 2025-02-11T07:33:40.730169Z
# User@Host: root[root] @ localhost [] Id: 7
# Query_time: 30.000454 Lock_time: 0.000002 Rows_sent: 2 Rows_examined: 3 Thread_id: 7 Errno: 0 Killed: 0 Bytes_received: 31 Bytes_sent: 170 Read_first: 0 Read_last: 0 Read_key: 2 Read_next: 0 Read_prev: 0 Read_rnd: 0 Read_rnd_next: 0 Sort_merge_passes: 0 Sort_range_count: 0 Sort_rows: 0 Sort_scan_count: 0 Created_tmp_disk_tables: 0 Created_tmp_tables: 0 Start: 2025-02-11T07:33:40.730093Z End: 2025-02-11T07:34:10.730547Z
use test;
SET timestamp=1739259220;
call SleepWithMessages();
^^ We can see both Time/Start and End are clearly different. Anything am missing here? Please let me know. Thank you.
regards,
Umesh
[11 Feb 12:55]
karry zhang
The Time filed is infact the end time of call SleepWithMessages(), there is no problem with the value of this field, but there is no corresponding description of this field in the official documentation. The Start is the start time of call SleepWithMessages(), the End is the end time of call SleepWithMessages(), you can see it in https://dev.mysql.com/doc/refman/8.0/en/slow-query-log.html. But unfortunately, when calling procedure, the value of Start is wrong. You can see in your test case that it is basically the same as the Time field, both are 2025-02-11T07:33:40. The value of End is Start plus Query_time, so End is also wrong. You can create the following procedure and execute the above operations. You can observe the correct values of the corresponding fields. DELIMITER $$ CREATE PROCEDURE SleepWithNoMessages() BEGIN DO SLEEP(30); END $$ DELIMITER ; And why calling SleepWithNoMessages will cause incorrect Start and End? I have analyzed it in the comment above.
[11 Feb 13:01]
karry zhang
Correction to the previous comment: it is calling SleepWithMessages that causes the problem.
Description: We know for the file format slow log, after setting log_slow_extra, the Start field is the start time of the sql. And we can also find SET timestamp=xxx; in the log file to see the start time of sql too. However, we found that when we call procedure, these two fields are incorrect. They record the end time of calling procedure. How to repeat: Set slow_query_log = ON long_query_time=1 log_output=FILE log_slow_extra=ON in cnf. Execute the following statement: DELIMITER $$ CREATE PROCEDURE SleepWithMessages() BEGIN SELECT 'Sleeping for 30 seconds...' AS Message; DO SLEEP(30); SELECT 'Woke up after 30 seconds!' AS Message; END $$ DELIMITER ; select now(); call SleepWithMessages(); and the check the slow log file， you can see the Start filed is the end time of call procedure, and the set timestamp = xxx; is incorrect too. Suggested fix: The root cause of this problem is that reset_start_time_for_sp is called every time a statement in procedure is executed. And when we determine whether it is a slow query, we use thd->start_utime in the function update_slow_query_status, but when recording, we use thd->start_time in the function log_slow, which is very strange. Is it just for the time accuracy of microseconds?