MySQLのEXPLAIN ANALYZEの読み方を勉強したよ

ミライトデザインアドベントカレンダー3日目です。
[ミライトデザイン Advent Calendar 2021のカレンダー | Advent Calendar 2021 - Qiita](https://qiita.com/advent-calendar/2021/miraito-inc)

昨日は@tkek321さんのKeycloakでOIDC認可コードフローをやってみる記事でした。
OIDCを実際に動かしながら勉強できるので、凄く頭に入ってきやすい良記事でした！

本日は、MySQLに関して最近自分が勉強したことを記事にさせていただきます。

## 概要

MySQL 8.0.18から`EXPLAIN ANALYZE`が導入されました。
PostgreSQLでは昔からある機能ですが、MySQLに導入されたのはつい最近のことです。

この記事では`EXPLAIN ANALYZE`の読み方について、自分が学んだ内容をご紹介できればと思います。

## `EXPLAIN ANALYZE`ってそもそも何？

### その前に`EXPLAIN`って何？

`EXPLAIN ANALYZE`を説明する前に、まずは`EXPLAIN`とは何か軽く説明します。

`EXPLAIN`は、MySQLがクエリをどのように実行するかについての情報を取得するものです。
この情報はよく**実行計画**と呼ばれます。

使い方は簡単で、実行計画を知りたいクエリの前に`EXPLAIN`を付けて実行するだけです。
例えば、あるSELECT文の実行計画が知りたければ、下記の様にSQLを実行します。

```sql
EXPLAIN SELECT * FROM users WHERE user_no='U-00000005';
+----+-------------+-------+------------+-------+---------------+---------+---------+-------+------+----------+-------+
| id | select_type | table | partitions | type  | possible_keys | key     | key_len | ref   | rows | filtered | Extra |
+----+-------------+-------+------------+-------+---------------+---------+---------+-------+------+----------+-------+
|  1 | SIMPLE      | users | NULL       | const | user_no       | user_no | 42      | const |    1 |   100.00 | NULL  |
+----+-------------+-------+------------+-------+---------------+---------+---------+-------+------+----------+-------+
```

実行計画を見ることで、

- 検索が遅くなりそうなクエリになっていないか
- どのテーブルに対する検索が遅くなっていそうか
- インデックスが適切に使用されているか

などを調べることができます。

`EXPLAIN`の読み方については、本記事では詳しく触れません。
興味がある方は下記の記事で非常に詳しく解説されています。

http://nippondanji.blogspot.com/2009/03/mysqlexplain.html

自分もこちらの記事で大変勉強させていただいたので、是非一読をおすすめします。

### `EXPLAIN ANALYZE`は`EXPLAIN`と何が違うの？

`EXPLAIN`はクエリを実行する前の計画を取得しています。

それに対して`EXPLAIN ANALYZE`は**実際にクエリを実行して**各ステップでの実行時間を測定してくれます。

そのため、クエリのどのステップに時間がかかっているかをより正確に掴むことができます。

また、実行計画と実行結果が大きく異なっているかを確認し、テーブルの統計情報がずれていないかを判断する材料にも使えます。

## 環境

MySQL: 8.0.26

今回は下記の2テーブルを使用して検証しています。

```sql
SHOW CREATE TABLE users\G
*************************** 1. row ***************************
       Table: users
Create Table: CREATE TABLE `users` (
  `id` int NOT NULL AUTO_INCREMENT,
  `user_no` varchar(10) COLLATE utf8mb4_bin NOT NULL,
  `name` varchar(20) COLLATE utf8mb4_bin DEFAULT NULL,
  `created_at` datetime DEFAULT NULL,
  `updated_at` datetime DEFAULT NULL,
  PRIMARY KEY (`id`),
  UNIQUE KEY `user_no` (`user_no`)
) ENGINE=InnoDB AUTO_INCREMENT=1048561 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin

SHOW CREATE TABLE scores\G
*************************** 1. row ***************************
       Table: scores
Create Table: CREATE TABLE `scores` (
  `id` int NOT NULL AUTO_INCREMENT,
  `user_id` int NOT NULL,
  `score` int NOT NULL,
  `created_at` datetime DEFAULT NULL,
  `updated_at` datetime DEFAULT NULL,
  PRIMARY KEY (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=2031586 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin
```

検証用のデータとして、`users`テーブルには100万件、`scores`テーブルには200万件のレコードをINSERTしています。

## Lv1. 単一テーブルに対するSELECT（全件取得）

まずは検索条件などを指定せず、最もシンプルなSELECT文に対して`EXPLAIN ANALYZE`を実行してみましょう。

```sql
EXPLAIN ANALYZE SELECT * FROM users;
+---------------------------------------------------------------------------------------------------------+
| EXPLAIN                                                                                                 |
+---------------------------------------------------------------------------------------------------------+
| -> Table scan on users  (cost=101290.81 rows=995849) (actual time=0.046..775.839 rows=1000000 loops=1)  |
+---------------------------------------------------------------------------------------------------------+
```

結果が取得できたので、これをいくつかのパーツに分解して見ていきましょう。

- `Table scan on users`

この部分は`users`テーブルをテーブルスキャンで検索したことを表しています。
テーブルスキャンとは、インデックスなどを使用せずにテーブル内の全てのレコードを検索したという意味になります。
非常に遅い検索方法なので、クエリチューニングの必要性が出た場合は改善する有力候補になります。

- `(cost=101290.81 rows=995849) `

この部分は**推定実行コスト**[^1]と**戻される行の推定数**を表しています。
ここはクエリ実行前の推定値なので、`EXPLAIN`で取得できるものと同じ値になります。

[^1]: 注意点として、costの数字は具体的な時間などを表すものではなく、後に出てくる実行時間（ミリ秒）とは直接比較できません。単に値が大きければコストが大きい（≒遅い、DBに負担がかかる）、値が小さければコストが小さい（≒速い、DBへの負担が少ない）という目安の数字だと思ってください。

- `(actual time=0.046..775.839 rows=1000000 loops=1)`

`actual time`は最初の行・全ての行を取得するのに実際にかかった時間（ミリ秒）を表しています。ここで特に重要なのは全ての行を取得するのにかかった時間の方で、**実際のコスト**とみなすことができます。
`rows`は実際にクエリで取得した行数となります。この場合は100万件のレコードが取得されたことになります（そのまんま）。
`loops`はこのステップのループ数を表しています。この例ではloops=1なのでイメージしづらいかもしれませんので、後ほど説明します。

## Lv.2 複数のテーブルをJOINしてSELECT

続いて2つのテーブルをJOINした例を見てみましょう。
`users`テーブルと`scores`テーブルをJOINしてみます。

```sql
EXPLAIN ANALYZE SELECT * FROM users u JOIN scores s ON u.id = s.user_id WHERE u.id < 100;
+----------------------------------------------------------------------------------------------------------------------------------------+
| EXPLAIN                                                                                                                                |
+----------------------------------------------------------------------------------------------------------------------------------------+
| -> Nested loop inner join  (cost=2399258.64 rows=1994337) (actual time=9.622..598.250 rows=198 loops=1)                                |
|     -> Filter: (s.user_id < 100)  (cost=205487.94 rows=1994337) (actual time=9.598..597.860 rows=198 loops=1)                          |
|         -> Table scan on s  (cost=205487.94 rows=1994337) (actual time=9.595..530.336 rows=2000000 loops=1)                            |
|     -> Single-row index lookup on u using PRIMARY (id=s.user_id)  (cost=1.00 rows=1) (actual time=0.002..0.002 rows=1 loops=198)       |
+----------------------------------------------------------------------------------------------------------------------------------------+
```

~~Oh、、、頭痛くなってきた~~
大分複雑になりましたが、1つずつ見ていけば理解できるはずです。

まず、先程と異なり結果が4行になっています。
さらによく見ると単に4行並んでいるだけでなく、ネストしたツリー構造になっています。

これはMySQL 8.0.16から追加された、`EXPLAIN FORMAT=TREE`という表示形式です。

このツリー構造の読み方についてはMySQLの公式ドキュメントでは見つけられませんでした（ご存じの方、誰か教えて下さいm(_ _)m）が、基本的にはOracleやPostgreSQLの実行計画と同じ読み方ができると思います。

基本的にはツリー構造を見て、次のルール[^2]で読んでいきます。

- ネストが深い方→浅い方の順に読む
- 同じ階層にあるものは上から読む

[^2]: 厳密には[こちらの記事](https://cosol.jp/techdb/2020/04/how_to_read_oracle_sql_execution_plan/#i-5)で紹介されている通り、ネストが最も深い順に実行されるとは限らないのですが、ここでは説明を単純化しています。もっと厳密に理解したい方は左記の記事を参考にしてみてください。

まずツリー構造を整理すると下記のような形式になっています。

```
A
├─ B
│  └ C
└─ D
```

この場合はC→B→D→Aの順で実行されています。
つまり、先程の結果は下記のような操作が行われていることを示しています。

1. `Table scan on s ... `で、`scores`テーブルをテーブルスキャンしている
2. `Filter: (s.user_id < 100) ...`で、1の結果を`scores.user_id < 100`の条件で絞り込みしている
3. `Single-row index lookup on u using PRIMARY ...`で、`users`テーブルを1行ずつ主キー検索している
    - ここで`loops=198`となっているので、このステップが198回実行されたことを示しています。ここから、2で取得した行（`rows=198`）に対して1件ずつ検索が行われたことがわかります。
4. `Nested loop inner join ... `で、2, 3の結果を[Nested Loop](https://dev.mysql.com/doc/refman/8.0/ja/nested-loop-joins.html)して結合している

何となく雰囲気を掴んでいただけたでしょうか。
~~こちとら、何となくの雰囲気でしか理解しとらんぞい~~

### `EXPLAIN ANALYZE`の結果を見てクエリを改善しよう

ここで、クエリの実行速度を改善するために`EXPLAIN ANALYZE`の結果を再度見てみましょう。

```sql
EXPLAIN ANALYZE SELECT * FROM users u JOIN scores s ON u.id = s.user_id WHERE u.id < 100;
+----------------------------------------------------------------------------------------------------------------------------------------+
| EXPLAIN                                                                                                                                |
+----------------------------------------------------------------------------------------------------------------------------------------+
| -> A. Nested loop inner join  (cost=2399258.64 rows=1994337) (actual time=9.622..598.250 rows=198 loops=1)                                |
|     -> B. Filter: (s.user_id < 100)  (cost=205487.94 rows=1994337) (actual time=9.598..597.860 rows=198 loops=1)                          |
|         -> C. Table scan on s  (cost=205487.94 rows=1994337) (actual time=9.595..530.336 rows=2000000 loops=1)                            |
|     -> D. Single-row index lookup on u using PRIMARY (id=s.user_id)  (cost=1.00 rows=1) (actual time=0.002..0.002 rows=1 loops=198)       |
+----------------------------------------------------------------------------------------------------------------------------------------+
```

※便宜上、各ステップにA, B, C, Dとラベルを付けました。
更に、実行順はC→B→D→Aだったことも思い出しておきましょう。

さて、まず`actual time`を見てみると、A, B, Cが500ミリ秒を超えており、Cの実行時点で既に時間がかかっていることがわかると思います。

また、Cに`Table scan`の文言があり、取得した行（`rows`）が200万件であることからも、`scores`テーブルを全件検索しているのが問題だと予想できます。

~~、、、犯人はCさん、アンタだよ！！~~

ここで、`scores.user_id`に外部キー制約をかけていなかったことに気づいたので、追加してみましょう。

```sql
ALTER TABLE scores ADD FOREIGN KEY (user_id) REFERENCES users(id);
Query OK, 2000000 rows affected (31.23 sec)
Records: 2000000  Duplicates: 0  Warnings: 0

SHOW CREATE TABLE scores\G
*************************** 1. row ***************************
       Table: scores
Create Table: CREATE TABLE `scores` (
  `id` int NOT NULL AUTO_INCREMENT,
  `user_id` int NOT NULL,
  `game_id` int NOT NULL,
  `score` int NOT NULL,
  `created_at` datetime DEFAULT NULL,
  `updated_at` datetime DEFAULT NULL,
  PRIMARY KEY (`id`),
  KEY `user_id` (`user_id`),
  CONSTRAINT `scores_ibfk_1` FOREIGN KEY (`user_id`) REFERENCES `users` (`id`)
) ENGINE=InnoDB AUTO_INCREMENT=2031586 DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin
```

再度`EXPLAIN ANALYZE`を実行してみましょう。

```sql
EXPLAIN ANALYZE SELECT * FROM users u JOIN scores s ON u.id = s.user_id WHERE u.id < 100;
+-----------------------------------------------------------------------------------------------------------------------+
| EXPLAIN                                                                                                               |
+-----------------------------------------------------------------------------------------------------------------------+
| -> Nested loop inner join  (cost=103.23 rows=99) (actual time=0.107..6.201 rows=198 loops=1)                          |
|     -> Filter: (u.id < 100)  (cost=20.94 rows=99) (actual time=0.032..0.273 rows=99 loops=1)                          |
|         -> Index range scan on u using PRIMARY  (cost=20.94 rows=99) (actual time=0.028..0.237 rows=99 loops=1)       |
|     -> Index lookup on s using user_id (user_id=u.id)  (cost=0.73 rows=1) (actual time=0.058..0.059 rows=2 loops=99)  |
+-----------------------------------------------------------------------------------------------------------------------+
```

`actual time`を見ると、最終行取得まで6ミリ秒しかかかっていないことがわかります。改善前が598ミリ秒だったので、約100倍処理速度が改善したことになります。

なお、改善後の結果を軽く記しておくと

1. `Index range scan on u using PRIMARY ... `で、`users`テーブルを主キーを使用して範囲検索している
    - `rows=99`と取得している件数が減っていること、`actual time`が改善していることに注目しましょう。なお、検索しているテーブルも`users`が先になっています。
2. `Filter: (u.id < 100) ...`で、1の結果を`users.id < 100`の条件で絞り込みしている
3. `Index lookup on s using user_id ...`で、`scores`テーブルを1行ずつインデックス検索している
    - 先程外部キー制約を追加したことにより、`scores.user_id`にはインデックスが張られている
4. `Nested loop inner join ... `で、2, 3の結果を[Nested Loop](https://dev.mysql.com/doc/refman/8.0/ja/nested-loop-joins.html)して結合している

となります。

## まとめ

- `EXPLAIN`は実行計画（MySQLがクエリをどの様に実行するかの計画）を見ることができる
- `EXPLAIN ANALYZE`は実行計画と、実際にクエリを実行した結果を見ることができる
    - `(cost=xxx rows=xxx)`の部分は**推定実行コスト**と**戻される行の推定数**で、これは`EXPLAIN`で取得できるものと同じである
    - `(actual time=xxx..xxx rows=xxx loops=xxx)`は実際にクエリを実行して**かかった時間（ミリ秒）**、**取得した行数**、**実行された回数**を表している
- `EXPLAIN ANALYZE`が複数ステップでネストしている場合、**ネストが深いところから**順に読んでいく


明日は@polidogさんの記事になります。
PHPについて書いてくれるみたいなので、個人的にもめっちゃ気になっています。
お楽しみに！


## 参考

### MySQLマニュアル

[MySQL :: MySQL 8.0 リファレンスマニュアル :: 13.8.2 EXPLAIN ステートメント](https://dev.mysql.com/doc/refman/8.0/ja/explain.html)
[MySQL :: MySQL 8.0 リファレンスマニュアル :: 8.8.2 EXPLAIN 出力フォーマット](https://dev.mysql.com/doc/refman/8.0/ja/explain-output.html)

### EXPLAIN ANALYZEについて

[Using Explain Analyze in MySQL 8 - Percona Database Performance Blog](https://www.percona.com/blog/2019/10/28/using-explain-analyze-in-mysql-8/)
[MySQL :: WL#4168: Implement EXPLAIN ANALYZE](https://dev.mysql.com/worklog/task/?id=4168)

### EXPLAIN FORMAT=TREEの読み方

[Georgi Sotirov's Blog: TREE explain format in MySQL 8.0.16](https://gdsotirov.blogspot.com/2019/06/tree-explain-format-in-mysql-8016.html)
[Oracle SQL実行計画の読み方 | コーソルDatabaseエンジニアのBlog](https://cosol.jp/techdb/2020/04/how_to_read_oracle_sql_execution_plan/#i-5)
[PolarDB · 特性分析 · Explain Format Tree 详解](http://mysql.taobao.org/monthly/2021/02/01/)