Bug #80467 log_queries_not_using_indexes is not working as expected in 5.7
Submitted: 22 Feb 2016 9:26 Modified: 31 Mar 2016 10:29
Reporter: Ramesh Sivaraman (OCA) Email Updates:
Status: Verified Impact on me:
None 
Category:MySQL Server: Logging Severity:S3 (Non-critical)
Version:5.7.11 OS:CentOS
Assigned to: CPU Architecture:Any

[22 Feb 2016 9:26] Ramesh Sivaraman
Description:
Some of the SQL statements that are using "full table scan" is not getting logged in slow query log if we turn on log_queries_not_using_indexes. Those queries are logging in 5.6 slow query log. 

As per the document, the queries which are using full table scan should be logged in slow query log. 

https://dev.mysql.com/doc/refman/5.7/en/server-options.html#option_mysqld_log-queries-not-...

"If you are using this option with the slow query log enabled, queries that are expected to retrieve all rows are logged. See Section 5.2.5, “The Slow Query Log”. This option does not necessarily mean that no index is used. For example, a query that uses a full index scan uses an index but would be logged because the index would not limit the number of rows."

How to repeat:
Please find the testcase

******************** 5.6
mysql> select @@slow_query_log,@@general_log,@@log_queries_not_using_indexes,@@log_output,@@slow_launch_time;
+------------------+---------------+---------------------------------+--------------+--------------------+
| @@slow_query_log | @@general_log | @@log_queries_not_using_indexes | @@log_output | @@slow_launch_time |
+------------------+---------------+---------------------------------+--------------+--------------------+
|                1 |             1 |                               1 | TABLE        |                  0 |
+------------------+---------------+---------------------------------+--------------+--------------------+
1 row in set (0.00 sec)

mysql>

CREATE TABLE t1 (f1 INTEGER PRIMARY KEY) ENGINE=InnoDB;
INSERT INTO t1 VALUES (1),(2).......;
mysql> SELECT 1 = 1 from test.t1;
+-------+
| 1 = 1 |
+-------+
|     1 |
[..]
|     1 |
+-------+
100 rows in set (0.43 sec)

mysql>  select rows_sent,rows_examined,sql_text from mysql.slow_log where sql_text ='SELECT 1 = 1 from test.t1';
+-----------+---------------+---------------------------+
| rows_sent | rows_examined | sql_text                  |
+-----------+---------------+---------------------------+
|       100 |           100 | SELECT 1 = 1 from test.t1 |
+-----------+---------------+---------------------------+
1 row in set (0.00 sec)

mysql>  select @@version;
+------------+
| @@version  |
+------------+
| 5.6.29-log |
+------------+
1 row in set (0.00 sec)

mysql>  EXPLAIN SELECT 1 = 1 from test.t1;
+----+-------------+-------+-------+---------------+---------+---------+------+------+-------------+
| id | select_type | table | type  | possible_keys | key     | key_len | ref  | rows | Extra       |
+----+-------------+-------+-------+---------------+---------+---------+------+------+-------------+
|  1 | SIMPLE      | t2    | index | NULL          | PRIMARY | 4       | NULL |  100 | Using index |
+----+-------------+-------+-------+---------------+---------+---------+------+------+-------------+
1 row in set (0.04 sec)

mysql> SELECT EVENT_ID,SQL_TEXT,ROWS_SENT,ROWS_EXAMINED,NO_INDEX_USED FROM performance_schema.events_statements_history WHERE EVENT_ID=29;
+----------+---------------------------+-----------+---------------+---------------+
| EVENT_ID | SQL_TEXT                  | ROWS_SENT | ROWS_EXAMINED | NO_INDEX_USED |
+----------+---------------------------+-----------+---------------+---------------+
|       29 | SELECT 1 = 1 from test.t1 |       100 |           100 |             1 |
+----------+---------------------------+-----------+---------------+---------------+
1 row in set (0.00 sec)

mysql> 

********************* 5.7

mysql> select @@slow_query_log,@@general_log,@@log_queries_not_using_indexes,@@log_output,@@slow_launch_time;
+------------------+---------------+---------------------------------+--------------+--------------------+
| @@slow_query_log | @@general_log | @@log_queries_not_using_indexes | @@log_output | @@slow_launch_time |
+------------------+---------------+---------------------------------+--------------+--------------------+
|                1 |             1 |                               1 | TABLE        |                  0 |
+------------------+---------------+---------------------------------+--------------+--------------------+
1 row in set (0.00 sec)

mysql>

CREATE TABLE t1 (f1 INTEGER PRIMARY KEY) ENGINE=InnoDB;
INSERT INTO t1 VALUES (1),(2).......;
mysql>  SELECT 1 = 1 from test.t1;
+-------+
| 1 = 1 |
+-------+
|     1 |
[..]
|     1 |
+-------+
100 rows in set (0.16 sec)

mysql>  select rows_sent,rows_examined,sql_text from mysql.slow_log where sql_text ='SELECT 1 = 1 from test.t1';
Empty set (0.05 sec)

mysql> select @@version;
+------------+
| @@version  |
+------------+
| 5.7.11-log |
+------------+
1 row in set (0.00 sec)

mysql>  EXPLAIN SELECT 1 = 1 from test.t1;
+----+-------------+-------+------------+-------+---------------+---------+---------+------+------+----------+-------------+
| id | select_type | table | partitions | type  | possible_keys | key     | key_len | ref  | rows | filtered | Extra       |
+----+-------------+-------+------------+-------+---------------+---------+---------+------+------+----------+-------------+
|  1 | SIMPLE      | t1    | NULL       | index | NULL          | PRIMARY | 4       | NULL |  100 |   100.00 | Using index |
+----+-------------+-------+------------+-------+---------------+---------+---------+------+------+----------+-------------+
1 row in set, 1 warning (0.03 sec)

mysql> SELECT EVENT_ID,SQL_TEXT,ROWS_SENT,ROWS_EXAMINED,NO_INDEX_USED FROM performance_schema.events_statements_history WHERE EVENT_ID=2;
+----------+---------------------------+-----------+---------------+---------------+
| EVENT_ID | SQL_TEXT                  | ROWS_SENT | ROWS_EXAMINED | NO_INDEX_USED |
+----------+---------------------------+-----------+---------------+---------------+
|        2 | SELECT 1 = 1 from test.t1 |       100 |           100 |             0 |
+----------+---------------------------+-----------+---------------+---------------+
1 row in set (0.01 sec)

mysql>
[31 Mar 2016 10:29] Umesh Shastry
Hello Ramesh,

Thank you for the report.
Observed this with 5.7.11 build.

Thanks,
Umesh
[31 Mar 2016 10:31] Umesh Shastry
test results

Attachment: 80467.results (application/octet-stream, text), 12.92 KiB.