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

[12 Jan 2006 4:20] Peter Gulutzan
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.
[12 Jan 2006 11:06] Valeriy Kravchuk
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.
[28 Jan 2006 16:15] Valeriy Kravchuk
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
[21 Feb 2006 3:27] Bugs System
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
[1 Mar 2006 1:37] Bugs System
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
[1 Mar 2006 2:52] Bugs System
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
[1 Mar 2006 3:02] Andrey Hristov
Fixed in 5.1.8
[2 Mar 2006 6:34] Jon Stephens
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.