Monday, February 13, 2006

My first EVENT and table logging tests

I've been very excited to test the new EVENT and table logging features, so I downloaded and installed MySQL 5.1 from the development source tree to get the very latest development version - 5.1.7-beta (no alpha anymore!).

The first thing you have to do to test the features is to enable event handling and logging (I also enabled the slow-query-log) in the my.cnf file - like this:
[mysqld]
log
log-slow-queries
event-scheduler=1

First I needed a table - I created quite a simple one:
DROP TABLE IF EXISTS `test`.`tt`;
CREATE TABLE `test`.`tt` (
`id` int(10) unsigned NOT NULL auto_increment,
`d` int(10) unsigned NOT NULL,
`ts` timestamp NOT NULL default CURRENT_TIMESTAMP
on update CURRENT_TIMESTAMP,
PRIMARY KEY (`id`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8;

The event should insert a random value into column d every 5 seconds. With Trudy Pelzer's documentation it was quite easy to do that:
delimiter //

DROP EVENT IF EXISTS insertIntoTt //

CREATE EVENT insertIntoTt
ON SCHEDULE EVERY 5 SECOND
STARTS current_timestamp + INTERVAL 5 SECOND
ON COMPLETION PRESERVE
DISABLE
DO
BEGIN
INSERT INTO test.tt (d) VALUES (floor(rand() * 20));
END //

delimiter ;

There's just one mistake that I found: the documentation names the options to enable and disable the event as ENABLED and DISABLED, wheras I found out that it works with ENABLE and DISABLE.

So lets start the event:
E:\mysql_dump>mysql -h 10.2.4.1 -P 3307
Enter password: *******
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 419 to server version: 5.1.7-beta-log

Type 'help;' or '\h' for help. Type '\c' to clear the buffer.

mysql> use test
Database changed
mysql> ALTER EVENT insertIntoTt ENABLE;
Query OK, 1 row affected (0.00 sec)
mysql> SELECT current_time(), count(*) FROM tt;
+----------------+----------+
| current_time() | count(*) |
+----------------+----------+
| 19:26:14 | 14 |
+----------------+----------+
1 row in set (0.00 sec)

mysql> SELECT current_time(), count(*) FROM tt;
+----------------+----------+
| current_time() | count(*) |
+----------------+----------+
| 19:26:22 | 16 |
+----------------+----------+
1 row in set (0.00 sec)

mysql> SELECT current_time(), count(*) FROM tt;
+----------------+----------+
| current_time() | count(*) |
+----------------+----------+
| 19:26:30 | 17 |
+----------------+----------+
1 row in set (0.02 sec)

Currently there's a bug in the Event Scheduler which prevents commands from inside an event from being logged in the general log. However, the mysql.general_log table shows the log data like we were used to from the general_log stored in the file system:
mysql> SELECT * FROM mysql.general_log
-> ORDER BY event_time
-> LIMIT 10\G
*************************** 1. row ***************************
event_time: 2006-02-13 18:52:42
user_host: mpopp[mpopp] @ [10.2.1.1]
thread_id: 114
server_id: 0
command_type: Quit
argument:
*************************** 2. row ***************************
event_time: 2006-02-13 18:53:19
user_host: mpopp[mpopp] @ [10.2.1.1]
thread_id: 115
server_id: 0
command_type: Connect
argument: mpopp@10.2.1.1 on
*************************** 3. row ***************************
event_time: 2006-02-13 18:53:23
user_host: mpopp[mpopp] @ [10.2.1.1]
thread_id: 115
server_id: 0
command_type: Query
argument: SELECT DATABASE()
*************************** 4. row ***************************
event_time: 2006-02-13 18:53:23
user_host: mpopp[mpopp] @ [10.2.1.1]
thread_id: 115
server_id: 0
command_type: Init DB
argument: test
*************************** 5. row ***************************
event_time: 2006-02-13 18:53:27
user_host: mpopp[mpopp] @ [10.2.1.1]
thread_id: 115
server_id: 0
command_type: Query
argument: DROP EVENT IF EXISTS insertIntoTt
*************************** 6. row ***************************
event_time: 2006-02-13 18:53:27
user_host: mpopp[mpopp] @ [10.2.1.1]
thread_id: 115
server_id: 0
command_type: Query
argument: CREATE EVENT insertIntoTt
ON SCHEDULE EVERY 5 SECOND
STARTS current_timestamp + INTERVAL 5 SECOND
ON COMPLETION PRESERVE
DISABLE
DO
BEGIN
INSERT INTO test.tt (d) VALUES (floor(rand() * 20));
END
*************************** 7. row ***************************
event_time: 2006-02-13 18:54:01
user_host: mpopp[mpopp] @ [10.2.1.1]
thread_id: 116
server_id: 0
command_type: Connect
argument: mpopp@10.2.1.1 on test
*************************** 8. row ***************************
event_time: 2006-02-13 18:54:01
user_host: mpopp[mpopp] @ [10.2.1.1]
thread_id: 116
server_id: 0
command_type: Query
argument: SET SESSION interactive_timeout=1000000
*************************** 9. row ***************************
event_time: 2006-02-13 18:54:01
user_host: mpopp[mpopp] @ [10.2.1.1]
thread_id: 116
server_id: 0
command_type: Query
argument: SELECT @@sql_mode
*************************** 10. row ***************************
event_time: 2006-02-13 18:54:01
user_host: mpopp[mpopp] @ [10.2.1.1]
thread_id: 116
server_id: 0
command_type: Query
argument: SET SESSION sql_mode=''
10 rows in set (0.00 sec)

Nice stuff, indeed :-).

3 comments:

gmax said...

Very impressive.
I think I'm going to love this feature!
However, I made my first experiments with events and I found my first 5.1 bug (http://bugs.mysql.com/17354)

Cheers
Giuseppe

Markus Popp said...

Hi! I also love them, but I was quite disappointed when I updated my Windows MySQL 5.1 server to 5.1.6 :-(. Logging and the EVENT scheduler don't work here at all. Activating the event scheduler even crashes the server.

I hope that it works better with the Linux version. I'll now update db4free.net - if it works better here, I'll write a new blog article about the new possibilities there (triggers for everybody, event scheduling, a view for the slow query log, ...).

Cheers, Markus

gmax said...

Hi,
one more bug. This one is in 5.1.6 and it looks nastier, but I don't know if it is easy to reproduce.

Giuseppe