MySQL Bugs: #65643: event execute more than once at one time(concurrent)

Bug #65643	event execute more than once at one time(concurrent)
Submitted:	17 Jun 2012 10:43	Modified:	28 Feb 2013 18:29
Reporter:	Danniel Wallace	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Server: Stored Routines	Severity:	S1 (Critical)
Version:	5.1.32	OS:	Linux
Assigned to:		CPU Architecture:	Any
Tags:	event concurrent

Description:
I create a event in my C++ program;

The sql is shown below:
CREATE DEFINER=`root`@`localhost` EVENT IF NOT EXISTS extract_lottery 
ON SCHEDULE EVERY 1 DAY 
STARTS TIMESTAMP '2012-06-14 21:50:00' 
ENDS TIMESTAMP '2012-06-15 00:00:00' 
ENABLE 
DO 
CALL extract_mphone();

It supposed to be execute once every day at 21:50:00.

When we test it, found at most time i work well, but some time the event
execute more than once at one time(concurrent).

The concurrency have confused me several days, hope any one tell me the reason. My email is dannielwallace@gmail.com, if want more detail infomation, please contact me or leave me message here.

I complete have no idea why this happend, only one clue:
when concurrency shown, the mysql server kept several connections for client user, some of client use the same account.(every acount has super priviledge).

Some proof for event concurrency:
err-log:
120614 19:50:00 [Note] Event Scheduler: Last execution of name_head.extract_lottery. Dropping.
120614 19:50:00 [Note] Event Scheduler: Last execution of name_head.extract_lottery. Dropping.
120614 19:50:00 [Note] Event Scheduler: Dropping name_head.extract_lottery
120614 19:50:00 [Note] Event Scheduler: Dropping name_head.extract_lottery
120614 19:50:00 [ERROR] Event Scheduler: [root@localhost][name_head.extract_lottery] Unknown event 'extract_lottery'
120614 19:50:00 [Note] Event Scheduler: [root@localhost].[name_head.extract_lottery] event execution failed.

bin-log(before and after "DROP EVENT `name_head`.`extract_lottery`", is the store program extract_mphone that event called ):
#120614 19:50:00 server id 1  end_log_pos 31512666 	Query	thread_id=422	exec_time=0	error_code=0
use name_head/*!*/;
SET TIMESTAMP=1339674600/*!*/;
BEGIN
/*!*/;
# at 31512666
#120614 19:50:00 server id 1  end_log_pos 31512809 	Query	thread_id=422	exec_time=0	error_code=0
SET TIMESTAMP=1339674600/*!*/;
UPDATE lottery SET Reserve = 1 WHERE (Number =  NAME_CONST('v_number',189))
/*!*/;
# at 31512809
#120614 19:50:00 server id 1  end_log_pos 31512999 	Query	thread_id=422	exec_time=0	error_code=0
SET TIMESTAMP=1339674600/*!*/;
DELETE FROM lottery_candidate where FamilyName= NAME_CONST('v_familyname',_latin1'成娇的茄子' COLLATE 'latin1_swedish_ci')
/*!*/;
# at 31512999
#120614 19:50:00 server id 1  end_log_pos 31513359 	Query	thread_id=422	exec_time=0	error_code=0
SET TIMESTAMP=1339674600/*!*/;
INSERT INTO lottery_prize (Number,FamilyName,Sequency,Reserve,AreaGroup)  			VALUES ( NAME_CONST('v_number',189),  NAME_CONST('v_familyname',_latin1'成娇的茄子' COLLATE 'latin1_swedish_ci'),  NAME_CONST('v_sequency',3), 1,  NAME_CONST('v_areagroup',_latin1'5-90' COLLATE 'latin1_swedish_ci'))
/*!*/;
# at 31513359
#120614 19:50:00 server id 1  end_log_pos 31513386 	Xid = 61469
COMMIT/*!*/;
# at 31513386
#120614 19:50:00 server id 1  end_log_pos 31513494 	Query	thread_id=422	exec_time=0	error_code=0
SET TIMESTAMP=1339674600/*!*/;
DROP EVENT `name_head`.`extract_lottery`
/*!*/;
# at 31513494
#120614 19:50:00 server id 1  end_log_pos 31513567 	Query	thread_id=423	exec_time=0	error_code=0
SET TIMESTAMP=1339674600/*!*/;
BEGIN
/*!*/;
# at 31513567
#120614 19:50:00 server id 1  end_log_pos 31513710 	Query	thread_id=423	exec_time=0	error_code=0
SET TIMESTAMP=1339674600/*!*/;
UPDATE lottery SET Reserve = 1 WHERE (Number =  NAME_CONST('v_number',212))
/*!*/;
# at 31513710
#120614 19:50:00 server id 1  end_log_pos 31513894 	Query	thread_id=423	exec_time=0	error_code=0
SET TIMESTAMP=1339674600/*!*/;
DELETE FROM lottery_candidate where FamilyName= NAME_CONST('v_familyname',_latin1'小明' COLLATE 'latin1_swedish_ci')
/*!*/;
# at 31513894
#120614 19:50:00 server id 1  end_log_pos 31514248 	Query	thread_id=423	exec_time=0	error_code=0
SET TIMESTAMP=1339674600/*!*/;
INSERT INTO lottery_prize (Number,FamilyName,Sequency,Reserve,AreaGroup)  			VALUES ( NAME_CONST('v_number',212),  NAME_CONST('v_familyname',_latin1'小明' COLLATE 'latin1_swedish_ci'),  NAME_CONST('v_sequency',3), 1,  NAME_CONST('v_areagroup',_latin1'5-90' COLLATE 'latin1_swedish_ci'))
/*!*/;
# at 31514248
#120614 19:50:00 server id 1  end_log_pos 31514275 	Xid = 61491
COMMIT/*!*/;
# at 31514275

How to repeat:
I'm trying to repeat it, if succeed later, I will add here

Also, please, upgrade to recent version, 5.1.63, before any further checks. 5.1.32 is many years old, and hundreds of bugs were fixed since its release.

I check changed history for mysql 5.1.32->5.1.64, found the describe of Bug #61005.

It may caused by Bug #61005:
CREATE IF NOT EXIST event will create multiple running events.

I prepeare to test it, if repeated succeed, another way to complete task is cost cheaper rather than upgrade the version of mysql server.

Anyway, I want get the real reason that cause event's concurrency.Hope anyone give some tips, thanks very much.

Repeated.

Do you still have the same problem on 5.1.63+? Please, clarify.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

sorry, I don't upgrade the version to 5.1.63

Thank you for the feedback.

This is indeed looks like bug #61005. Please try with current version 5.1.67 and inform us still exists after fix of this bug.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".