MySQL Bugs: #53821: Slow queries not being logged

Bug #53821	Slow queries not being logged
Submitted:	19 May 2010 18:35	Modified:	17 May 2011 2:38
Reporter:	Dan Slimmon	Email Updates:
Status:	No Feedback	Impact on me:	None
Category:	MySQL Server: Options	Severity:	S2 (Serious)
Version:	5.1.45	OS:	Linux (CentOS 4.5)
Assigned to:		CPU Architecture:	Any
Tags:	logging, slow query log, symlink

Description:
The following variables are defining the MySQL server settings:

+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| long_query_time | 30.000000 |
| log_output    | FILE  |
| min_examined_row_limit | 0     |
| slow_query_log      | ON                            |
| slow_query_log_file | /home/mysql/logs/db4-slow.log |
+---------------+-------+

That path is a symlink to another file.  When I run "SELECT SLEEP(31)" on the server, nothing appears in the destination file.

How to repeat:
I haven't done a lot of experiments about this, but here's exactly what has happened leading up to this issue:

Make slow_query_log_file a symlink to /dev/null.  Start mysqld.  Change the destination of the symlink to a regular file.  Run "FLUSH LOGS;".  Run a query that will last longer than long_query_time.

Upon further investigation, I've found that the symlink is not the issue.  MySQL is not writing to the slow log even if it is a regular file.

I have the same problem on MySQL 5.1.45-log on CentOS 4.5.

I had a thought, to see if I could test whether the problem was with the file or not.  Here's what I came up with:

############ slow queries are properly identified as such by MySQL:

mysql> show status like 'Slow_queries';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Slow_queries  | 0     |
+---------------+-------+
1 row in set (0.00 sec)

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

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

mysql> show status like 'Slow_queries';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| Slow_queries  | 1     |
+---------------+-------+
1 row in set (0.00 sec)

############## OK, so a slow query is being identified as such.....let's see if that happened to make it to the slow query log.  (hint:  no).

mysql> show variables like '%slow_query_log%';
+---------------------+-------------------------------+
| Variable_name       | Value                         |
+---------------------+-------------------------------+
| slow_query_log      | ON                            |
| slow_query_log_file | /home/mysql/logs/db4-slow.log |
+---------------------+-------------------------------+
2 rows in set (0.00 sec)

mysql> \! ls -l /home/mysql/logs/db4-slow.log
-rw-r--r--  1 mysql mysql 0 May 21 11:03 /home/mysql/logs/db4-slow.log

############ And just in case, let's change it to table logging and see if that works:

mysql> show variables like 'log_output';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_output    | FILE  |
+---------------+-------+
1 row in set (0.00 sec)

mysql> set global log_output=TABLE;
ERROR 1064 (42000): You have an error in your SQL syntax; check the manual that corresponds to your MySQL server version for the right syntax to use near 'TABLE' at line 1
mysql> set global log_output=FILE;
ERROR 1227 (42000): Access denied; you need the SUPER privilege for this operation

########## OK, so there's something wrong in general with logging.  http://dev.mysql.com/doc/refman/5.1/en/server-options.html#option_mysqld_log-output states that TABLE and FILE are the correct options, but TABLE gives a syntax error.  I should get an Access denied with the user I was using...

Thank you for the report.

I can not repeat described behavior. Please try with current version 5.1.47 and if problem still exists indicate which package do you use (file name you downloaded).

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

Probably min_examined_row_limit was set to non-zero.

I had the same problem and after 
    set global min_examined_row_limit = 0; 
the
    select sleep(10);
query was properly logged to the slow query log.

See http://serverfault.com/questions/193145/mysql-slow-query-log-is-on-but-not-logging-anythin... for details.

Thank you for the feedback.

min_examined_row_limit is 0 in the initial description, so we still need consistent instruction how to repeat this problem.

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".

No feedback was provided for this bug for over a month, so it is
being suspended automatically. If you are able to provide the
information that was originally requested, please do so and change
the status of the bug back to "Open".