Bug #17600 Invalid data logged into mysql.slow_log
Submitted: 20 Feb 2006 23:36 Modified: 14 Mar 2006 18:45
Reporter: Andrey Hristov Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server Severity:S3 (Non-critical)
Version: OS:
Assigned to: Petr Chardin CPU Architecture:Any

[20 Feb 2006 23:36] Andrey Hristov 
Description:
 See the output.

mysql> set session long_query_time=1;
Query OK, 0 rows affected (0.06 sec)

sql> select * from slow_log;
Empty set (0.01 sec)

mysql> select sleep(5) from dual;
+----------+
| sleep(5) |
+----------+
|        0 |
+----------+
1 row in set (5.01 sec)

mysql> select * from slow_log\G
*************************** 1. row ***************************
    start_time: 2006-02-21 00:26:23
     user_host: root[root] @ localhost []
    query_time: 00:00:05
     lock_time: 00:00:00
     rows_sent: 1
 rows_examined: 0
            db: mysql
last_insert_id: -1515870811
     insert_id: -1515870811
     server_id: 1
      sql_text: select sleep(5) from dual
1 row in set (0.01 sec)

How to repeat:
set session long_query_time=1;
select * from slow_log;
select sleep(5) from dual;
select * from slow_log\G
[22 Feb 2006 7:39] Petr Chardin 
Miguel, I can repeat the bug. I use Suse Linux 10.0. For compile I used
BUILD/compile-pentium-debug. Did you have slow log enabled?
[22 Feb 2006 12:07] Valeriy Kravchuk 
I also can not repeat with ChangeSet@1.2158, 2006-02-22 08:32:58+01:00. Same results as Miguel shown already.

Do you use -debug version of server? Any startup/my.cnf options seet?
[22 Feb 2006 12:50] Valeriy Kravchuk 
My fault (wrong my.cnf). Here is what I got:

openxs@suse:~/dbs/5.1> bin/mysqld_safe --log-slow-queries &
[1] 20629
openxs@suse:~/dbs/5.1> Starting mysqld daemon with databases from /home/openxs/d
bs/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.8-beta-log

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

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

mysql> select sleep(5) from dual;
+----------+
| sleep(5) |
+----------+
|        0 |
+----------+
1 row in set (5.01 sec)

mysql> select * from mysql.slow_log\G
*************************** 1. row ***************************
    start_time: 2006-02-13 21:17:38
     user_host: root[root] @ localhost []
    query_time: 00:00:05
     lock_time: 00:00:00
     rows_sent: 1
 rows_examined: 0
            db: test
last_insert_id: 0
     insert_id: 0
     server_id: 0
      sql_text: select sleep(5) from dual
1 row in set (0.00 sec)
[22 Feb 2006 13:48] Valeriy Kravchuk 
Verified just as described with 5.1.8-BK (ChangeSet@1.2161, 2006-02-22 12:15:43+01:00) built --with-debug=full:

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.8-beta-debug-log

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

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

mysql> select * from mysql.slow_log\G
*************************** 1. row ***************************
    start_time: 2006-02-13 21:17:38
     user_host: root[root] @ localhost []
    query_time: 00:00:05
     lock_time: 00:00:00
     rows_sent: 1
 rows_examined: 0
            db: test
last_insert_id: 0
     insert_id: 0
     server_id: 0
      sql_text: select sleep(5) from dual
1 row in set (0.00 sec)

mysql> select sleep(5) from dual;
+----------+
| sleep(5) |
+----------+
|        0 |
+----------+
1 row in set (5.00 sec)

mysql> select * from mysql.slow_log\G
*************************** 1. row ***************************
    start_time: 2006-02-13 21:17:38
     user_host: root[root] @ localhost []
    query_time: 00:00:05
     lock_time: 00:00:00
     rows_sent: 1
 rows_examined: 0
            db: test
last_insert_id: 0
     insert_id: 0
     server_id: 0
      sql_text: select sleep(5) from dual
*************************** 2. row ***************************
    start_time: 2006-02-13 22:02:55
     user_host: root[root] @ localhost []
    query_time: 00:00:05
     lock_time: 00:00:00
     rows_sent: 1
 rows_examined: 0
            db: test
last_insert_id: -1515870811
     insert_id: -1515870811
     server_id: 0
      sql_text: select sleep(5) from dual
2 rows in set (0.00 sec)
[24 Feb 2006 17:58] 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/3121
[6 Mar 2006 18:01] 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/3517
[13 Mar 2006 11:19] Petr Chardin 
pushed into 5.1.9
[14 Mar 2006 18:45] Paul DuBois 
Noted in 5.1.9 changelog.

<literal>NULL</literal> values were written to the
<literal>mysql.slow_log</literal> table incorrectly. (Bug
#17600)
[15 Mar 2006 13:51] Paul DuBois 
Fix is in 5.1.8.