Bug #96849 some events are delayed after dropping event
Submitted: 12 Sep 2019 12:52 Modified: 17 Dec 2019 19:47
Reporter: yunsheng zhu (OCA) Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Stored Routines Severity:S2 (Serious)
Version:MySQL 5.6.28, 5.7.18, 8.0.15 OS:Any
Assigned to: CPU Architecture:Any

[12 Sep 2019 12:52] yunsheng zhu
Description:
We have a client whose business is seriously dependent on event. There are about 50 events, and
some events are updated or created or deleted on a fixed time on midnight. But they found that
some events are occasionally delayed somehow. Maybe some hours, even some days, even never. 
After analyzing, the reason is:
(1)In function queue_remove, function queue_remove, we just adjust min-heap downward, never upward.
In fact, if the value of changed element is larger than before, we should adjust downward, otherwise
upward. Because of this error,  min-heap will not be kept after queue_remove, which may cause some
event to be delayed.

Both 5.6/ and 5.7/8.0 have this problem.

How to repeat:
# step1: turn off event scheduler
set global event_scheduler=OFF;

# step2: create some special events to build an special min-heap event queue
drop table if exists event_log;
CREATE TABLE `event_log` (
  `id` bigint(20) NOT NULL AUTO_INCREMENT,
  `event_name` varchar(50) NOT NULL,
  `create_time` datetime DEFAULT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

DROP EVENT IF EXISTS event1;
CREATE EVENT event1
ON SCHEDULE EVERY 1 HOUR STARTS CURRENT_TIMESTAMP + INTERVAL 60 SECOND
DO insert into event_log values(NULL, 'event1', now()); 

DROP EVENT IF EXISTS event2;
CREATE EVENT event2
ON SCHEDULE EVERY 1 HOUR STARTS CURRENT_TIMESTAMP + INTERVAL 65 SECOND
DO insert into event_log values(NULL, 'event2', now()); 

DROP EVENT IF EXISTS event3;
CREATE EVENT event3
ON SCHEDULE EVERY 1 HOUR STARTS CURRENT_TIMESTAMP + INTERVAL 84 SECOND
DO insert into event_log values(NULL, 'event3', now());

DROP EVENT IF EXISTS event4;
CREATE EVENT event4
ON SCHEDULE EVERY 1 HOUR STARTS CURRENT_TIMESTAMP + INTERVAL 75 SECOND
DO insert into event_log values(NULL, 'event4', now());

DROP EVENT IF EXISTS event5;
CREATE EVENT event5
ON SCHEDULE EVERY 1 HOUR STARTS CURRENT_TIMESTAMP + INTERVAL 80 SECOND
DO insert into event_log values(NULL, 'event5', now());

DROP EVENT IF EXISTS event6;
CREATE EVENT event6
ON SCHEDULE EVERY 1 HOUR STARTS CURRENT_TIMESTAMP + INTERVAL 85 SECOND
DO insert into event_log values(NULL, 'event6', now());

DROP EVENT IF EXISTS event7;
CREATE EVENT event7
ON SCHEDULE EVERY 1 HOUR STARTS CURRENT_TIMESTAMP + INTERVAL 90 SECOND
DO insert into event_log values(NULL, 'event7', now());

DROP EVENT IF EXISTS event8;
CREATE EVENT event8
ON SCHEDULE EVERY 1 HOUR STARTS CURRENT_TIMESTAMP + INTERVAL 95 SECOND
DO insert into event_log values(NULL, 'event8', now());

DROP EVENT IF EXISTS event9;
CREATE EVENT event9
ON SCHEDULE EVERY 1 HOUR STARTS CURRENT_TIMESTAMP + INTERVAL 100 SECOND
DO insert into event_log values(NULL, 'event9', now());

DROP EVENT IF EXISTS event10;
CREATE EVENT event10
ON SCHEDULE EVERY 1 HOUR STARTS CURRENT_TIMESTAMP + INTERVAL 105 SECOND
DO insert into event_log values(NULL, 'event10', now());

DROP EVENT IF EXISTS event11;
CREATE EVENT event11
ON SCHEDULE EVERY 1 HOUR STARTS CURRENT_TIMESTAMP + INTERVAL 82 SECOND
DO insert into event_log values(NULL, 'event11', now());

# step3: turn on event scheduler. This step must be executed before step4,
#        because event queue will be adjusted on the start of event scheduler
#        thread
set global event_scheduler=ON;

# step4: drop event7, then part of the event queue will not be min-heap, because
#        in function queue_remove, we just move event11 to event7 but not 
#        adjust min-heap furthermore. In this case, event11's parent is 
#        event3, but execute time of event3 is larger than event11.
drop event if exists event7;

# step5: check event execute order after each event has runned one time
select * from event_log;

# we can see that the event execute order is:
# event1 ,event2 ,event4  ,event5 ,event3 ,event11 ,event6 ,event8 ,event9, event10
# not what we expected:
# event1 ,event2 ,event4  ,event5 ,event11 ,event3 ,event6 ,event8 ,event9, event10
# event11 is delayed.

Suggested fix:
For 5.6:
(1)In function queue_remove, call queue_fix instead of _downheap.
For 5.7 and 8.0
(1)In function remove of priority_queue, call udpate instead of heapify.
[12 Sep 2019 12:53] yunsheng zhu
change severity
[12 Sep 2019 12:57] yunsheng zhu
change synopsis
[12 Sep 2019 12:57] yunsheng zhu
change synopsis
[13 Sep 2019 5:54] MySQL Verification Team
Hello yunsheng zhu,

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

regards,
Umesh
[10 Dec 2019 6:36] yunsheng zhu
We are from Tencent TXSQL Team.
[17 Dec 2019 19:47] Paul DuBois
Posted by developer:
 
Fixed in 5.6.48, 5.7.30, 8.0.20.

Scheduling of events could be disturbed by removing events.