MySQL 8 系でクエリ改善に便利な EXPLAIN ANALYZE の使い方を紹介します

こんにちは。
開発チームのワイルド担当、まんだいです。

今回は MySQL 8 系でクエリ改善に便利な EXPLAIN ANALYZE の使い方を紹介します。

MySQL でクエリチューニングをする際、 EXPLAIN を使用することが一般的だと思いますが、 EXPLAIN はクエリの実行計画を表示するだけで、実際のクエリの実行時間や行数などの詳細な情報は提供しませんでした。

しかし、 MySQL 8 系からは EXPLAIN ANALYZE を使用することで、 EXPLAIN では分からなかったことが色々わかるようになります。それでは見ていきましょう！

EXPLAIN ANALYZE とは？

EXPLAIN ANALYZE は、 MySQL 8 系で導入された新しい機能で、クエリチューニングをするにあたって非常に便利なツールです。

EXPLAIN ANALYZE と EXPLAIN が決定的に違うのは、 EXPLAIN はオプティマイザの統計情報に基づいたクエリの実行計画を表示するのに対し、 EXPLAIN ANALYZE は実際にクエリを実行することによって、クエリの実行時間が正確にわかるところです。

実際にクエリを実行する、という部分がとても重要で、実際に動かしたからこそクエリの実行時間や、実際に処理された行数など詳細な情報は信用に足るものになります。

また、内部処理の段階ごとに細かく実行時間がわかるため、クエリのどの部分がボトルネックになっているのかを特定することができるのが開発者にとってとても嬉しいポイントです。

EXPLAIN ANALYZE が提供する情報

EXPLAIN ANALYZE を使用すると、以下のような情報が提供されます。

explain analyze select ...(省略)...\G
*************************** 1. row ***************************
EXPLAIN: -> Nested loop left join  (cost=10.2 rows=2.13) (actual time=0.192..3.42 rows=63 loops=1)
    -> Nested loop left join  (cost=8.37 rows=2.13) (actual time=0.172..3.26 rows=63 loops=1)
        -> Nested loop left join  (cost=6.22 rows=0.208) (actual time=0.153..2.77 rows=63 loops=1)
            -> Nested loop left join  (cost=6.06 rows=0.208) (actual time=0.151..2.75 rows=63 loops=1)
                -> Nested loop left join  (cost=5.92 rows=0.0991) (actual time=0.123..0.626 rows=21 loops=1)
                    -> Nested loop inner join  (cost=5.86 rows=0.07) (actual time=0.0448..0.065 rows=7 loops=1)
                        -> Nested loop inner join  (cost=5.61 rows=0.7) (actual time=0.0398..0.0569 rows=7 loops=1)
                            -> Filter: ((table1.id in ('52','48','58','201','59','45','54')) and (table1.cd1 is not null) and (table1.cd2 is not null))  (cost=3.16 rows=7) (actual time=0.0248..0.0383 rows=7 loops=1)
                                -> Index range scan on table1 using PRIMARY over (id = 45) OR (id = 48) OR (5 more)  (cost=3.16 rows=7) (actual time=0.0231..0.0311 rows=7 loops=1)
                            -> Filter: (table2.flag1 = '1')  (cost=0.251 rows=0.1) (actual time=0.0023..0.00235 rows=1 loops=7)
                                -> Single-row index lookup on table2 using cd1 (cd1=table1.cd1)  (cost=0.251 rows=1) (actual time=0.00199..0.002 rows=1 loops=7)
                        -> Filter: (table3.flag1 = '1')  (cost=0.264 rows=0.1) (actual time=902e-6..995e-6 rows=1 loops=7)
                            -> Single-row index lookup on table3 using cd3 (cd3=table1.cd3)  (cost=0.264 rows=1) (actual time=762e-6..789e-6 rows=1 loops=7)
                    -> Filter: ((table4.type = '1') and (table4.date <= table1.date) and (table4.date = (select #2)))  (cost=2.8 rows=1.42) (actual time=0.0509..0.0798 rows=3 loops=7)
                        -> Index lookup on table4 using table5_idx2 (id3=table1.id3, date=(select #2))  (cost=2.8 rows=1.42) (actual time=0.0367..0.0376 rows=3 loops=7)
                        -> Select #2 (subquery in condition; dependent)
                            -> Aggregate: max(table7.date)  (cost=1.17 rows=1) (actual time=0.0134..0.0134 rows=1 loops=35)
                                -> Filter: (table7.type = '1')  (cost=1.16 rows=0.0699) (actual time=0.00638..0.0121 rows=4 loops=35)
                                    -> Index lookup on table7 using table5_idx1 (id3=table1.id3), with index condition: (table7.date <= table1.date)  (cost=1.16 rows=2.1) (actual time=0.00624..0.0116 rows=6.43 loops=35)
                -> Filter: ((table6.type = '2') and (table6.date >= table1.date) and (table6.date = (select #3)))  (cost=3.27 rows=2.1) (actual time=0.0216..0.101 rows=3 loops=21)
                    -> Index lookup on table6 using table5_idx1 (id3=table1.id3)  (cost=3.27 rows=2.1) (actual time=0.00552..0.0129 rows=10 loops=21)
                    -> Select #3 (subquery in condition; dependent)
                        -> Aggregate: min(table8.date)  (cost=1.17 rows=1) (actual time=0.0138..0.0138 rows=1 loops=126)
                            -> Filter: (table8.type = '2')  (cost=1.16 rows=0.0699) (actual time=0.00603..0.0124 rows=6 loops=126)
                                -> Index lookup on table8 using table5_idx1 (id3=table1.id3), with index condition: (table8.date >= table1.date)  (cost=1.16 rows=2.1) (actual time=0.00577..0.0118 rows=7.71 loops=126)
            -> Single-row index lookup on table9 using no (no=table6.data)  (cost=1.19 rows=1) (actual time=89.6e-6..89.6e-6 rows=0 loops=63)
        -> Filter: (table10.type = '1')  (cost=14.2 rows=10.2) (actual time=0.00681..0.00772 rows=1 loops=63)
            -> Index lookup on table10 using table10_idx1 (id3=table10.id3)  (cost=14.2 rows=10.2) (actual time=0.00667..0.00735 rows=5 loops=63)
    -> Index lookup on table11 using id4 (id4=table11.id4)  (cost=0.797 rows=1) (actual time=0.00203..0.00231 rows=1 loops=63)

1 row in set, 4 warnings (0.007 sec)

何回 JOIN してるんだよ！っていう感じではありますが、わざと複雑なクエリを用意しました。
EXPLAIN で見慣れていると EXPLAIN ANALYZE の出力は少し見辛いなと感じるかも知れませんが、この出力には、クエリのパフォーマンス改善に役立つ情報がたくさん詰まっているんです！

都合よく LEFT JOIN と INNER JOIN が混在しているクエリがあったわけですが、 MySQL の Nested Loop Join の仕組みに照らし合わせると、 LEFT JOIN したテーブルのレコードがループの外側に、 INNER JOIN したテーブルのレコードをループの内側に配置して、結合していく様がわかりますね。

実はこのクエリ、 INNER JOIN と LEFT JOIN の順序がばらばらになっているんですが、そこはオプティマイザがしっかり仕事をしていて、処理順はちゃんと LEFT JOIN したテーブルからになっています。

各処理ごとに cost や rows 、actual time 、 loops といった情報が表示されていますが、実際のデータを処理した際にかかった時間（acutual time）や処理された行数（rows）が見られるので、クエリのどの部分がボトルネックになっているのかを特定することができます。

それぞれの値の見方は以下の通りです。

左側のカッコ内の数字

• cost: クエリオプティマイザが見積もったコスト
• rows: オプティマイザが見積もった行数

右側のカッコ内の数字

• actual time: 実際にかかった時間。「..」の左が最初の行が返されるまでの時間、右が最後の行が返されるまでの時間
• rows: 実際に処理された行数
• loops: この処理が実行された回数

例として一番最初の Nested loop left join の行を見てみると、 (cost=10.2 rows=2.13) (actual time=0.192..3.42 rows=63 loops=1) と書かれています。

これは、クエリオプティマイザは cost=10.2 なので、この処理のコストを 10.2 と見積もっていて、 rows=2.13 なので 2.13 行処理されるだろう、と予測したということになります。
それに対して、 actual time=0.192..3.42 なので、最初の行が返されるまでに 0.192 ミリ秒かかり、最後の行が返されるまでに 3.42 ミリ秒かかったということになります。
一番外側の最後の行を処理した時間は、クエリ全体の実行時間とほぼ同じと捉えていいですが、この後の処理として、結果をネットワーク経由で返す時間はこの時間に含まれていません。
EXPLAIN ANALYZE の結果は良好なのにクエリの実行時間が長いなと感じる場合は、ネットワーク経由で返す時間が長い可能性もある、ということになります。

さらに、 rows=63 なので実際には 63 行処理されていますが、オプティマイザの予測は 2.13 行だったので、実際には予測よりも多くの行が処理されていることになります。
これはオプティマイザの統計情報が古い可能性があるので、 ANALYZE TABLE を実行して統計情報を更新してみるとよいでしょう。

ちなみに今回の EXPLAIN ANALYZE は手元のローカル環境で実行したもので、データ数が多くありません。
なのでこの結果だけを見るとめっちゃ速いじゃん！って思うかも知れませんが、本番環境と同程度のデータ数を用意しないと正確な情報は得られないので、注意してください。

単純なインデックスの確認だと、 EXPLAIN の方が情報量が少ないので見やすいですが、思ったようにインデックスが効かないな、といったクエリのパフォーマンス改善をする際には、 EXPLAIN ANALYZE を使用して、実際のクエリの実行時間や処理された行数などの詳細な情報を確認すると、すっきり解決することもあると思います。

まとめ

今回は MySQL 8 系で新しく追加された EXPLAIN ANALYZE を使ったクエリ改善の方法を紹介しました。

新しくといってもEXPLAIN ANALYZE が追加された MySQL 8.0.18 のリリースは2019年なので、全然新しくもなんともないんですが、クエリ改善するぜっていうときに EXPLAIN だけ見て結局分からない、みたいなパターンで諦めてしまう人がまだまだいるみたいなので、改めて記事にしました。

事前にアプリケーションの仕様がはっきりしておらず、開発しながら後付けでカラムを追加したりしていると、インデックスが有効に機能しないクエリが実行されていたり、無理な JOIN をしてデータを何とか取ってきているクエリがあったりすることもあると思います。

そういったクエリのチューニングの際に、 EXPLAIN ANALYZE を使用してみてはいかがでしょうか、というお話でした。

以上です。