MySQL EXPLAIN の結果は良い感じなのに、何故か遅いクエリの原因を調べる

クエリ

SELECT c1, c2, c3, c4, c5
FROM t1
WHERE ((c3 = 1489930231868609 and c4 in (7, 1169) and c2 between '2018-05-29 10:33:35.495' and '2020-05-29 10:33:35.495'))
ORDER BY c2 desc, c1 desc;

テーブル

mysql> show create table t1 \G;
*************************** 1. row ***************************
Table: t1
Create Table: CREATE TABLE `t1` (
`c1` bigint(20) unsigned NOT NULL AUTO_INCREMENT,
`c2` datetime NOT NULL,
`c3` bigint(20) unsigned NOT NULL,
`c4` bigint(20) unsigned NOT NULL,
`c5` varchar(255) NOT NULL,
`c6` varchar(255) NOT NULL,
`c7` varchar(255) NOT NULL,
`c8` varchar(255) DEFAULT NULL,
`c9` datetime NOT NULL,
`c10` datetime NOT NULL,
PRIMARY KEY (`c1`,`c2`),
KEY `idx_c3_c2` (`c3`,`c2`),
KEY `c2_c4_idx` (`c2`,`c4)
) ENGINE=InnoDB AUTO_INCREMENT=2081930928 DEFAULT CHARSET=utf8
/*!50500 PARTITION BY RANGE  COLUMNS(c2)
(PARTITION part_201501 VALUES LESS THAN ('2015-01-01 00:00:00') ENGINE = InnoDB,
 ...
 PARTITION part_202010 VALUES LESS THAN ('2020-10-01 00:00:00') ENGINE = InnoDB,
 ... */

EXPLAIN

Slow Query

# Query_time: 6.397257  Lock_time: 1.034133 Rows_sent: 0  Rows_examined: 1914

Performance Schema

mysql> SHOW VARIABLES LIKE 'per%';
mysql> UPDATE performance_schema.setup_instruments SET ENABLED = 'YES', TIMED = 'YES';
mysql> UPDATE performance_schema.setup_consumers SET ENABLED = 'YES';

file_summary_by_instance

ファイルごとに I/O の統計情報が見れる。

table_io_waits_summary_by_table という便利なテーブルもあるけど、何故か Aurora MySQL だと見れなかった。
今回は検証用の DB なので他のクエリは流れないのでこれで行く。

純粋にテーブルを見ても良いし、ps-top を見ても良い。
もし、I/O が発生していたら Buffer Pool に載っておらず、Buffer Pool への取り込むのに時間がかかっていると予測できる。

github.com

MySQL 5.7 で EXPLAIN をする

MySQL 5.7 では EXPLAIN の情報が増えていて、partitions というカラムがある。
パーティショニングされたテーブルだと、舐めるであろうパーティションが見れる

id|select_type|table          |partitions                                                                                                                                                                                                                                                     |type |possible_keys                                 |key               |key_len|ref|rows|filtered|Extra                             |
--|-----------|---------------|---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------|-----|----------------------------------------------|------------------|-------|---|----|--------|----------------------------------|
1|SIMPLE     |t1|part_201806,part_201807,part_201808,part_201809,part_201810,part_201811,part_201812,part_201901,part_201902,part_201903,part_201904,part_201905,part_201906,part_201907,part_201908,part_201909,part_201910,part_201911,part_201912,part_202001,part_202002,par|range|idx_account_number,execute_date_partner_id_idx|idx_account_number|13     |   |1914|    20.0|Using index condition; Using where|

１回目

２回目

１回目でクエリが返ってくるまで 7.5秒ぐらいあったので、ほとんどが I/O による時間であることが予測できる。
２回目は Buffer Pool にデータが載ってるので I/O が発生せずに数ミリ秒で返ってくる。

このテーブルは数億行のテーブルで、頻繁にアクセスもないようなので Buffer Pool に常に載っているわけではないと予想。