MySQL Bugs: #17543: Event executes at wrong time

Bug #17543	Event executes at wrong time
Submitted:	18 Feb 2006 12:38	Modified:	18 Feb 2006 13:37
Reporter:	Markus Popp	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server	Severity:	S3 (Non-critical)
Version:	5.1.6	OS:	Linux (SuSE Linux 9.0)
Assigned to:		CPU Architecture:	Any

Description:
I have defined an event that's supposed to execute every day at midnight. However, the output in the mysql.event table states that the event executes at 13:09:17 instead.

Unfortunately, these events fail to execute because of another bug (which is already reported and verified), so I have no proof whether it really tried to execute.

How to repeat:
See here that the execution plan and execution time differ in an unexpected way:

mysql> select * from event\G
*************************** 1. row ***************************
            db: mysql
          name: cleanSlowLog
          body:  BEGIN

  DELETE FROM slow_log
    WHERE start_time > DATE_SUB(now(), INTERVAL 1 DAY);

END
       definer: root@%
    execute_at: NULL
interval_value: 1
interval_field: DAY
       created: 2006-02-14 21:28:02
      modified: 2006-02-14 21:28:02
 last_executed: 2006-02-17 13:09:17
        starts: 2006-02-15 00:00:00
          ends: NULL
        status: ENABLED
 on_completion: PRESERVE
      sql_mode:
       comment:
*************************** 2. row ***************************
            db: mysql
          name: cleanGeneralLog
          body:  BEGIN

  DELETE FROM general_log
    WHERE command_type != 'Connect'
    AND event_time > DATE_SUB(now(), INTERVAL 1 DAY);

END
       definer: root@%
    execute_at: NULL
interval_value: 1
interval_field: DAY
       created: 2006-02-14 21:37:52
      modified: 2006-02-14 21:37:52
 last_executed: 2006-02-17 13:09:17
        starts: 2006-02-15 00:00:00
          ends: NULL
        status: ENABLED
 on_completion: PRESERVE
      sql_mode:
       comment:
2 rows in set (0.25 sec)

mysql>

Could you provide the CREATE EVENT statement you have executed?
Thanks!

Unfortunately it's not possible to get the original command from SHOW CREATE EVENT (which is reported in another bug report), so I had to recreate it from memory:

DELIMITER //

CREATE EVENT cleanSlowLog
ON SCHEDULE EVERY 1 DAY
STARTS '2005-02-15 00:00:00'
ON COMPLETION PRESERVE
ENABLE
BEGIN
  DELETE FROM slow_log
    WHERE start_time > DATE_SUB(now(), INTERVAL 1 DAY);
END //

DELIMITER ;

The second event is practically the same except its name and its execution body.

Oups - 2005 in the start time is of course 2006.

This is duplicate of bug#17346.

Will explain shortly. The problem is the date "calculator" is a bit conservative in some way and if you stop and start the server it will execute the 1 day, 1 month, whatever again. If you don't shutdown and start the server there will be no such problem. There is a way to test whether when running the events are scheduled correctly. Let's say you create as in this case an even to be executed every day. You create it, then the server waits till the execution time, you can move your clock ahead but ~1 minute before the execution should happen. The create a dummy event
create event dummy on schedule at now() do select 1;
This will wake-up the scheduler so it will see that the date has changed and recalculate how much time it should sleep till it's right time. I used this method and without restarting the server it works correctly but restarting the server is not nice for the scheduler :( . Will be fixed.
Thanks for your effort in testing this new feature. BTW, since 5.1.7 which will appear in about a week, one can see the errors and they will be logged if he uses error log table. Your event generated the following:
060219  0:00:00 [Note] SCHEDULER: Executing event mysql.cleanSlowLog of root@localhost [EXPR:1]
060219  0:00:00 [ERROR] SCHEDULER: [root@localhost][mysql.cleanSlowLog] You can't write-lock a log table. Only read access is possible.]
060219  0:00:00 [Note] SCHEDULER: Executed event mysql.cleanSlowLog of root@localhost  [EXPR:1]. RetCode=1

Something like the following should help you. It's not 100% working because between FLUSH LOGS and TRUNCATE you can miss some :( . You don't need on completion preserve. It's only needed if you have ENDS clause and then the server will know whether to drop the event or not if the time passes the time specified in ENDS.
DELIMITER //

CREATE EVENT cleanSlowLog ON SCHEDULE EVERY 1 DAY STARTS '2006-02-19 00:00:00'
DO BEGIN
  CREATE TABLE IF NOT EXISTS log_last_day LIKE mysql.slow_log;
  ALTER TABLE log_last_day ENGINE=myisam;
  FLUSH LOGS;
  INSERT INTO log_last_day SELECT * FROM mysql.slow_log WHERE start_time < DATE_SUB(now(), INTERVAL 1 DAY);
  TRUNCATE mysql.slow_log;
END //

DELIMITER ;