Bug #96722 Event does't record slow insert in slow log
Submitted: 3 Sep 2019 3:19 Modified: 10 Dec 2019 6:37
Reporter: yunsheng zhu (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Logging Severity:S3 (Non-critical)
Version:5.6.28, 5.6.45, 5.7.27 OS:Any
Assigned to: CPU Architecture:Any

[3 Sep 2019 3:19] yunsheng zhu
Description:
Phenomenon:
1. Slow select in an event was recorded in slow log.
2. Slow insert in an event was not recorded in slow log unless there were slow select before this insert.

Reason:
(1)THD::server_status was updated in sp_instr_stmt::execute only when thd->get_stmt_da()->is_eof() is true as follows:
if (thd->get_stmt_da()->is_eof())
{
  /* Finalize server status flags after executing a statement. */
  thd->update_server_status();

  thd->protocol->end_statement();
}
As eof flag is only set for select not update/insert/delete, slow update/insert/delete will not be marked as slow in thd->update_server_status.

(2)If there are multiple statements in an event, THD::server_status will not be cleared until the laste statement was executed.So if there
are slow select before update/insert/delete, THD::server_status will be marked with SERVER_QUERY_WAS_SLOW, and the following update/insert/delete
will be treated as slow even they are quick.

How to repeat:
step1: create table ta and insert data
drop table if exists ta;
create table ta (id int auto_increment primary key,c1 varchar(200));

DROP PROCEDURE IF EXISTS pre_test;  
DELIMITER // 
CREATE PROCEDURE pre_test()  
BEGIN  
DECLARE i INT DEFAULT 1;   
WHILE i<1024 DO  
INSERT INTO ta VALUES( NULL, CONCAT( 'Carl', i ) );  
SET i = i+1;  
END WHILE;  
END; // 
DELIMITER ; 
CALL pre_test();

step2: set long_query_time
set global long_query_time = 1;

step3: create event with slow insert
drop table if exists tb;
create table tb (id int auto_increment primary key,c1 varchar(200));

drop event if exists test_zpl;
delimiter ;;
create event test_zpl ON SCHEDULE EVERY 20 minute STARTS CURRENT_TIMESTAMP  ON COMPLETION PRESERVE ENABLE  DO BEGIN
insert into tb select t11.* from ta t11,ta t22
on duplicate key update tb.c1=concat(t11.c1,tb.c1);
end;;
delimiter ;

# slow insert will not be logged in slow log

step4: create event with slow select and slow insert
drop table if exists tb;
create table tb (id int auto_increment primary key,c1 varchar(200));

drop event if exists test_zpl;
delimiter ;;
create event test_zpl ON SCHEDULE EVERY 20 minute STARTS CURRENT_TIMESTAMP  ON COMPLETION PRESERVE ENABLE  DO BEGIN
select sleep(5);
insert into tb select t11.* from ta t11,ta t22
on duplicate key update tb.c1=concat(t11.c1,tb.c1);
end;;
delimiter ;

# slow select and slow insert will both be logged in slow log

step5: create event with slow select and quick insert
drop table if exists tb;
create table tb (id int auto_increment primary key,c1 varchar(200));

drop event if exists test_zpl;
delimiter ;;
create event test_zpl ON SCHEDULE EVERY 20 minute STARTS CURRENT_TIMESTAMP  ON COMPLETION PRESERVE ENABLE  DO BEGIN
select sleep(5);
insert into tc values(NULL, 'test');
end;;
delimiter ;

# slow select and quick insert will both be logged in slow log

Suggested fix:
(1)update server status if thd->get_stmt_da()->is_eof() or thd->get_stmt_da()->is_ok().
(2)clear  server status after each statement was executed.
[9 Sep 2019 10:56] MySQL Verification Team
Hello yunsheng zhu,

Thank you for the report and test case.
Verified as described on 5.6.45 build.

regards,
Umesh
[10 Dec 2019 6:37] yunsheng zhu
We are from Tencent TXSQL Team.