log slow queries config problems.

Hi Folks,

I’ve created a log.cnf in /etc/mysql/conf.d which contains the following…

[mysqld]
log_slow_queries = /var/log/mysql/mysql-slow.log
slow_query_log = 1
long_query_time = 2
log-queries-not-using-indexes

but even though long_query_time is set to 2 ( seconds according to the docs ), I get comments such as…

Time: 120821 16:57:21

User@Host: dummy[dummy] @ localhost []

Thread_id: 267874 Schema: dummy Last_errno: 0 Killed: 0

Query_time: 0.000259 Lock_time: 0.000088 Rows_sent: 0 Rows_examined: 1 Rows_affected: 0 Rows_read: 0

Bytes_sent: 87 Tmp_tables: 1 Tmp_disk_tables: 0 tmp_table_sizes: 0

InnoDB_trx_id: 4456105

mysql> explain SELECT main_table.poll_id FROM poll AS main_table
-> INNER JOIN poll_store AS store ON main_table.poll_id=store.poll_id AND store.store_id = ‘1’ WHERE (closed = 0) ORDER BY RAND() LIMIT 1;
±—±------------±-----------±-------±----------------- -----------±--------±--------±--------------------------- ----±-----±---------------------------------------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
±—±------------±-----------±-------±----------------- -----------±--------±--------±--------------------------- ----±-----±---------------------------------------------+
| 1 | SIMPLE | main_table | ALL | PRIMARY | NULL | NULL | NULL | 1 | Using where; Using temporary; Using filesort |
| 1 | SIMPLE | store | eq_ref | PRIMARY,FK_POLL_STORE_STORE | PRIMARY | 6 | dummy.main_table.poll_id,const | 1 | Using index |
±—±------------±-----------±-------±----------------- -----------±--------±--------±--------------------------- ----±-----±---------------------------------------------+
2 rows in set (0.00 sec)

which is clearly much faster than the threshold, and the explain plan shows it using indexes. Can anyone suggest what is wrong with my config? ( is the order by rand() causing this? ).

cat /etc/debian_version

6.0.5

uname -a

Linux dummy 2.6.32-5-amd64 #1 SMP Sun May 6 04:00:17 UTC 2012 x86_64 GNU/Linux

dpkg -l | grep percona

ii percona-server-client 5.5.25a-rel27.1-277.squeeze Percona Server database client
ii percona-server-client-5.5 5.5.25a-rel27.1-277.squeeze Percona Server database client binaries
ii percona-server-common-5.5 5.5.25a-rel27.1-277.squeeze Percona Server database common files (e.g. /etc/mysql/my.cnf)
ii percona-server-server-5.5 5.5.25a-rel27.1-277.squeeze Percona Server database server binaries
ii percona-toolkit 2.1.3-1~dotdeb.0 Command-line tools for MySQL and system tasks
ii percona-xtrabackup 2.0.2-461.squeeze Open source backup tool for InnoDB and XtraDB

Cheers,

Steve

Your first table isn’t using any indexes. It is a full table scan (ALL). It only has one row, which isn’t bad, but an index isn’t used (even though PRIMARY could be used) so it is logged…