ちゃんるいすのブログ

オタクエンジニアの雑記

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


1回目は7秒かかるクエリが、2回目は速い。
実行計画を見ても、Slow Query を見てもインデックスは使われてそうなイキフンを感じる。

前置き

新しく Aurora MySQL を作成し、検証用のクエリ以外は流れないようにする。
遅いクエリは 7.5秒, 2回目実行すると 20ms とかで返ってくる。

クエリ

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

id select_type table type possible_keys key key_len ref rows Extra
1 SIMPLE t1 range idx_c3_c2, c2_c4_idx idx_c3_c2 13 NULL 21 Using where

Slow Query

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

調べる

考えられる原因として、I/O に時間がかかってると予想し、
とりあえず Performance Schema を有効にする。

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|

結果

Buffer Pool が空の状態と、2回目の file_summary_by_instance を比較する

1回目

f:id:rarirureluis:20200615222043p:plain

2回目

f:id:rarirureluis:20200615222057p:plain

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

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

解決方法

教えてください。

ふと思いつくのは

  • innodb_file_per_table を付ける(今回はついてた)
  • 不要なレコード数を削除して、Buffer Pool に乗る量を減らす(不要なレコードはない)
  • クエリを見直して舐める行数を減らす(舐める行数は2000行ぐらいしかないけど、パーティショニングの範囲が広すぎるせい)
  • それでもダメなら Buffer Pool を増やす(これが一番?)

ぐらいなのかなぁ。と思ったけどパーティションを20以上も見てるということはこれ以上 I/O は削減できなさそう。
いらないレコード削除できるだけでも良いかもしれないけどこれは履歴を保存してるのでそれは厳しそう。

今んとこの解決方法としてはメモリを増やす ということしか思いつかば無いんですが
他にいい案があったら教えてください。

EXPLAIN と実際の舐める行数が剥離する理由

WHERE 句によってその時どきで結果は変わるけど、今回の WHERE 句には不変な値しか指定していないのにも関わらず
EXAPLAIN では rows 21、Slow Query 読みだと 1914行と90倍の差がある。

EXPLAIN はインデックスのカーディナリティから推測する。
もし、オプティマイザがベストなインデックスを選択していれば実際に舐める行数(今回で言う Slow Query)と差異があっても
何も問題ないよう。

勉強になりました。

8.0.19 以降ならもっと便利に

EXPLAIN ANALYZE

Aurora MySQL でスロークエリの調査をするのはダルい

Survivable Cache Warming という、機能のせいで DB インスタンスを再起動してもキャッシュが残るので
空にするには逐一 DB を作り直さないといけない。
docs.aws.amazon.com