MySQL Bugs: #111935: The procedure contains an alter table and the slow log output is inaccurate

Bug #111935	The procedure contains an alter table and the slow log output is inaccurate
Submitted:	1 Aug 2023 7:50	Modified:	1 Aug 2023 14:29
Reporter:	xiang wang	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S4 (Feature request)
Version:	8.0	OS:	Any
Assigned to:		CPU Architecture:	Any

Description:
When log_slow_admin_statements set to on.When  procedure contains an alter table, the execution time of the procedure exceeds long_query_time, the slow log will record statements after the alter table.

How to repeat:
my.cnf
[mysqld]
log_slow_admin_statements=on
long_query_time=1

table t:
create table t(id int primary key,var char(20));
insert into t values(1,'aa'),(2,'bb');

procedure:
DELIMITER $$
create procedure test()
BEGIN
update t set var='bb' where id=sleep(2);
alter table t add age int;
select now();
END $$
DELIMITER ;

execute procedure test:
call test();

slow log output,select now() Query_time: 4.008146:

# Time: 2023-08-01T15:46:31.414862+08:00
# User@Host: root[root] @ localhost []  Id: 16610
# Query_time: 4.008146  Lock_time: 0.000200 Rows_sent: 1  Rows_examined: 3
SET timestamp=1690875991;
select now();
# Time: 2023-08-01T15:46:31.414943+08:00
# User@Host: root[root] @ localhost []  Id: 16610
# Query_time: 4.008227  Lock_time: 0.000000 Rows_sent: 1  Rows_examined: 3
SET timestamp=1690875991;
call test();

Hi Mr. wang,

Thank you for your bug report.

However, the release that you are using is ancient.

We have tested your test case with 8.0.34 and we get syntax errors in your definition of the stored procedure.

Unsupported.

Testing on MySQL 8.0.33：

#my.cnf configuration：
[mysqld]
log_slow_admin_statements=on
long_query_time=1

#Execute the following statement：
create database test;
use test;
create table t(id int primary key,var char(20));
insert into t values(1,'aa'),(2,'bb');
DELIMITER $$
create procedure test()
BEGIN
update t set var='bb' where id=sleep(2);
alter table t add age int;
select now();
END $$
DELIMITER ;
call test();

#slow log oputout，Among them, select now() did not execute for 4 seconds:

# Time: 2023-08-01T21:09:10.185192+08:00
# User@Host: root[root] @ localhost []  Id:   169
# Query_time: 4.011447  Lock_time: 0.000026 Rows_sent: 1  Rows_examined: 3
use test;
SET timestamp=1690895350;
select now();
# Time: 2023-08-01T21:09:10.185675+08:00
# User@Host: root[root] @ localhost []  Id:   169
# Query_time: 4.011930  Lock_time: 0.000004 Rows_sent: 1  Rows_examined: 3
SET timestamp=1690895350;
call test();

Hi,

This time, we were able to repeat the test case, we got this in the slow query log:

Time                 Id Command    Argument
# Time: 2023-08-01T14:15:41.426023Z
# User@Host: admin[admin] @ localhost []  Id:     8
# Query_time: 4.020971  Lock_time: 0.000018 Rows_sent: 1  Rows_examined: 3
use test;
SET timestamp=1690899341;
select now();
# Time: 2023-08-01T14:15:41.426363Z
# User@Host: sinisa[sinisa] @ localhost []  Id:     8
# Query_time: 4.021311  Lock_time: 0.000002 Rows_sent: 1  Rows_examined: 3
SET timestamp=1690899341;
call test();
-----------------------------

This is expected behaviour. However, we suppose you wished to see the following command in it:

update t set var='bb' where id=sleep(2);

This is truly a bug, but very low priority bug. Actually, this is a feature request.

Verified.

HI,

It affects both 8.0.34 and 8.1.0.