Extended slow log: full table scan incorrectly set.

[Agustín]

'Full_scan: Yes' is shown in the slow error log, even though there was no full table scan.

mysql> explain select i from joinit limit 100;
+----+-------------+--------+-------+---------------+---------+---------+------+--------+-------------+
| id | select_type | table | type | possible_keys | key | key_len | ref | rows | Extra |
+----+-------------+--------+-------+---------------+---------+---------+------+--------+-------------+
| 1 | SIMPLE | joinit | index | NULL | PRIMARY | 4 | NULL | 522144 | Using index |
+----+-------------+--------+-------+---------------+---------+---------+------+--------+-------------+
1 row in set (0.00 sec)

Slow log shows:

# Time: 160628 22:40:25
# User@Host: root[root] @ localhost [] Id: 15
# Schema: slowlog Last_errno: 0 Killed: 0
# Query_time: 0.001879 Lock_time: 0.000253 Rows_sent: 100 Rows_examined: 100 Rows_affected: 0
# Bytes_sent: 798 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0
# InnoDB_trx_id: F5B
# QC_Hit: No Full_scan: Yes Full_join: No Tmp_table: No Tmp_table_on_disk: No
# Filesort: No Filesort_on_disk: No Merge_passes: 0
# InnoDB_IO_r_ops: 0 InnoDB_IO_r_bytes: 0 InnoDB_IO_r_wait: 0.000000
# InnoDB_rec_lock_wait: 0.000000 InnoDB_queue_wait: 0.000000
# InnoDB_pages_distinct: 3
SET timestamp=1467153625;
select i from joinit limit 100;

Create table:

CREATE TABLE `joinit` (
  `i` int(11) NOT NULL AUTO_INCREMENT,
  `s` varchar(64) DEFAULT NULL,
  `t` time NOT NULL,
  `g` int(11) NOT NULL,
  PRIMARY KEY (`i`)
) ENGINE=InnoDB DEFAULT CHARSET=latin1;

Some variables:

mysql> show variables like '%slow%';
+------------------------------------+-------------------------------------+
| Variable_name | Value |
+------------------------------------+-------------------------------------+
| log_slow_admin_statements | OFF |
| log_slow_filter | |
| log_slow_rate_limit | 1 |
| log_slow_rate_type | session |
| log_slow_slave_statements | OFF |
| log_slow_sp_statements | ON |
| log_slow_verbosity | microtime,query_plan,innodb |
| max_slowlog_files | 0 |
| max_slowlog_size | 0 |
| slow_launch_time | 2 |
| slow_query_log | ON |
| slow_query_log_always_write_time | 10.000000 |
| slow_query_log_file | /var/lib/mysql/VM-centos67-slow.log |
| slow_query_log_timestamp_always | OFF |
| slow_query_log_timestamp_precision | second |
| slow_query_log_use_global_control | |
+------------------------------------+-------------------------------------+
16 rows in set (0.00 sec)

mysql> show variables like '%version%';
+-------------------------+------------------------------------------------------+
| Variable_name | Value |
+-------------------------+------------------------------------------------------+
| innodb_version | 5.6.30-76.3 |
| protocol_version | 10 |
| slave_type_conversions | |
| version | 5.6.30-76.3-log |
| version_comment | Percona Server (GPL), Release 76.3, Revision 3850db5 |
| version_compile_machine | x86_64 |
| version_compile_os | Linux |
+-------------------------+------------------------------------------------------+
7 rows in set (0.01 sec)

I'm attaching the full slow log, for your reference. There are other queries like `show status like 'handler_read_rnd_next';` that also show this behaviour.

It works as expected with `SELECT *` queries where full table scans are needed, but it should not show 'full_scan: yes' for these other kinds of queries.

[Laurynas Biveinis (laurynas-biveinis)]

Please check if there is an associated Select_scan status variable bump with this query, as the slow log implementation is linked to it. If Select_scan is being bumped, please file an upstream bug too ("Select_scan is bumped for a query where no table scan is happenning")

[Shahriyar Rzayev (rzayev-sehriyar)]

Percona now uses JIRA for bug reports so this bug report is migrated to: https://jira.percona.com/browse/PS-1725