MySQL Bugs: #64822: ALTER TABLE does not appear in the slow query log

Bug #64822	ALTER TABLE does not appear in the slow query log
Submitted:	31 Mar 2012 1:33	Modified:	26 Mar 2013 22:27
Reporter:	Baron Schwartz (Basic Quality Contributor)	Email Updates:
Status:	Closed	Impact on me:	None
Category:	MySQL Server: Logging	Severity:	S3 (Non-critical)
Version:	5.1.61, 5.5.20	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	qc

Description:
With long_query_time set to 0, ALTER does not appear in the slow query log.

How to repeat:
Enable the slow query log and set long_query_time to 0.

mysql> create table t(a int)engine=innodb;
mysql> alter table t add column b int;

The result in the slow query log:

# Time: 120330 21:29:33
# User@Host: msandbox[msandbox] @ localhost [127.0.0.1]
# Query_time: 0.026885  Lock_time: 0.000109 Rows_sent: 0  Rows_examined: 0
SET timestamp=1333157373;
create table t(a int)engine=innodb;

There should be a second entry for the ALTER.

Thank you for the bug report. Verified with 5.1.61 also:

macbook-pro:5.1 openxs$ bin/mysql -uroot testReading 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
Server version: 5.1.61-debug-log Source distribution

Copyright (c) 2000, 2011, Oracle and/or its affiliates. All rights reserved.

Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.

Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.

mysql> drop table t;
Query OK, 0 rows affected (0.00 sec)

mysql> create table t(a int)engine=innodb;
Query OK, 0 rows affected (0.06 sec)

mysql> alter table t add column b int;
Query OK, 0 rows affected (0.11 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql> exit
Bye
macbook-pro:5.1 openxs$ tail var/macbook-pro-slow.log 
# Time: 120331 10:49:18
# User@Host: root[root] @ localhost []
# Query_time: 0.061100  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1333180158;
create table t(a int)engine=innodb;
# Time: 120331 10:49:27
# User@Host: root[root] @ localhost []
# Query_time: 0.000007  Lock_time: 0.000000 Rows_sent: 0  Rows_examined: 0
SET timestamp=1333180167;
# administrator command: Quit;
macbook-pro:5.1 openxs$

"To include slow administrative statements such as OPTIMIZE TABLE, ANALYZE TABLE, and ALTER TABLE in the statements written to the slow query log, use the --log-slow-admin-statements server option."

CREATE TABLE is not considered a slow administrative statement, so it will be 
included in the slow query log regardless of --log-slow-admin-statements

ALTER TABLE is (as Davi (hi!) mentions) regarded as a slow administrative 
statement, so it will only be considered for the slow query log if 
--log-slow-admin-statements is set.

Other administrative statements are CREATE INDEX, DROP INDEX, ANALYZE TABLE, 
CHECK TABLE, OPTIMIZE TABLE, REPAIR TABLE.

So the current behavior is by design and according to the documentation
as far as I can see: http://dev.mysql.com/doc/refman/5.6/en/slow-query-log.html

Is the current behavior causing problems? Or just confusion? :-)

I was confused about admin statements and thought that --log-slow-admin-statements behaved similarly to --log-queries-not-using-indexes. I believe the documentation should be updated to reflect the difference between these. Currently the intro on http://dev.mysql.com/doc/refman/5.6/en/slow-query-log.html says the following:

The slow query log consists of SQL statements that took more than long_query_time seconds to execute and required at least min_examined_row_limit rows to be examined. 

That is an unqualified statement; it should probably say something like this instead:

The slow query log consists of SQL statements that took more than long_query_time seconds to execute and required at least min_examined_row_limit rows to be examined, except for administrative statements.

Later in the documentation that "except" can be explained as it currently is.  And it would be good to add a note to the option's own docs to explain that --log-slow-admin-statements and --log-queries-not-using-indexes differ: one includes a type of statements that is otherwise excluded by default, and the other includes statements regardless of their execution time.  I think --log-queries-not-using-indexes ought to be indicated in the above "except" as well, but I don't see a good way to phrase it.

Also, it is odd that --log-slow-admin-statements is only a command line option. We should probably have it as a system variable (and default it to true).

Thank you for your bug report. This issue has been addressed in the documentation. The updated documentation will appear on our website shortly, and will be included in the next release of the relevant products.

Added to http://dev.mysql.com/doc/refman/5.6/en/slow-query-log.html:

By default, nonadministrative statements are not logged, nor are 
queries that do not use indexes for lookups. This behavior can be
changed using --log-slow-admin-statements and
log_queries_not_using_indexes, as described later.

Modified description of --log-slow-admin-statements:

To include slow administrative statements in the statements written
to the slow query log, use the --log-slow-admin-statements server
option. Administrative statements include ALTER TABLE, ANALYZE TABLE,
CHECK TABLE, CREATE INDEX, DROP INDEX, OPTIMIZE TABLE, and REPAIR
TABLE.