MySQL Bugs: #16493: Slow query log logs SHOW statements

Bug #16493	Slow query log logs SHOW statements
Submitted:	13 Jan 2006 19:21	Modified:	27 Jun 2006 5:07
Reporter:	Stefan Hinz	Email Updates:
Status:	Duplicate	Impact on me:	None
Category:	MySQL Server	Severity:	S3 (Non-critical)
Version:	5.0.19-BK	OS:	probably all
Assigned to:	Assigned Account	CPU Architecture:	Any

Description:
The slow query log logs SHOW statement if --log-queries-not-using-indexes is specified on server start. This cannot be turned off (and is probably not needed, anyway).

I discovered this bug via a comment on http://dev.mysql.com/doc/refman/5.0/en/slow-query-log.html:

"When I turned on the slow_query.log, and told it to also log queries that do not use indexes my log started to fill up with SHOW COLLATION; and SHOW VARIABLES; statement. It can cause your log file to grow VERY quickly."

I asked our developers: Do we intentionally log SHOW statements? - No.- Or is this a bug? - Yes. - Is there a workaround so that SHOW command aren't logged as queries that don't use an index? - I don't think so.

Since there's no workaround this bug should probably get a rather high priority.

How to repeat:
Turn on the slow query log, including logging queries that don't use indexes.

Suggested fix:
Exclude SHOW statement from getting written to the slow log in any case.

Please, specify the exact versions having this probledm. I was not able to repeat on 4.1.17-BK (ChangeSet@1.2475, 2006-01-11 17:31:52+03:00), for example, after starting server with the following command:

bin/mysqld_safe --log-slow-queries --log-queries-not-using-indexes &

Queries like "select * from large_table" are logged, but "show varables" and "show tables" are not logged.

MySQL 5.0.17 has the problem I reported. After restarting mysqld with --log-slow-queries and --log-queries-not-using-indexes I got this, in the slow log:
themis:/var/lib/mysql # cat themis-slow.log
/usr/sbin/mysqld-max, Version: 5.0.17-max-log. started with:
Tcp port: 0  Unix socket: (null)
Time                 Id Command    Argument
# Time: 060115 10:25:52
# User@Host: stefan[stefan] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 27  Rows_examined: 27
show variables like '%log%';
# Time: 060115 10:26:14
# User@Host: replikator[replikator] @ iconnect2 [192.168.0.10]
# Query_time: 0  Lock_time: 0  Rows_sent: 1  Rows_examined: 1
SHOW VARIABLES LIKE 'SERVER_ID';
# Time: 060115 10:26:15
# User@Host: replikator[replikator] @ artemis [192.168.0.47]
# Query_time: 0  Lock_time: 0  Rows_sent: 1  Rows_examined: 1
SHOW VARIABLES LIKE 'SERVER_ID';
themis:/var/lib/mysql #

OK, I'll check with 5.0.19-BK also.

Verified just as described with 5.0.19-BK (ChangeSet@1.1997, 2006-01-20 17:21:39+03:00) on Linux.

I've started server as follows:

[openxs@Fedora 5.0]$ bin/mysqld_safe --log-slow-queries --log-queries-not-using-indexes &

and after some queries got in the slow log:

[openxs@Fedora 5.0]$ cat var/Fedora-slow.log
/home/openxs/dbs/5.0/libexec/mysqld, Version: 5.0.19-log. started with:
Tcp port: 0  Unix socket: (null)
Time                 Id Command    Argument
# Time: 060121 20:11:07
# User@Host: root[root] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 8  Rows_examined: 8
use test;
show databases;
# User@Host: root[root] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 36  Rows_examined: 36
show tables;
# Time: 060121 20:11:32
# User@Host: root[root] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 36  Rows_examined: 36
show tables;
# Time: 060121 20:11:58
# User@Host: root[root] @ localhost []
# Query_time: 2  Lock_time: 0  Rows_sent: 99657  Rows_examined: 99657
select * from products;
# Time: 060121 20:12:34
# User@Host: root[root] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 8  Rows_examined: 8
show databases;
# User@Host: root[root] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 36  Rows_examined: 36
show tables;
# Time: 060121 20:13:00
# User@Host: root[root] @ localhost []
# Query_time: 0  Lock_time: 0  Rows_sent: 25  Rows_examined: 25
show variables like '%log%';

Note that selecting from INFORMATION_SCHEMA also causes an entry in the slow query log when log-queries-not-using-indexes is enabled. This seems related to the original subject of this bug report in that it's a query retrieving status information that certainly could never be indexed and has no purpose appearing in the slow query log.

Bug#19764 is a duplicate of this issue whose patch has been approved for an upcoming release.