Tuesday, May 02, 2006

Event scheduler out of control?

I tried to test (once more) the event scheduler of MySQL 5.1.9 on Windows and experienced a very strange behaviour:
CREATE TABLE  `tt` (
`id` int(10) unsigned NOT NULL auto_increment,
`d` int(10) unsigned NOT NULL,
`ts` timestamp NOT NULL,
PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

DELIMITER //

DROP EVENT insertIntoTT //

CREATE EVENT insertIntoTT
ON SCHEDULE EVERY 5 SECOND
STARTS current_timestamp + INTERVAL 5 SECOND
DO
BEGIN
insert into tt (d) values (floor(rand() * 100));
END //

DELIMITER ;

After a while, I found this content in table tt:
mysql> select * from tt;
+-----+----+---------------------+
| id | d | ts |
+-----+----+---------------------+
| 1 | 83 | 2006-05-02 07:40:20 |
| 2 | 35 | 2006-05-02 07:40:25 |
| 3 | 66 | 2006-05-02 07:40:25 |
| 4 | 68 | 2006-05-02 07:40:25 |
| 5 | 82 | 2006-05-02 07:40:25 |
| 6 | 50 | 2006-05-02 07:40:25 |
| 7 | 44 | 2006-05-02 07:40:30 |
| 8 | 14 | 2006-05-02 07:40:30 |
| 9 | 79 | 2006-05-02 07:40:30 |
| 10 | 94 | 2006-05-02 07:40:30 |
| 11 | 75 | 2006-05-02 07:40:30 |
| 12 | 35 | 2006-05-02 07:40:30 |
| 13 | 90 | 2006-05-02 07:40:30 |
| 14 | 88 | 2006-05-02 07:40:30 |
| 15 | 13 | 2006-05-02 07:40:30 |
| 16 | 44 | 2006-05-02 07:40:30 |
| 17 | 21 | 2006-05-02 07:40:30 |
| 18 | 16 | 2006-05-02 07:40:30 |
| 19 | 56 | 2006-05-02 07:40:30 |
| 20 | 76 | 2006-05-02 07:40:30 |
| 21 | 54 | 2006-05-02 07:40:30 |
| 22 | 81 | 2006-05-02 07:40:30 |
| 23 | 88 | 2006-05-02 07:40:30 |
| 24 | 38 | 2006-05-02 07:40:30 |
| 25 | 66 | 2006-05-02 07:40:30 |
| 26 | 59 | 2006-05-02 07:40:30 |
| 27 | 39 | 2006-05-02 07:40:30 |
| 28 | 60 | 2006-05-02 07:40:30 |
| 29 | 25 | 2006-05-02 07:40:30 |
| 30 | 89 | 2006-05-02 07:40:30 |
| 31 | 9 | 2006-05-02 07:40:30 |
| 32 | 19 | 2006-05-02 07:40:30 |
| 33 | 10 | 2006-05-02 07:40:30 |
| 34 | 36 | 2006-05-02 07:40:30 |
| 35 | 90 | 2006-05-02 07:40:30 |
| 36 | 84 | 2006-05-02 07:40:30 |
| 37 | 93 | 2006-05-02 07:40:30 |
| 38 | 55 | 2006-05-02 07:40:30 |
| 39 | 36 | 2006-05-02 07:40:30 |
| 40 | 58 | 2006-05-02 07:40:31 |
| 41 | 23 | 2006-05-02 07:40:35 |
| 42 | 81 | 2006-05-02 07:40:35 |
| 43 | 80 | 2006-05-02 07:40:35 |
| 44 | 97 | 2006-05-02 07:40:35 |
| 45 | 88 | 2006-05-02 07:40:35 |
| 46 | 90 | 2006-05-02 07:40:35 |
| 47 | 26 | 2006-05-02 07:40:35 |
| 48 | 5 | 2006-05-02 07:40:35 |
| 49 | 88 | 2006-05-02 07:40:35 |
| 50 | 66 | 2006-05-02 07:40:35 |
| 51 | 8 | 2006-05-02 07:40:35 |
| 52 | 83 | 2006-05-02 07:40:35 |
| 53 | 33 | 2006-05-02 07:40:35 |
| 54 | 59 | 2006-05-02 07:40:35 |
| 55 | 38 | 2006-05-02 07:40:35 |
| 56 | 54 | 2006-05-02 07:40:35 |
| 57 | 99 | 2006-05-02 07:40:35 |
| 58 | 76 | 2006-05-02 07:40:35 |
| 59 | 22 | 2006-05-02 07:40:35 |
| 60 | 27 | 2006-05-02 07:40:35 |
| 61 | 8 | 2006-05-02 07:40:35 |
| 62 | 1 | 2006-05-02 07:40:35 |
| 63 | 25 | 2006-05-02 07:40:35 |
| 64 | 62 | 2006-05-02 07:40:35 |
| 65 | 78 | 2006-05-02 07:40:35 |
| 66 | 45 | 2006-05-02 07:40:35 |
| 67 | 35 | 2006-05-02 07:40:35 |
| 68 | 80 | 2006-05-02 07:40:35 |
| 69 | 36 | 2006-05-02 07:40:35 |
| 70 | 80 | 2006-05-02 07:40:35 |
| 71 | 38 | 2006-05-02 07:40:35 |
| 72 | 89 | 2006-05-02 07:40:35 |
| 73 | 73 | 2006-05-02 07:40:35 |
| 74 | 39 | 2006-05-02 07:40:35 |
| 75 | 19 | 2006-05-02 07:40:35 |
| 76 | 19 | 2006-05-02 07:40:36 |
| 77 | 81 | 2006-05-02 07:40:36 |
| 78 | 88 | 2006-05-02 07:40:40 |
| 79 | 42 | 2006-05-02 07:40:40 |
| 80 | 84 | 2006-05-02 07:40:40 |
| 81 | 38 | 2006-05-02 07:40:40 |
| 82 | 81 | 2006-05-02 07:40:40 |
| 83 | 30 | 2006-05-02 07:40:40 |
| 84 | 50 | 2006-05-02 07:40:40 |
| 85 | 2 | 2006-05-02 07:40:40 |
| 86 | 1 | 2006-05-02 07:40:40 |
| 87 | 42 | 2006-05-02 07:40:40 |
| 88 | 48 | 2006-05-02 07:40:40 |
| 89 | 57 | 2006-05-02 07:40:40 |
| 90 | 81 | 2006-05-02 07:40:40 |
| 91 | 78 | 2006-05-02 07:40:40 |
| 92 | 87 | 2006-05-02 07:40:40 |
| 93 | 42 | 2006-05-02 07:40:40 |
| 94 | 91 | 2006-05-02 07:40:40 |
| 95 | 70 | 2006-05-02 07:40:40 |
| 96 | 22 | 2006-05-02 07:40:40 |
| 97 | 38 | 2006-05-02 07:40:40 |
| 98 | 69 | 2006-05-02 07:40:40 |
| 99 | 70 | 2006-05-02 07:40:40 |
| 100 | 88 | 2006-05-02 07:40:40 |
| 101 | 71 | 2006-05-02 07:40:40 |
| 102 | 31 | 2006-05-02 07:40:40 |
| 103 | 85 | 2006-05-02 07:40:40 |
| 104 | 76 | 2006-05-02 07:40:40 |
| 105 | 63 | 2006-05-02 07:40:40 |
| 106 | 30 | 2006-05-02 07:40:40 |
| 107 | 3 | 2006-05-02 07:40:40 |
| 108 | 68 | 2006-05-02 07:40:40 |
| 109 | 72 | 2006-05-02 07:40:40 |
| 110 | 97 | 2006-05-02 07:40:40 |
| 111 | 13 | 2006-05-02 07:40:40 |
| 112 | 15 | 2006-05-02 07:40:40 |
| 113 | 78 | 2006-05-02 07:40:40 |
| 114 | 86 | 2006-05-02 07:40:40 |
| 115 | 36 | 2006-05-02 07:40:41 |
| 116 | 66 | 2006-05-02 07:40:45 |
| 117 | 61 | 2006-05-02 07:40:45 |
| 118 | 51 | 2006-05-02 07:40:45 |
| 119 | 15 | 2006-05-02 07:40:45 |
| 120 | 61 | 2006-05-02 07:40:45 |
| 121 | 2 | 2006-05-02 07:40:45 |
| 122 | 68 | 2006-05-02 07:40:45 |
| 123 | 78 | 2006-05-02 07:40:45 |
| 124 | 25 | 2006-05-02 07:40:45 |
| 125 | 35 | 2006-05-02 07:40:45 |
| 126 | 42 | 2006-05-02 07:40:45 |
| 127 | 47 | 2006-05-02 07:40:45 |
| 128 | 51 | 2006-05-02 07:40:45 |
| 129 | 56 | 2006-05-02 07:40:45 |
| 130 | 70 | 2006-05-02 07:40:45 |
| 131 | 21 | 2006-05-02 07:40:45 |
| 132 | 39 | 2006-05-02 07:40:45 |
| 133 | 75 | 2006-05-02 07:40:45 |
| 134 | 99 | 2006-05-02 07:40:45 |
| 135 | 12 | 2006-05-02 07:40:45 |
| 136 | 5 | 2006-05-02 07:40:45 |
| 137 | 31 | 2006-05-02 07:40:45 |
| 138 | 82 | 2006-05-02 07:40:45 |
| 139 | 58 | 2006-05-02 07:40:45 |
| 140 | 85 | 2006-05-02 07:40:45 |
| 141 | 93 | 2006-05-02 07:40:45 |
| 142 | 53 | 2006-05-02 07:40:45 |
| 143 | 25 | 2006-05-02 07:40:45 |
| 144 | 11 | 2006-05-02 07:40:45 |
| 145 | 19 | 2006-05-02 07:40:45 |
| 146 | 6 | 2006-05-02 07:40:45 |
| 147 | 14 | 2006-05-02 07:40:45 |
| 148 | 93 | 2006-05-02 07:40:45 |
| 149 | 64 | 2006-05-02 07:40:45 |
| 150 | 83 | 2006-05-02 07:40:45 |
| 151 | 65 | 2006-05-02 07:40:45 |
| 152 | 17 | 2006-05-02 07:40:45 |
| 153 | 35 | 2006-05-02 07:40:46 |
| 154 | 63 | 2006-05-02 07:40:50 |
| 155 | 51 | 2006-05-02 07:40:50 |
+-----+----+---------------------+
155 rows in set (0.00 sec)

Instead of inserting one row every 5 seconds, MySQL inserted 155 rows in 30 seconds. Can anybody else experience something like this?

5 comments:

Andrey Hristov said...

Hi Markus,
the problem is known - Bug #19170. The fix came too late in the build cycle of 5.1.9 and thus was not incorporated into the release. 5.1.10 which will come soon won't have this defect.

Jay Pipes said...

very strange. I'd post it to bugs DB after a quick search for similar ...

Cheers,

Jay

Markus Popp said...

That's good to know, thanks! I wasn't absolutely sure whether it's caused by my installation or whether it's a general problem - so now as the bug is reported and about to be fixed, that's fine for me.

Sheeri said...

Hi Markus,

I can replicate the behavior, but it seems I'm too late -- you already knew it was a bug.

But now I have 5.1 installed!

Markus Popp said...

Hi Sheeri,

great that you've also 5.1 installed. There are still some rough edges, but (at least usually) they get smoother from version to version. This bug here is a little exception ;-).

Cheers,
Markus