MariaDB 10.3 on Debian 10 ignores long_query_time value

Question

I have enabled the Slow Query Log on a Mariadb 10.3 server on Debian 10. Below is the implemented configuration

MariaDB [(none)]> show session variables like '%slow%';

MariaDB [(none)]> show session variables like '%slow%';
+------------------------------+-------------------------------+| 
Variable_name                | Value                         |
+------------------------------+-------------------------------+| 
log_slow_admin_statements    | ON                            || 
log_slow_disabled_statements | sp                            || 
log_slow_filter              |                               || 
log_slow_rate_limit          | 1                             || 
log_slow_slave_statements    | ON                            || 
log_slow_verbosity           |                               || 
slow_launch_time             | 2                             || 
slow_query_log               | ON                            || 
slow_query_log_file          | /var/log/mysql/mysql-slow.log |
+------------------------------+-------------------------------+

MariaDB [(none)]> show session variables like '%long_query_time%';

+-----------------+----------+| 
Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 4.000000 |
+-----------------+----------+

MariaDB [(none)]> show variables like '%long_query_time%';

+-----------------+----------+| 
Variable_name   | Value    |
+-----------------+----------+
| long_query_time | 4.000000 |
+-----------------+----------+

MariaDB [(none)]> show session variables like '%log_queries_not_using_indexes%';

+-------------------------------+-------+| 
Variable_name                 | Value |
+-------------------------------+-------+| 
log_queries_not_using_indexes | OFF   |
+-------------------------------+-------+

MariaDB [(none)]> show variables like '%log_queries_not_using_indexes%';

+-------------------------------+-------+| 
Variable_name                 | Value |
+-------------------------------+-------+| 
log_queries_not_using_indexes | OFF   |
+-------------------------------+-------+

As shown in the log file below, all queries are logged, even those that run with a time less than the value of the long_query_time parameter (4.000000)

# User@Host: xxxx[xxxx] @ xxxxxxx [x.x.x.x]# Thread_id: 1035728  Schema: xxxx  QC_hit: No
# Query_time: 0.000058  Lock_time: 0.000021  Rows_sent: 2  Rows_examined: 2
# Rows_affected: 0  Bytes_sent: 80
SET timestamp=1669676402;
SELECT id FROM site;
# User@Host: xxxx[xxxx] @ xxxxxxx [x.x.x.x]
# Thread_id: 1035716  Schema: xxxx  QC_hit: No
# Query_time: 0.000053  Lock_time: 0.000019  Rows_sent: 2  Rows_examined: 2
# Rows_affected: 0  Bytes_sent: 80
SET timestamp=1669676402;
SELECT id FROM site;
# User@Host: xxxx[xxxx] @ xxxxxxx [x.x.x.x]
# Thread_id: 1035737  Schema: xxxx  QC_hit: No
# Query_time: 0.000058  Lock_time: 0.000022  Rows_sent: 2  Rows_examined: 2
# Rows_affected: 0  Bytes_sent: 80
SET timestamp=1669676402;
SELECT id FROM site;
# User@Host: xxxx[xxxx] @ xxxxxxx [x.x.x.x]
# Thread_id: 1035723  Schema: xxxx  QC_hit: No
# Query_time: 0.000060  Lock_time: 0.000022  Rows_sent: 2  Rows_examined: 2
# Rows_affected: 0  Bytes_sent: 80
SET timestamp=1669676402;
SELECT id FROM site;
# User@Host: xxxx[xxxx] @ xxxxxxx [x.x.x.x]
# Thread_id: 1037049  Schema: xxxx  QC_hit: No
# Query_time: 0.000063  Lock_time: 0.000024  Rows_sent: 2  Rows_examined: 2
# Rows_affected: 0  Bytes_sent: 80
SET timestamp=1669676402;

For information, I implemented the same configuration on Mariadb 10.1 Debian 9. And the parameter long_query_time is well taken into account

Any help will be appreciated.

score 2 · Accepted Answer · edited Dec 11 '22 at 06:17

This is the behaviour of the existing bug MDEV-21187.

A fix has been developed and will undergo review before being included in the next release.

A work around of setting log_slow_filter=query_cache_miss,query_cache (assuming your query cache is disabled, or the qcache queries are faster than long_query_time) should be sufficient to avoid this log_queries_not_using_indexes=ON behaviour in the logs.

Alternately setting min_examined_row_limit=10000 to 10k or so will only show slow queries where > 10k rows where examined so this will reduce the log_queries_not_using_indexes=ON behavour for small tables.

MariaDB 10.3 on Debian 10 ignores long_query_time value

1 Answers1