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.
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.