The Ultimate Guide to High Availability with MariaDB
This is a read-only copy of the MariaDB Knowledgebase generated on 2024-11-15. For the latest, interactive version please visit https://mariadb.com/kb/.

Slow query log and long_query_time

In my understanding if we enable slow query log, MySQL will capture all SQL statements that take more than long_query_time seconds to execute into the log.

If so below testing puzzled me:

Server version: 10.0.21-MariaDB-wsrep-log MariaDB Server, wsrep_25.10.r4144

in the mysql CLI

ip-10-74-2-218$ root@localhost[galeratest] MYSQL> select now();
+---------------------+
| now()               |
+---------------------+
| 2015-12-18 11:12:50 |
+---------------------+
1 row in set (0.00 sec)

ip-10-74-2-218$ root@localhost[galeratest] MYSQL> show variables like 'long%';
+-----------------+-----------+
| Variable_name   | Value     |
+-----------------+-----------+
| long_query_time | 10.000000 |
+-----------------+-----------+
1 row in set (0.00 sec)

ip-10-74-2-218$ root@localhost[galeratest] MYSQL> select count(*) from test_table;
+----------+
| count(*) |
+----------+
|       13 |
+----------+
1 row in set (0.00 sec)

ip-10-74-2-218$ root@localhost[galeratest] MYSQL> select sleep(5);
+----------+
| sleep(5) |
+----------+
|        0 |
+----------+
1 row in set (5.00 sec)

ip-10-74-2-218$ root@localhost[galeratest] MYSQL> select sleep(11);
+-----------+
| sleep(11) |
+-----------+
|         0 |
+-----------+
1 row in set (11.00 sec)

ip-10-74-2-218$ root@localhost[galeratest] MYSQL> select count(*) from test_table;
+----------+
| count(*) |
+----------+
|       13 |
+----------+
1 row in set (0.00 sec)

ip-10-74-2-218$ root@localhost[galeratest] MYSQL>

from the slow query log

# Time: 151218 11:13:12
# User@Host: root[root] @ localhost []
# Thread_id: 125  Schema: galeratest  QC_hit: No
# Query_time: 0.000163  Lock_time: 0.000075  Rows_sent: 1  Rows_examined: 13
SET timestamp=1450465992;
select count(*) from test_table;
# Time: 151218 11:13:48
# User@Host: root[root] @ localhost []
# Thread_id: 125  Schema: galeratest  QC_hit: No
# Query_time: 11.002494  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0
SET timestamp=1450466028;
select sleep(11);
# Time: 151218 11:14:10
# User@Host: root[root] @ localhost []
# Thread_id: 125  Schema: galeratest  QC_hit: No
# Query_time: 0.000159  Lock_time: 0.000073  Rows_sent: 1  Rows_examined: 13
SET timestamp=1450466050;
select count(*) from test_table;

Question - why the 'select count(*) from test_table' statement is captured while it seems right that select sleep(11) got captured and sleep(5) did not?

Answer Answered by Petri Rautiainen in this comment.

Most likely you have log_queries_not_using_indexes enabled in your my.cnf, this would explain the issue as the count() you are using does not use indexes. Also quick way to check if it is enable through CLI with next query: SELECT @@log_queries_not_using_indexes;

Did try on own 10.0.21 and did not have this on by default and could not replicate the problem without enable previously mentioned attribute;

Content reproduced on this site is the property of its respective owners, and this content is not reviewed in advance by MariaDB. The views, information and opinions expressed by this content do not necessarily represent those of MariaDB or any other party.