MySQL Bugs: #16426: Events: Event-caused statements don't appear in the slow query log

Bug #16426	Events: Event-caused statements don't appear in the slow query log
Submitted:	12 Jan 2006 4:20	Modified:	2 Mar 2006 6:34
Reporter:	Peter Gulutzan	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Stored Routines	Severity:	S3 (Non-critical)
Version:	5.1.6-alpha-debug	OS:	Linux (SUSE 10.0)
Assigned to:	Andrey Hristov	CPU Architecture:	Any

Description:
Statements which are slow should be in the slow query log.
They aren't.

How to repeat:

Start the server with
mysqld --user=root --skip-networking --log-slow-queries=/tmp/slow.txt

Start the client. Say:

mysql> create table t_34 (s1 int);
Query OK, 0 rows affected (0.01 sec)

mysql> create event e_34 on schedule every 1 second do insert into db1.t_34 values (sleep(5));
Query OK, 1 row affected (0.00 sec)

mysql> set global event_scheduler = 1;
Query OK, 0 rows affected (0.00 sec)

Wait a few seconds.

Look at /tmp/slow.txt. Notice that there are no insert statements.

Thank you for a problem report. Sorry, but I was not able to repeat it on 5.1.6-BK (ChangeSet@1.2012.25.1, 2006-01-12 11:41:57+04:00):

mysql> create event e_34 on schedule every 1 second do insert into test.t_34 values (sleep(15));
Query OK, 1 row affected (0.00 sec)

mysql> delete from t_34;
Query OK, 9 rows affected (0.00 sec)

mysql> show variables like 'long_query%';
+-----------------+-------+
| Variable_name   | Value |
+-----------------+-------+
| long_query_time | 10    |
+-----------------+-------+
1 row in set (0.00 sec)

mysql> select count(*) from t_34;
+----------+
| count(*) |
+----------+
|        0 |
+----------+
1 row in set (0.00 sec)

mysql> set global event_scheduler = 1;
Query OK, 0 rows affected (0.00 sec)

mysql> select sleep(15);
+-----------+
| sleep(15) |
+-----------+
|         0 |
+-----------+
1 row in set (15.00 sec)

mysql> select count(*) from t_34;
+----------+
| count(*) |
+----------+
|        1 |
+----------+
1 row in set (0.01 sec)

mysql> exit
Bye
openxs@suse:~/dbs/5.1> cat /tmp/slow.txt
/home/openxs/dbs/5.1/libexec/mysqld, Version: 5.1.6-alpha-log. started with:
Tcp port: 0  Unix socket: (null)
Time                 Id Command    Argument
# Time: 060111 17:49:30
# User@Host: root[root] @ localhost []
# Query_time: 15  Lock_time: 0  Rows_sent: 1  Rows_examined: 0
use test;
select sleep(15);

Note, that because of default value 10 for long_query_time I had to change sleep timeout to 15. I believe, that 5 was the reason to NOT having this insert written to the slow query log.

My previous test case already proved that select(sleep(15)) was written to the slow query log, but insert from the event was not. So, there is a bug, really.

Moreover, when I've tried to repeat again, with ChangeSet@1.2075.1.1, 2006-01-27 20:27:10+01:00, I found that current 5.1.6-alpha version does not create slow query log at all:

openxs@suse:~/dbs/5.1> bin/mysqld_safe --log-slow-queries=/tmp/slow.txt &
[1] 24292
openxs@suse:~/dbs/5.1> Starting mysqld daemon with databases from /home/openxs/dbs/5.1/var

openxs@suse:~/dbs/5.1> bin/mysql -uroot test;
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A

Welcome to the MySQL monitor.  Commands end with ; or \g.
Your MySQL connection id is 1 to server version: 5.1.6-alpha-log

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

mysql>  show variables like '%long_query%';
+-----------------+-------+
| Variable_name   | Value |
+-----------------+-------+
| long_query_time | 10    |
+-----------------+-------+
1 row in set (0.00 sec)

mysql> show variables like '%slow%';
+------------------+-------+
| Variable_name    | Value |
+------------------+-------+
| log_slow_queries | ON    |
| slow_launch_time | 2     |
+------------------+-------+
2 rows in set (0.00 sec)

mysql> select sleep(15);
+-----------+
| sleep(15) |
+-----------+
|         0 |
+-----------+
1 row in set (15.00 sec)

mysql> exit
Bye
openxs@suse:~/dbs/5.1> ls /tmp/s*
/bin/ls: /tmp/s*: No such file or directory

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/2946

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/3289

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/3291

Fixed in 5.1.8

Thank you for your bug report. This issue has been committed to our
source repository of that product and will be incorporated into the
next release.

If necessary, you can access the source repository and build the latest
available version, including the bugfix, yourself. More information 
about accessing the source trees is available at
    http://www.mysql.com/doc/en/Installing_source_tree.html

Additional info:

Documented fix in 5.1.8 changelog. Closed.

Same bug in version 5.6.39-log MySQL Community Server (GPL)
I'm afraid this bug is still alive now.