MySQL 8.0.32 / explain analyze 実行途中でキャンセルできるみたいだけど、キャンセルしたら、Actual Plan、途中まで出るの？ Tweet
本年度一発目のw Databaseネタは、なんと、MySQLネタからのスタートですw
MySQL 8.0.18以降、Actualプランが取得できるようになってた。
また、MySQL 8.0.20 以降、KILL QUERY または CTRL-C を使用してこのステートメントを終了できるとある。
ただ、マニュアルに記載されているのはここまでで、キャンセルできることは記載されているが、キャンセルした場合のActual Planはどこまで出力されるのだろう？ or 全く出力されない？
OracleのリアルタイムSQL監視だとキャンセルすると不完全ではあるけども、なんとなーく判断できる程度の情報は途中まで取得できるが、
GATHER_PLAN_STATISTICSヒントなどを使ったActualプランは最後まで実行しないとアcつあlはしゅとくできない。どちらのタイプに似ているのでしょうね？
長時間（数日とかw）かかってしまうようになったSQLのActualプラン取得するの意外と難しいケースも場合によってはあったりするわけで。。。そんなとき、Actualみたいけど、キャンセルしたらどうなるのだろうと。。
途中まででも取得できるのか、それとも、Nothingなのか。。。
MySQLのActualプランの取得はどうなんだろう。。。ということで、試してみた。
EXPLAIN ANALYZE による情報の取得
https://dev.mysql.com/doc/refman/8.0/ja/explain.html#explain-analyze
結論から書くと、
MySQL 8.0.32での検証だが、
explain analyzeで取得できるActual Planは、対応しているSQL文の実行中にCTRL-Cでキャンセルしても、その時点までの、Actual Planを表示してくれる!!!!!!
ただし、パース時間が異常に長めのSQL文(結合数めちゃ多いとか）だと、実行以前に、パース時間が長いため、パースフェーズでキャンセルしてしまうの何も表示されない。。と（最初はこちらを引いてしまったので、常に表示されないものかと思い込んでしまった）
他の方法で実行をキャンセルした場合も同じだろう。とは思う。
いや、他にも出力されないケースがあるとか、その検証方法だから出力されているだけどか、MySQLのexplain analyzeのディープなツッコミがありましたら、よろしくお願いします。:)
MySQLの8.0台ってマイナー番号変わっても機能追加されたり変化しているので、一応。 MySQL 8.0.32 上では。ということにしておく。
以下、検証の記録的なもの。
確認に使用した MySQLのバージョン
[master@localhost ~]$ mysql -u scott -p
Enter password:
Welcome to the MySQL monitor. Commands end with ; or \g.
Your MySQL connection id is 8
Server version: 8.0.32 Source distribution
Copyright (c) 2000, 2023, Oracle and/or its affiliates.
Oracle is a registered trademark of Oracle Corporation and/or its
affiliates. Other names may be trademarks of their respective
owners.
Type 'help;' or '\h' for help. Type '\c' to clear the current input statement.
mysql> select version();
+-----------+
| version() |
+-----------+
| 8.0.32 |
+-----------+
1 row in set (0.00 sec)
事前に準備したクエリ向け表と索引など
Database changed
mysql> use perftestdb
Reading table information for completion of table and column names
You can turn off this feature to get a quicker startup with -A
Database changed
mysql>
mysql> desc master;
+--------+-------------+------+-----+---------+-------+
| Field | Type | Null | Key | Default | Extra |
+--------+-------------+------+-----+---------+-------+
| id | int | NO | PRI | NULL | |
| dummya | varchar(10) | YES | | NULL | |
+--------+-------------+------+-----+---------+-------+
2 rows in set (0.01 sec)
mysql> desc detail;
+--------+-------------+------+-----+---------+-------+
| Field | Type | Null | Key | Default | Extra |
+--------+-------------+------+-----+---------+-------+
| id | int | NO | PRI | NULL | |
| subid | int | NO | PRI | NULL | |
| dummya | varchar(10) | YES | | NULL | |
+--------+-------------+------+-----+---------+-------+
3 rows in set (0.00 sec)
mysql> show indexes from master;
+--------+------------+----------+--------------+-------------+------------+
| Table | Non_unique | Key_name | Seq_in_index | Column_name | Index_type |
+--------+------------+----------+--------------+-------------+------------+
| master | 0 | PRIMARY | 1 | id | BTREE |
+--------+------------+----------+--------------+-------------+------------+
1 row in set (0.02 sec)
mysql> show indexes from detail;
+--------+------------+----------+--------------+-------------+------------+
| Table | Non_unique | Key_name | Seq_in_index | Column_name | Index_type |
+--------+------------+----------+--------------+-------------+------------+
| detail | 0 | PRIMARY | 1 | id | BTREE |
| detail | 0 | PRIMARY | 2 | subid | BTREE |
+--------+------------+----------+--------------+-------------+------------+
2 rows in set (0.02 sec)
mysql> select * from master;
+----+--------+
| id | dummya |
+----+--------+
| 1 | 1 |
| 2 | 2 |
| 3 | 3 |
| 4 | 4 |
| 5 | 5 |
| 6 | 6 |
| 7 | 7 |
| 8 | 8 |
| 9 | 9 |
| 10 | 10 |
+----+--------+
10 rows in set (0.01 sec)
mysql> select * from detail;
+----+-------+--------+
| id | subid | dummya |
+----+-------+--------+
| 1 | 1 | 11 |
| 1 | 2 | 12 |
| 2 | 1 | 21 |
| 2 | 2 | 22 |
| 3 | 1 | 31 |
...略...
| 7 | 1 | 71 |
| 7 | 2 | 72 |
| 8 | 1 | 81 |
| 8 | 2 | 82 |
| 9 | 1 | 91 |
| 9 | 2 | 92 |
| 10 | 1 | 101 |
| 10 | 2 | 102 |
+----+-------+--------+
20 rows in set (0.01 sec)
検証用に作ったSQL。どのぐらいのElapsed Timeかanaluyzeをつけて実行して、キャンセルしやすい程度のElapsed Timeか確認しておきます。
mysql> explain analyze
-> select *
-> from
-> master inner join detail
-> on master.id = detail.id
-> inner join detail t2
-> on
-> t2.id = detail.id
-> inner join detail t3
-> on
-> t3.id = t2.id
-> inner join detail t4
-> on
-> t4.id = t3.id
-> inner join detail t5
-> on
-> t5.id = t4.id
-> inner join detail t6
-> on
-> t6.id = t5.id
-> inner join detail t7
-> on
-> t7.id = t6.id
-> inner join detail t8
-> on
-> t8.id = t7.id
-> inner join detail t9
-> on
-> t9.id = t8.id
-> inner join detail t10
-> on
-> t10.id = t9.id
-> ;
+------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| EXPLAIN |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| -> Nested loop inner join (cost=5729.85 rows=8192) (actual time=0.115..37.938 rows=10240 loops=1)
-> Nested loop inner join (cost=2862.65 rows=4096) (actual time=0.108..18.747 rows=5120 loops=1)
-> Nested loop inner join (cost=1429.05 rows=2048) (actual time=0.102..9.267 rows=2560 loops=1)
-> Nested loop inner join (cost=712.25 rows=1024) (actual time=0.097..4.689 rows=1280 loops=1)
-> Nested loop inner join (cost=353.85 rows=512) (actual time=0.091..2.336 rows=640 loops=1)
-> Nested loop inner join (cost=174.65 rows=256) (actual time=0.086..1.203 rows=320 loops=1)
-> Nested loop inner join (cost=85.05 rows=128) (actual time=0.080..0.630 rows=160 loops=1)
-> Nested loop inner join (cost=40.25 rows=64) (actual time=0.075..0.337 rows=80 loops=1)
-> Nested loop inner join (cost=17.85 rows=32) (actual time=0.069..0.189 rows=40 loops=1)
-> Nested loop inner join (cost=6.65 rows=16) (actual time=0.063..0.110 rows=20 loops=1)
-> Table scan on master (cost=1.05 rows=8) (actual time=0.041..0.047 rows=10 loops=1)
-> Index lookup on detail using PRIMARY (id=`master`.id) (cost=0.53 rows=2) (actual time=0.005..0.006 rows=2 loops=10)
-> Index lookup on t2 using PRIMARY (id=`master`.id) (cost=0.51 rows=2) (actual time=0.003..0.004 rows=2 loops=20)
-> Index lookup on t3 using PRIMARY (id=`master`.id) (cost=0.51 rows=2) (actual time=0.002..0.003 rows=2 loops=40)
-> Index lookup on t4 using PRIMARY (id=`master`.id) (cost=0.50 rows=2) (actual time=0.002..0.003 rows=2 loops=80)
-> Index lookup on t5 using PRIMARY (id=`master`.id) (cost=0.50 rows=2) (actual time=0.002..0.003 rows=2 loops=160)
-> Index lookup on t6 using PRIMARY (id=`master`.id) (cost=0.50 rows=2) (actual time=0.002..0.003 rows=2 loops=320)
-> Index lookup on t7 using PRIMARY (id=`master`.id) (cost=0.50 rows=2) (actual time=0.002..0.003 rows=2 loops=640)
-> Index lookup on t8 using PRIMARY (id=`master`.id) (cost=0.50 rows=2) (actual time=0.002..0.003 rows=2 loops=1280)
-> Index lookup on t9 using PRIMARY (id=`master`.id) (cost=0.50 rows=2) (actual time=0.002..0.003 rows=2 loops=2560)
-> Index lookup on t10 using PRIMARY (id=`master`.id) (cost=0.50 rows=2) (actual time=0.002..0.003 rows=2 loops=5120)
|
+------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (21.18 sec)
では、explain analyseを途中でキャンセルしてみます。elapsed timeが21秒ほどなので、20秒後にキャンセルしてみます。
mysql> explain analyze
select *
from
master inner join detail
on master.id = detail.id
inner join detail t2
on t2.id = master.id
inner join detail t3
on t3.id = master.id
inner join detail t4
on t4.id = master.id
inner join detail t5
on t5.id = master.id
inner join detail t6
on t6.id = master.id
inner join detail t7
on t7.id = master.id
inner join detail t8
on t8.id = master.id
inner join detail t9
on t9.id = master.id
inner join detail t10
on t10.id = master.id
;
^C^C -- query aborted
ERROR 1317 (70100): Query execution was interrupted
mysql>
！ やはり、実行途中のキャンセルだとActual Planは何も出力されないみたい。。。。
？？ん？ いや、なんか違うな。これw！
SQL文の実行時間はたいしたことない。人間がこの時間内にピンポイントでキャンセルするには短すぎるよね。
SQL文の実行時間は、約38ミリ秒！！！ こっちだw 最終に表示されている21秒には、SQLのパース時間も含まれているはず。。。。見逃した。俺としたことが。。。
| -> Nested loop inner join (cost=5729.85 rows=8192) (actual time=0.115..37.938 rows=10240 loops=1)
キャンセルしたのは、SQL実行後、おおよそ、20秒後。SQLのActualタイムを見ると38ミリ秒なので、ギリギリ、パース時間中に被ってそう。
1 row in set (21.00 sec)
だとしたら、まず、そこから確認。パースにどの程度要しているか、explainだけにすれば、良さそうだよね。Oracle Databaseでもそうだし。(PostgreSQLはパース時間も表示してくれたりするけども。あれ意外に便利なんだよ）
mysql> explain format=tree -> select *
-> from
-> master inner join detail
-> on master.id = detail.id
-> inner join detail t2
-> on
-> t2.id = detail.id
-> inner join detail t3
-> on
-> t3.id = t2.id
-> inner join detail t4
-> on
-> t4.id = t3.id
-> inner join detail t5
-> on
-> t5.id = t4.id
-> inner join detail t6
-> on
-> t6.id = t5.id
-> inner join detail t7
-> on
-> t7.id = t6.id
-> inner join detail t8
-> on
-> t8.id = t7.id
-> inner join detail t9
-> on
-> t9.id = t8.id
-> inner join detail t10
-> on
-> t10.id = t9.id
-> ;
+------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| EXPLAIN |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| -> Nested loop inner join (cost=5729.85 rows=8192)
-> Nested loop inner join (cost=2862.65 rows=4096)
-> Nested loop inner join (cost=1429.05 rows=2048)
-> Nested loop inner join (cost=712.25 rows=1024)
-> Nested loop inner join (cost=353.85 rows=512)
-> Nested loop inner join (cost=174.65 rows=256)
-> Nested loop inner join (cost=85.05 rows=128)
-> Nested loop inner join (cost=40.25 rows=64)
-> Nested loop inner join (cost=17.85 rows=32)
-> Nested loop inner join (cost=6.65 rows=16)
-> Table scan on master (cost=1.05 rows=8)
-> Index lookup on detail using PRIMARY (id=`master`.id) (cost=0.53 rows=2)
-> Index lookup on t2 using PRIMARY (id=`master`.id) (cost=0.51 rows=2)
-> Index lookup on t3 using PRIMARY (id=`master`.id) (cost=0.51 rows=2)
-> Index lookup on t4 using PRIMARY (id=`master`.id) (cost=0.50 rows=2)
-> Index lookup on t5 using PRIMARY (id=`master`.id) (cost=0.50 rows=2)
-> Index lookup on t6 using PRIMARY (id=`master`.id) (cost=0.50 rows=2)
-> Index lookup on t7 using PRIMARY (id=`master`.id) (cost=0.50 rows=2)
-> Index lookup on t8 using PRIMARY (id=`master`.id) (cost=0.50 rows=2)
-> Index lookup on t9 using PRIMARY (id=`master`.id) (cost=0.50 rows=2)
-> Index lookup on t10 using PRIMARY (id=`master`.id) (cost=0.50 rows=2)
|
+------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (21.84 sec)
お！ 予想通り、explainでパースだけさせたら、explain analyze（SQL文の実行を含む）とほぼ同じ 21秒台。想定は正しそう。
だとすると、今回確認したいことを実現するには、..... SQLの実行時間をもっと長くして、人がw キャンセルしやすい程度に実行時間を間延びさせておく必要がある。。
とはいえ、大量のデータを用意する時間もVMのストレージもないと。。。
さて、どうするか。。。。
***** ここで、 一休さん、考え中。。。 木魚の音。ポク、ポク、ポク。。。。w *****
***** ここで、 一休さん、閃いた。。。 鐘の音、チーーーーーん *****
sleep()関数を使って、眠らせると時間稼ぎできるのでは？ やってみよう！
おおおおお、いい感じだ。
mysql> explain analyze
-> select *, sleep(0.01)
-> from
-> master inner join detail
-> on master.id = detail.id
-> inner join detail t2
-> on
-> t2.id = detail.id
-> inner join detail t3
-> on
-> t3.id = t2.id
-> inner join detail t4
-> on
-> t4.id = t3.id
-> inner join detail t5
-> on
-> t5.id = t4.id
-> inner join detail t6
-> on
-> t6.id = t5.id
-> inner join detail t7
-> on
-> t7.id = t6.id
-> inner join detail t8
-> on
-> t8.id = t7.id
-> inner join detail t9
-> on
-> t9.id = t8.id
-> inner join detail t10
-> on
-> t10.id = t9.id
-> ;
+------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| EXPLAIN |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| -> Nested loop inner join (cost=5729.85 rows=8192) (actual time=0.170..232.399 rows=10240 loops=1)
-> Nested loop inner join (cost=2862.65 rows=4096) (actual time=0.164..75.457 rows=5120 loops=1)
-> Nested loop inner join (cost=1429.05 rows=2048) (actual time=0.159..37.659 rows=2560 loops=1)
-> Nested loop inner join (cost=712.25 rows=1024) (actual time=0.154..17.709 rows=1280 loops=1)
-> Nested loop inner join (cost=353.85 rows=512) (actual time=0.149..9.612 rows=640 loops=1)
-> Nested loop inner join (cost=174.65 rows=256) (actual time=0.143..4.658 rows=320 loops=1)
-> Nested loop inner join (cost=85.05 rows=128) (actual time=0.138..2.285 rows=160 loops=1)
-> Nested loop inner join (cost=40.25 rows=64) (actual time=0.132..1.174 rows=80 loops=1)
-> Nested loop inner join (cost=17.85 rows=32) (actual time=0.126..0.625 rows=40 loops=1)
-> Nested loop inner join (cost=6.65 rows=16) (actual time=0.120..0.347 rows=20 loops=1)
-> Table scan on master (cost=1.05 rows=8) (actual time=0.097..0.122 rows=10 loops=1)
-> Index lookup on detail using PRIMARY (id=`master`.id) (cost=0.53 rows=2) (actual time=0.017..0.021 rows=2 loops=10)
-> Index lookup on t2 using PRIMARY (id=`master`.id) (cost=0.51 rows=2) (actual time=0.010..0.013 rows=2 loops=20)
-> Index lookup on t3 using PRIMARY (id=`master`.id) (cost=0.51 rows=2) (actual time=0.010..0.013 rows=2 loops=40)
-> Index lookup on t4 using PRIMARY (id=`master`.id) (cost=0.50 rows=2) (actual time=0.010..0.013 rows=2 loops=80)
-> Index lookup on t5 using PRIMARY (id=`master`.id) (cost=0.50 rows=2) (actual time=0.010..0.014 rows=2 loops=160)
-> Index lookup on t6 using PRIMARY (id=`master`.id) (cost=0.50 rows=2) (actual time=0.011..0.015 rows=2 loops=320)
-> Index lookup on t7 using PRIMARY (id=`master`.id) (cost=0.50 rows=2) (actual time=0.009..0.012 rows=2 loops=640)
-> Index lookup on t8 using PRIMARY (id=`master`.id) (cost=0.50 rows=2) (actual time=0.011..0.015 rows=2 loops=1280)
-> Index lookup on t9 using PRIMARY (id=`master`.id) (cost=0.50 rows=2) (actual time=0.010..0.014 rows=2 loops=2560)
-> Index lookup on t10 using PRIMARY (id=`master`.id) (cost=0.50 rows=2) (actual time=0.010..0.028 rows=2 loops=5120)
|
+------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (2 min 47.64 sec)
Elapsed Timeがパース時間より長くなったので、できそう。 60秒後にキャンセルすれば余裕はありそう。
1 row in set (2 min 47.64 sec)
explain analyzeを実行して、60秒後にキャンセルした！
mysql> explain analyze
-> select *, sleep(0.01)
-> from
-> master inner join detail
-> on master.id = detail.id
-> inner join detail t2
-> on
-> t2.id = detail.id
-> inner join detail t3
-> on
-> t3.id = t2.id
-> inner join detail t4
-> on
-> t4.id = t3.id
-> inner join detail t5
-> on
-> t5.id = t4.id
-> inner join detail t6
-> on
-> t6.id = t5.id
-> inner join detail t7
-> on
-> t7.id = t6.id
-> inner join detail t8
-> on
-> t8.id = t7.id
-> inner join detail t9
-> on
-> t9.id = t8.id
-> inner join detail t10
-> on
-> t10.id = t9.id
-> ;
^C^C -- query aborted
+------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| EXPLAIN |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| -> Nested loop inner join (cost=5729.85 rows=8192) (actual time=0.113..92.382 rows=2639 loops=1)
-> Nested loop inner join (cost=2862.65 rows=4096) (actual time=0.106..29.480 rows=1320 loops=1)
-> Nested loop inner join (cost=1429.05 rows=2048) (actual time=0.101..14.323 rows=660 loops=1)
-> Nested loop inner join (cost=712.25 rows=1024) (actual time=0.096..7.161 rows=330 loops=1)
-> Nested loop inner join (cost=353.85 rows=512) (actual time=0.090..3.507 rows=165 loops=1)
-> Nested loop inner join (cost=174.65 rows=256) (actual time=0.085..1.624 rows=83 loops=1)
-> Nested loop inner join (cost=85.05 rows=128) (actual time=0.079..0.867 rows=42 loops=1)
-> Nested loop inner join (cost=40.25 rows=64) (actual time=0.073..0.352 rows=21 loops=1)
-> Nested loop inner join (cost=17.85 rows=32) (actual time=0.068..0.210 rows=11 loops=1)
-> Nested loop inner join (cost=6.65 rows=16) (actual time=0.062..0.122 rows=6 loops=1)
-> Table scan on master (cost=1.05 rows=8) (actual time=0.040..0.044 rows=3 loops=1)
-> Index lookup on detail using PRIMARY (id=`master`.id) (cost=0.53 rows=2) (actual time=0.021..0.024 rows=2 loops=3)
-> Index lookup on t2 using PRIMARY (id=`master`.id) (cost=0.51 rows=2) (actual time=0.011..0.014 rows=2 loops=6)
-> Index lookup on t3 using PRIMARY (id=`master`.id) (cost=0.51 rows=2) (actual time=0.009..0.012 rows=2 loops=11)
-> Index lookup on t4 using PRIMARY (id=`master`.id) (cost=0.50 rows=2) (actual time=0.020..0.024 rows=2 loops=21)
-> Index lookup on t5 using PRIMARY (id=`master`.id) (cost=0.50 rows=2) (actual time=0.014..0.017 rows=2 loops=42)
-> Index lookup on t6 using PRIMARY (id=`master`.id) (cost=0.50 rows=2) (actual time=0.015..0.022 rows=2 loops=83)
-> Index lookup on t7 using PRIMARY (id=`master`.id) (cost=0.50 rows=2) (actual time=0.014..0.021 rows=2 loops=165)
-> Index lookup on t8 using PRIMARY (id=`master`.id) (cost=0.50 rows=2) (actual time=0.016..0.021 rows=2 loops=330)
-> Index lookup on t9 using PRIMARY (id=`master`.id) (cost=0.50 rows=2) (actual time=0.015..0.022 rows=2 loops=660)
-> Index lookup on t10 using PRIMARY (id=`master`.id) (cost=0.50 rows=2) (actual time=0.015..0.044 rows=2 loops=1320)
|
+------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set, 1 warning (1 min 3.57 sec)
SQLのActualタイムは、92ミリ秒、処理した行数が、2629行。
| -> Nested loop inner join (cost=5729.85 rows=8192) (actual time=0.113..92.382 rows=2639 loops=1)
以下を見ると、loopsが、1320回となっている。
-> Index lookup on t10 using PRIMARY (id=`master`.id) (cost=0.50 rows=2) (actual time=0.015..0.044 rows=2 loops=1320)
やった〜〜〜。 MySQLの explain analyzeは、"SQLの実行途中"(パース時間が長い割に、実行時間が短い場合は、実行中にキャンセルするのが難しいので表示されないケースはあるので注意）でキャンセルしても、途中までのActual Planを返してくれる！
念の為、sleep()関数を使ったトリッキーな再現方法ではなく、実際にSQLの実行中にキャンセルする方法を思いついたので、さらに、試してみる！
お分かりだろうか。 みなさん大好き（？）、 再起問い合わせ再帰問合せでシーケンス番号を生成するクエリーだ。100000000ぐらい生成すれば、いい感じの実行時間になるだろうと、思われるので、まず、このSQLのパース時間だけ確認。
mysql> SET SESSION cte_max_recursion_depth = 100000000;
Query OK, 0 rows affected (0.00 sec)
パース時間はほぼかかってないですね。先ほどの例は、結合する表が多いので、パース時間は長くなる傾向があるので、シンプルなSQLだけど、実行時間は、なげ〜〜〜〜ぞ〜というのにしてみた。
mysql> explain format=tree
-> WITH RECURSIVE gen_nums(v)
-> AS
-> (
-> SELECT 1
-> UNION ALL
-> SELECT v + 1
-> FROM
-> gen_nums
-> WHERE v + 1 <= 100000000
-> )
-> SELECT v from gen_nums;
+------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| EXPLAIN |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| -> Table scan on gen_nums (cost=3.87..5.56 rows=3)
-> Materialize recursive CTE gen_nums (cost=3.03..3.03 rows=3)
-> Rows fetched before execution (cost=0.00..0.00 rows=1)
-> Repeat until convergence
-> Filter: ((gen_nums.v + 1) <= 100000000) (cost=2.73 rows=2)
-> Scan new records on gen_nums (cost=2.73 rows=2)
|
+------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)
explain analyzeの実時間を確認
mysql> explain analyze
-> WITH RECURSIVE gen_nums(v)
-> AS
-> (
-> SELECT 1
-> UNION ALL
-> SELECT v + 1
-> FROM
-> gen_nums
-> WHERE v + 1 <= 100000000
-> )
-> SELECT v from gen_nums;
+------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| EXPLAIN |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| -> Table scan on gen_nums (cost=3.87..5.56 rows=3) (actual time=139082.095..178091.268 rows=100000000 loops=1)
-> Materialize recursive CTE gen_nums (cost=3.03..3.03 rows=3) (actual time=139081.959..139081.959 rows=100000000 loops=1)
-> Rows fetched before execution (cost=0.00..0.00 rows=1) (actual time=0.000..0.000 rows=1 loops=1)
-> Repeat until convergence
-> Filter: ((gen_nums.v + 1) <= 100000000) (cost=2.73 rows=2) (actual time=0.003..29453.367 rows=50000000 loops=2)
-> Scan new records on gen_nums (cost=2.73 rows=2) (actual time=0.002..21852.139 rows=50000000 loops=2)
|
+------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set (3 min 8.46 sec)
Actual timeは、178秒なので、60秒後にキャンセルすればよさそうですね。
| -> Table scan on gen_nums (cost=3.87..5.56 rows=3) (actual time=139082.095..178091.268 rows=100000000 loops=1)
では、キャンセルでどうなるか検証！！
mysql> explain analyze
-> WITH RECURSIVE gen_nums(v)
-> AS
-> (
-> SELECT 1
-> UNION ALL
-> SELECT v + 1
-> FROM
-> gen_nums
-> WHERE v + 1 <= 100000000
-> )
-> SELECT v from gen_nums;
^C^C -- query aborted
+------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| EXPLAIN |
+------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| -> Table scan on gen_nums (cost=3.87..5.56 rows=3) (never executed)
-> Materialize recursive CTE gen_nums (cost=3.03..3.03 rows=3) (never executed)
-> Rows fetched before execution (cost=0.00..0.00 rows=1) (actual time=0.000..0.000 rows=1 loops=1)
-> Repeat until convergence
-> Filter: ((gen_nums.v + 1) <= 100000000) (cost=2.73 rows=2) (actual time=0.004..27789.355 rows=47924088 loops=1)
-> Scan new records on gen_nums (cost=2.73 rows=2) (actual time=0.002..20555.788 rows=47924088 loops=1)
|
+------------------------------------------------------------------------------------------------------------------------------------------------------------------+
1 row in set, 1 warning (1 min 3.94 sec)
60行でキャンセルしたので、ほぼ同じ。
1 row in set, 1 warning (1 min 3.94 sec
以下の行ソースを見ると、Actual timeが21秒ほど、rowsも47924088行。
-> Scan new records on gen_nums (cost=2.73 rows=2) (actual time=0.002..20555.788 rows=47924088 loops=1)
興味深い部分は、以下の2行の行ソース。never execute と表示されている。
| -> Table scan on gen_nums (cost=3.87..5.56 rows=3) (never executed)
-> Materialize recursive CTE gen_nums (cost=3.03..3.03 rows=3) (never executed)
¥
これを見る限り、MySQLのexplain analyzeは、SQL文の実行フェース中にキャンセルすると、その時点までの Actual Planを出力してくれる。これ、結構嬉しいよね。長時間実行で、仕方なくキャンセルするにしても途中の状態。運が良ければ、詰まっている部分が見えるかもしれないわけで。。。
いや、他にも出力されないケースがあるとか、その検証方法だから出力されているだけどか、MySQLのexplain analyzeのディープなツッコミがありましたら、よろしくお願いします。:) (大事なので、2度書いておくw）
以上、explain analyze のブラックボックステスト。 実行途中でキャンセルできるみたいだけど、キャンセルしたら、Actual Plan、途中まで出るの？ の巻。終わり。
似てるようで、似てない。それぞれのRDBMSの世界w。 ではまた。
参考）
EXPLAIN ANALYZE による情報の取得
https://dev.mysql.com/doc/refman/8.0/ja/explain.html#explain-analyze
| 固定リンク | 0
コメント