Bug #26878 Slow query log not working in 5.1.15

• Submitted: 6 Mar 2007 15:51
• Modified: 6 Mar 2007 16:34
• Reporter: Robin Schumacher
• Status: Can't repeat
• Category: MySQL Server: Logging
• Severity: S2 (Serious)
• Version: 5.1.15
• OS: Linux (Fedora core 4)
• CPU Architecture: Any

[6 Mar 2007 15:51] Robin Schumacher

Description:
Dynamic slow log does not appear to work in 5.1.15

How to repeat:
mysql> set global slow_query_log=1;
Query OK, 0 rows affected (0.00 sec)
mysql> show global variables like '%slow%';
+---------------------+----------------------------------------------------------------------------------+
| Variable_name       | Value                                                                            |
+---------------------+----------------------------------------------------------------------------------+
| log_slow_queries    | ON                                                                               |
| slow_launch_time    | 2                                                                                |
| slow_query_log      | ON                                                                               |
| slow_query_log_file | /usr/local/mysql-5.1.15-beta-linux-i686-glibc23/data/linux1.localdomain-slow.log |
+---------------------+----------------------------------------------------------------------------------+
4 rows in set (0.00 sec)

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

mysql> show global variables like '%log_output%';
+---------------+-------+
| Variable_name | Value |
+---------------+-------+
| log_output    | TABLE |
+---------------+-------+
1 row in set (0.00 sec)
mysql> select count(*) from client_transaction_hist a, client_transaction b where a.description = b.description;

+----------+
| count(*) |
+----------+
|        0 |
+----------+
1 row in set (7 min 59.33 sec)
mysql> select * from mysql.slow_log;
Empty set (0.00 sec)

[6 Mar 2007 16:34] Valeriy Kravchuk

Thank you for a problem report. Sorry, but I can not repeat the behaviour describned with latest 5.1.17-BK on Linux:

mysql> set global slow_query_log=1;
Query OK, 0 rows affected (0.02 sec)

mysql> show global variables like '%slow%';
+---------------------+----------------------------------------+
| Variable_name       | Value                                  |
+---------------------+----------------------------------------+
| log_slow_queries    | ON                                     |
| slow_launch_time    | 2                                      |
| slow_query_log      | ON                                     |
| slow_query_log_file | /home/openxs/dbs/5.1/var/suse-slow.log |
+---------------------+----------------------------------------+
4 rows in set (0.01 sec)

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

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

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

mysql> select * from mysql.slow_log;
+---------------------+---------------------------+------------+-----------+----
-------+---------------+------+----------------+-----------+-----------+--------
----------+
| start_time          | user_host                 | query_time | lock_time | row
s_sent | rows_examined | db   | last_insert_id | insert_id | server_id | sql_tex
t         |
+---------------------+---------------------------+------------+-----------+----
-------+---------------+------+----------------+-----------+-----------+--------
----------+
| 2007-03-06 12:54:45 | root[root] @ localhost [] | 00:00:20   | 00:00:00  |
     1 |             0 | test |              0 |         0 |         0 | select
sleep(20) |
+---------------------+---------------------------+------------+-----------+----
-------+---------------+------+----------------+-----------+-----------+--------
----------+
1 row in set (0.01 sec)

mysql> select version();
+-------------+
| version()   |
+-------------+
| 5.1.17-beta |
+-------------+
1 row in set (0.00 sec)

[6 Mar 2007 17:29] Robin Schumacher

Valeriy - 

Thanks for checking on this so quickly.  I did a select sleep(20) too and it does show up in the log.  Wonder why my 7 minute query with the join didn't show up?  Stange...  

Again, thanks for looking into this.

[14 Mar 2011 15:47] Jussi Kuosa

Probably min_examined_row_limit was set to non-zero.

I had a similar 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.