MySQL Bugs: #69295: Slow_queries status variable incremented when it should not

Bug #69295	Slow_queries status variable incremented when it should not
Submitted:	21 May 2013 16:22	Modified:	22 May 2013 9:04
Reporter:	Cyril SCETBON	Email Updates:
Status:	Verified	Impact on me:	None
Category:	MySQL Server: Options	Severity:	S3 (Non-critical)
Version:	5.1.44, 5.6.10	OS:	Any
Assigned to:		CPU Architecture:	Any
Tags:	slow queries

Description:
Here are the system variables configuration
| log_queries_not_using_indexes           | ON                                                             |
| slow_query_log                          | ON                                                             
| slow_query_log_file                     | /var/log/mysql/mysql-slow.log                 
| long_query_time | 10.000000 |

if log_queries_not_using_indexes is enabled, Slow_queries status variable is incremented whenever there is a query that does not use an index even if it takes less than long_query_time seconds :

mysqladmin extended-status -i 10 -r |grep -i Slow_queries
| Slow_queries                      | 95057         |
| Slow_queries                      | 0             | <- log_queries_not_using_indexes is disabled
| Slow_queries                      | 0             |
| Slow_queries                      | 0             |
| Slow_queries                      | 0             |
| Slow_queries                      | 0             |
| Slow_queries                      | 0             |
| Slow_queries                      | 0             |
| Slow_queries                      | 0             |
| Slow_queries                      | 75            | <- log_queries_not_using_indexes is enabled
| Slow_queries                      | 76            |
| Slow_queries                      | 46            |
| Slow_queries                      | 40            |
| Slow_queries                      | 66            |
| Slow_queries                      | 97            |
| Slow_queries                      | 95            |
| Slow_queries                      | 92            |
| Slow_queries                      | 74            |
| Slow_queries                      | 56            |

And as you can see queries are not taking too much time !

tail -f /var/log/mysql/mysql-slow.log   |grep -i Query_time
# Query_time: 0.005186  Lock_time: 0.000044 Rows_sent: 3  Rows_examined: 297
# Query_time: 0.002449  Lock_time: 0.000035 Rows_sent: 3  Rows_examined: 297
# Query_time: 0.003077  Lock_time: 0.000033 Rows_sent: 3  Rows_examined: 297
# Query_time: 0.002616  Lock_time: 0.000037 Rows_sent: 0  Rows_examined: 297
# Query_time: 0.002769  Lock_time: 0.000033 Rows_sent: 3  Rows_examined: 297
# Query_time: 0.003283  Lock_time: 0.000032 Rows_sent: 3  Rows_examined: 297
# Query_time: 0.003147  Lock_time: 0.000035 Rows_sent: 3  Rows_examined: 297
# Query_time: 0.005299  Lock_time: 0.000033 Rows_sent: 3  Rows_examined: 297
# Query_time: 0.003446  Lock_time: 0.000041 Rows_sent: 3  Rows_examined: 297
# Query_time: 0.003449  Lock_time: 0.000033 Rows_sent: 3  Rows_examined: 297
# Query_time: 0.002503  Lock_time: 0.000034 Rows_sent: 3  Rows_examined: 297
# Query_time: 0.002750  Lock_time: 0.000031 Rows_sent: 3  Rows_examined: 297
# Query_time: 0.003391  Lock_time: 0.000040 Rows_sent: 3  Rows_examined: 297
# Query_time: 0.021060  Lock_time: 0.000064 Rows_sent: 3  Rows_examined: 297

And your documentation says at http://dev.mysql.com/doc/refman/5.6/en/server-status-variables.html#statvar_Slow_queries that it must show the number of queries that have taken MORE THAN long_query_time seconds

How to repeat:
mysql > CREATE TABLE `t` (
  `id` int(11) DEFAULT NULL,
  `c` int(11) DEFAULT NULL
);

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

mysql> set global log_queries_not_using_indexes=ON;
Query OK, 0 rows affected (0.00 sec)

mysql> show global status like '%slow%';
+---------------------+-------+
| Variable_name       | Value |
+---------------------+-------+
| Slow_launch_threads | 0     |
| Slow_queries        | 0     |
+---------------------+-------+

mysql> select count(*) from t;
+----------+
| count(*) |
+----------+
|         0 |
+----------+
1 row in set (0.00 sec)

mysql> show global status like '%slow%';
+---------------------+-------+
| Variable_name       | Value |
+---------------------+-------+
| Slow_launch_threads | 0     |
| Slow_queries        | 1     |
+---------------------+-------+
2 rows in set (0.00 sec)

mysql> show global variables like '%long%';
+--------------------------------------------------------+-----------+
| Variable_name                                          | Value     |
+--------------------------------------------------------+-----------+
| long_query_time                                        | 10.000000 |

Hello Cyril,

Thank you for the feedback.

At first, this sounds as if NOT A BUG, since it is known fact that Slow_queries count is determined based on the queries logged to slow query log and the following order to determine whether to write a query to the slow query log:

- The query must either not be an administrative statement, or --log-slow-admin-statements must have been specified.
- The query must have taken at least long_query_time seconds, or log_queries_not_using_indexes must be enabled and the query used no indexes for row lookups.
- The query must have examined at least min_examined_row_limit rows.
- The query must not be suppressed according to the log_throttle_queries_not_using_indexes setting. 

So, looking at the "select count(*) from t;" it certainly fall into the second category i.e log_queries_not_using_indexes must be enabled and the query used no indexes for row lookups.

So, looks like a FR for a new status variable called "query_not_using_indexes" or something...  to separate actual slow queries must have taken at least long_query_time seconds and those used no indexes for row lookups.

Normally, "slow_queries" is the number of queries written to the slow log for some reason. that reason might be no indexes or duration is too long.  docs could be clearer then. and server could be clearer by providing another status variable.

I understand, but your documentation should be updated too cause that's really sounds like a bug after having read it. That's the first time I see the different cases you announced concerning this counter value, if it's already documented somewhere, the documentation of this counter should point to it too.