TL;DR

日々の覚書: MySQL標準のEXPLAIN(format=TRADITIONAL)とEXPLAIN format=TREEを並べて見つめてみるで言ってたやつは、過去の記憶(?)だった

t3を含んだサブクエリ (SELECT SUBSTRING(val, 1, 1) AS f, SUM(num) FROM t3 GROUP BY f) AS tmp_t3 が最初に処理

5.6とそれ以降はDelayed Materializationによりt3を含んだサブクエリが最後に実行されていた
- これはEXPLAINだけでは読み切れなさそうな予感
- MySQL :: MySQL 5.6 Release Notes :: Changes in MySQL 5.6.3 (2011-10-03, Milestone 6)

まず、テーブルを開く順番。これはメタデータロックの順番でもある。

(全部InnoDBなので) ha_innobase::open にブレークポイントを仕掛けて

$ gdb -p $(pidof mysqld)
(gdb) b ha_innobase::open
+b ha_innobase::open
Breakpoint 1 at 0xc2de7e: ha_innobase::open. (2 locations)
(gdb) c
+c
Continuing.

FLUSH TABLES してテーブルキャッシュを吹っ飛ばしてから実行。
クエリは前回のと一緒。

mysql80 8> FLUSH TABLES;
Query OK, 0 rows affected (0.01 sec)

mysql80 8> SELECT * FROM t1, t2, (SELECT SUBSTRING(val, 1, 1) AS f, SUM(num) FROM t3 GROUP BY f) AS tmp_t3 WHERE t1.num IN (SELECT num FROM t5 WHERE num = (SELECT MAX(num) FROM t4) AND val LIKE '%');

起動直後だとデータディクショナリにアクセスするタイミングで1回目のブレークが来るけど取り敢えず次へ。

(gdb) bt
+bt
#0  ha_innobase::open(char const*, int, unsigned int, dd::Table const*) () at /home/yoku0825/mysql-8.0.28/storage/innobase/handler/ha_innodb.cc:6995
#1  0x0000000000ff7775 in handler::ha_open (this=0x7efa9c045a40, table_arg=table_arg@entry=0x7efa9c0450c0, name=0x7efa9c03faf0 "./mysql/check_constraints", mode=mode@entry=2, test_if_locked=2, table_def=0x7f0b4716f7d0)
    at /home/yoku0825/mysql-8.0.28/sql/handler.cc:2812
#2  0x0000000000eac9f2 in open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool, dd::Table const*) () at /home/yoku0825/mysql-8.0.28/sql/table.cc:3175
#3  0x0000000000d08c5f in open_table(THD*, TABLE_LIST*, Open_table_context*) () at /home/yoku0825/mysql-8.0.28/sql/sql_base.cc:3367
#4  0x0000000000d0a298 in open_and_process_table (ot_ctx=0x7f0b40128be0, has_prelocking_list=false, prelocking_strategy=0x7f0b40128c70, counter=0x7f0b40128c64, tables=0x7efa9c03e118, lex=<optimized out>, thd=0x7efa9c000d20)
    at /home/yoku0825/mysql-8.0.28/sql/sql_base.cc:5034
#5  open_tables (thd=0x7efa9c000d20, start=start@entry=0x7f0b40128c68, counter=counter@entry=0x7f0b40128c64, flags=flags@entry=18434, prelocking_strategy=prelocking_strategy@entry=0x7f0b40128c70)
    at /home/yoku0825/mysql-8.0.28/sql/sql_base.cc:5842
#6  0x0000000001fb2af0 in open_tables (flags=18434, counter=0x7f0b40128c64, tables=0x7f0b40128c68, thd=<optimized out>) at /home/yoku0825/mysql-8.0.28/sql/sql_base.h:455
#7  dd::Open_dictionary_tables_ctx::open_tables (this=this@entry=0x7f0b40128ce0) at /home/yoku0825/mysql-8.0.28/sql/dd/impl/transaction_impl.cc:107
#8  0x0000000001e2638c in dd::cache::Storage_adapter::get<dd::Item_name_key, dd::Abstract_table> (thd=thd@entry=0x7efa9c000d20, key=
      @0x7f0b40128ee0: {<dd::Object_key> = {_vptr.Object_key = 0x39499c0 <vtable for dd::Item_name_key+16>}, m_container_id_column_no = 1, m_name_column_no = 2, m_container_id = 6, m_object_name = "t1", m_cs = 0x3b80160 <my_charset_utf8_tolower_ci>}, isolation=isolation@entry=ISO_READ_COMMITTED, bypass_core_registry=bypass_core_registry@entry=false, object=object@entry=0x7f0b40128da0) at /home/yoku0825/mysql-8.0.28/sql/dd/impl/transaction_impl.h:90
#9  0x0000000001e1581f in dd::cache::Shared_dictionary_cache::get_uncached<dd::Item_name_key, dd::Abstract_table> (this=this@entry=0x3db4700 <dd::cache::Shared_dictionary_cache::instance()::s_cache>, thd=thd@entry=0x7efa9c000d20,
    key=
      @0x7f0b40128ee0: {<dd::Object_key> = {_vptr.Object_key = 0x39499c0 <vtable for dd::Item_name_key+16>}, m_container_id_column_no = 1, m_name_column_no = 2, m_container_id = 6, m_object_name = "t1", m_cs = 0x3b80160 <my_charset_utf8_tolower_ci>}, isolation=isolation@entry=ISO_READ_COMMITTED, object=object@entry=0x7f0b40128da0) at /home/yoku0825/mysql-8.0.28/sql/dd/impl/cache/shared_dictionary_cache.cc:109
#10 0x0000000001e1589f in dd::cache::Shared_dictionary_cache::get<dd::Item_name_key, dd::Abstract_table> (this=0x3db4700 <dd::cache::Shared_dictionary_cache::instance()::s_cache>, thd=0x7efa9c000d20, key=
      @0x7f0b40128ee0: {<dd::Object_key> = {_vptr.Object_key = 0x39499c0 <vtable for dd::Item_name_key+16>}, m_container_id_column_no = 1, m_name_column_no = 2, m_container_id = 6, m_object_name = "t1", m_cs = 0x3b80160 <my_charset_utf8_tolower_ci>}, element=element@entry=0x7f0b40128e38) at /home/yoku0825/mysql-8.0.28/sql/dd/impl/cache/shared_dictionary_cache.h:174
#11 0x0000000001dbdaa5 in dd::cache::Dictionary_client::acquire<dd::Item_name_key, dd::Abstract_table> (this=this@entry=0x7efa9c0044c0, key=
      @0x7f0b40128ee0: {<dd::Object_key> = {_vptr.Object_key = 0x39499c0 <vtable for dd::Item_name_key+16>}, m_container_id_column_no = 1, m_name_column_no = 2, m_container_id = 6, m_object_name = "t1", m_cs = 0x3b80160 <my_charset_utf8_tolower_ci>}, object=object@entry=0x7f0b40128ec8, local_committed=local_committed@entry=0x7f0b40128ebe, local_uncommitted=local_uncommitted@entry=0x7f0b40128ebf)
    at /opt/rh/devtoolset-10/root/usr/include/c++/10/bits/stl_tree.h:1014
#12 0x0000000001dc21de in dd::cache::Dictionary_client::acquire<dd::Abstract_table> (this=this@entry=0x7efa9c0044c0, schema_name="d2", object_name="t1", object=object@entry=0x7f0b40129040)
    at /home/yoku0825/mysql-8.0.28/sql/dd/impl/cache/dictionary_client.cc:846
#13 0x0000000000d01547 in get_table_share(THD*, char const*, char const*, char const*, unsigned long, bool, bool) () at /opt/rh/devtoolset-10/root/usr/include/c++/10/bits/basic_string.h:3342
#14 0x0000000000d082a7 in get_table_share_with_discover (error=<synthetic pointer>, open_secondary=false, key_length=6, key=<optimized out>, table_list=0x7efa9c01a6f0, thd=0x7efa9c000d20)
    at /home/yoku0825/mysql-8.0.28/sql/sql_base.cc:3202
#15 open_table(THD*, TABLE_LIST*, Open_table_context*) () at /home/yoku0825/mysql-8.0.28/sql/sql_base.cc:3202
#16 0x0000000000d0a298 in open_and_process_table (ot_ctx=0x7f0b401298b0, has_prelocking_list=false, prelocking_strategy=0x7f0b40129958, counter=0x7efa9c003c58, tables=0x7efa9c01a6f0, lex=<optimized out>, thd=0x7efa9c000d20)
    at /home/yoku0825/mysql-8.0.28/sql/sql_base.cc:5034
#17 open_tables (thd=thd@entry=0x7efa9c000d20, start=start@entry=0x7f0b40129948, counter=0x7efa9c003c58, flags=flags@entry=0, prelocking_strategy=prelocking_strategy@entry=0x7f0b40129958)
    at /home/yoku0825/mysql-8.0.28/sql/sql_base.cc:5842
#18 0x0000000000d0b6bd in open_tables_for_query (thd=thd@entry=0x7efa9c000d20, tables=<optimized out>, flags=0) at /home/yoku0825/mysql-8.0.28/sql/sql_base.cc:6722
#19 0x0000000000df387c in Sql_cmd_dml::prepare(THD*) () at /home/yoku0825/mysql-8.0.28/sql/sql_cmd.h:83
#20 0x0000000000df40ee in Sql_cmd_dml::execute(THD*) () at /home/yoku0825/mysql-8.0.28/sql/sql_select.cc:528
#21 0x0000000000d9bd08 in mysql_execute_command(THD*, bool) () at /home/yoku0825/mysql-8.0.28/sql/sql_parse.cc:4544
#22 0x0000000000d9f5d2 in dispatch_sql_command (thd=thd@entry=0x7efa9c000d20, parser_state=parser_state@entry=0x7f0b4012ac20) at /home/yoku0825/mysql-8.0.28/sql/sql_parse.cc:5174
#23 0x0000000000da08de in dispatch_command(THD*, COM_DATA const*, enum_server_command) () at /home/yoku0825/mysql-8.0.28/sql/sql_parse.cc:1938
#24 0x0000000000da29b2 in do_command (thd=thd@entry=0x7efa9c000d20) at /home/yoku0825/mysql-8.0.28/sql/sql_parse.cc:1352
#25 0x0000000000edcb70 in handle_connection (arg=arg@entry=0x7eeb0c0) at /home/yoku0825/mysql-8.0.28/sql/conn_handler/connection_handler_per_thread.cc:302
#26 0x00000000024b0770 in pfs_spawn_thread (arg=0x7e441d0) at /home/yoku0825/mysql-8.0.28/storage/perfschema/pfs.cc:2947
#27 0x00007f0b594d6ea5 in start_thread () from /lib64/libpthread.so.0
#28 0x00007f0b57af0b0d in clone () from /lib64/libc.so.6

(gdb) c
+c
Continuing.

↓のような感じでテーブルオープンのタイミングが見える。

(gdb) bt
+bt
#0  ha_innobase::open(char const*, int, unsigned int, dd::Table const*) () at /home/yoku0825/mysql-8.0.28/storage/innobase/handler/ha_innodb.cc:6995
#1  0x0000000000ff7775 in handler::ha_open (this=0x7efa9ca814e0, table_arg=table_arg@entry=0x7efa9ca8b900, name=0x7efa9c165620 "./d2/t1", mode=mode@entry=2, test_if_locked=2, table_def=0x7efa9c1275d0)
    at /home/yoku0825/mysql-8.0.28/sql/handler.cc:2812
#2  0x0000000000eac9f2 in open_table_from_share(THD*, TABLE_SHARE*, char const*, unsigned int, unsigned int, unsigned int, TABLE*, bool, dd::Table const*) () at /home/yoku0825/mysql-8.0.28/sql/table.cc:3175
#3  0x0000000000d08c5f in open_table(THD*, TABLE_LIST*, Open_table_context*) () at /home/yoku0825/mysql-8.0.28/sql/sql_base.cc:3367
#4  0x0000000000d0a298 in open_and_process_table (ot_ctx=0x7f0b401298b0, has_prelocking_list=false, prelocking_strategy=0x7f0b40129958, counter=0x7efa9c003c58, tables=0x7efa9c01a600, lex=<optimized out>, thd=0x7efa9c000d20)
    at /home/yoku0825/mysql-8.0.28/sql/sql_base.cc:5034
#5  open_tables (thd=thd@entry=0x7efa9c000d20, start=start@entry=0x7f0b40129948, counter=0x7efa9c003c58, flags=flags@entry=0, prelocking_strategy=prelocking_strategy@entry=0x7f0b40129958)
    at /home/yoku0825/mysql-8.0.28/sql/sql_base.cc:5842
#6  0x0000000000d0b6bd in open_tables_for_query (thd=thd@entry=0x7efa9c000d20, tables=<optimized out>, flags=0) at /home/yoku0825/mysql-8.0.28/sql/sql_base.cc:6722
#7  0x0000000000df387c in Sql_cmd_dml::prepare(THD*) () at /home/yoku0825/mysql-8.0.28/sql/sql_cmd.h:83
#8  0x0000000000df40ee in Sql_cmd_dml::execute(THD*) () at /home/yoku0825/mysql-8.0.28/sql/sql_select.cc:528
#9  0x0000000000d9bd08 in mysql_execute_command(THD*, bool) () at /home/yoku0825/mysql-8.0.28/sql/sql_parse.cc:4544
#10 0x0000000000d9f5d2 in dispatch_sql_command (thd=thd@entry=0x7efa9c000d20, parser_state=parser_state@entry=0x7f0b4012ac20) at /home/yoku0825/mysql-8.0.28/sql/sql_parse.cc:5174
#11 0x0000000000da08de in dispatch_command(THD*, COM_DATA const*, enum_server_command) () at /home/yoku0825/mysql-8.0.28/sql/sql_parse.cc:1938
#12 0x0000000000da29b2 in do_command (thd=thd@entry=0x7efa9c000d20) at /home/yoku0825/mysql-8.0.28/sql/sql_parse.cc:1352
#13 0x0000000000edcb70 in handle_connection (arg=arg@entry=0x7eeb0c0) at /home/yoku0825/mysql-8.0.28/sql/conn_handler/connection_handler_per_thread.cc:302
#14 0x00000000024b0770 in pfs_spawn_thread (arg=0x7e441d0) at /home/yoku0825/mysql-8.0.28/storage/perfschema/pfs.cc:2947
#15 0x00007f0b594d6ea5 in start_thread () from /lib64/libpthread.so.0
#16 0x00007f0b57af0b0d in clone () from /lib64/libc.so.6
(gdb) p name
+p name
$8 = 0x7efa9c165620 "./d2/t1"

これを繰り返すと、 t1, t2, t3, t5, t4の順番が得られた。

SELECT
  * 
FROM 
  t1,                      /* 1st */
  t2,                     /* 2nd */
  (
    SELECT 
      SUBSTRING(val, 1, 1) AS f, 
      SUM(num) 
    FROM 
      t3                 /* 3rd */
    GROUP BY f
  ) AS tmp_t3 
WHERE 
  t1.num IN 
    (
      SELECT 
         num 
       FROM 
         t5                     /* 4th */
        WHERE 
          num = 
            (
              SELECT 
                MAX(num) 
              FROM 
                t4               /* 5th */
            ) AND 
          val LIKE '%'
    )
;

これはクエリに出てきた順番に合致している。なるほど。

とはいえテーブルオープンの順番が実際に行にアクセスする順番ではないはずなので、色々探した挙句に件数を減らした(各テーブルレコード1件)の状態で ha_innobase::index_readにブレークポイントを置いてみる。

(gdb) b ha_innobase::index_read
+b ha_innobase::index_read
Breakpoint 1 at 0x20d8425: file /home/yoku0825/mysql-8.0.28/include/my_compiler.h, line 55.

(gdb) c
+c
Continuing.

mysql80 8> SELECT * FROM t1, t2, (SELECT SUBSTRING(val, 1, 1) AS f, SUM(num) FROM t3 GROUP BY f) AS tmp_t3 WHERE t1.num IN (SELECT num FROM t5 WHERE num = (SELECT MAX(num) FROM t4) AND val LIKE '%');

Breakpoint 1, ha_innobase::index_read (this=0x7efa9c0b87b0, buf=0x7efa9c133f50 "", key_ptr=0x0, key_len=0, find_flag=HA_READ_BEFORE_KEY) at /home/yoku0825/mysql-8.0.28/include/my_compiler.h:55
55      constexpr bool unlikely(bool expr) { return __builtin_expect(expr, false); }
(gdb) p this->m_share->table_name
+p this->m_share->table_name
$1 = 0x7efa9ca93f60 "./d2/t4"
(gdb) c
+c
Continuing.

Breakpoint 1, ha_innobase::index_read (this=0x7efa9ca814e0, buf=0x7efa9c00b120 "", key_ptr=0x7efa9c063c90 "\001", key_len=8, find_flag=HA_READ_KEY_EXACT) at /home/yoku0825/mysql-8.0.28/include/my_compiler.h:55
55      constexpr bool unlikely(bool expr) { return __builtin_expect(expr, false); }
(gdb) p this->m_share->table_name
+p this->m_share->table_name
$2 = 0x7efa9ca85be0 "./d2/t1"
(gdb) c
+c
Continuing.

Breakpoint 1, ha_innobase::index_read (this=0x7efa9caa44a0, buf=0x7efa9ca984e0 "", key_ptr=0x7efa9c064498 "\001", key_len=8, find_flag=HA_READ_KEY_EXACT) at /home/yoku0825/mysql-8.0.28/include/my_compiler.h:55
55      constexpr bool unlikely(bool expr) { return __builtin_expect(expr, false); }
(gdb) p this->m_share->table_name
+p this->m_share->table_name
$3 = 0x7efa9ca85850 "./d2/t5"
(gdb) c
+c
Continuing.

Breakpoint 1, ha_innobase::index_read (this=0x7efa9c136c90, buf=0x7efa9c03f740 "\377", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /home/yoku0825/mysql-8.0.28/include/my_compiler.h:55
55      constexpr bool unlikely(bool expr) { return __builtin_expect(expr, false); }
(gdb) p this->m_share->table_name
+p this->m_share->table_name
$4 = 0x7efa9c082ab0 "./d2/t2"
(gdb) c
+c
Continuing.

Breakpoint 1, ha_innobase::index_read (this=0x7efa9ca96e10, buf=0x7efa9ca834f0 "\377", key_ptr=0x0, key_len=0, find_flag=HA_READ_AFTER_KEY) at /home/yoku0825/mysql-8.0.28/include/my_compiler.h:55
55      constexpr bool unlikely(bool expr) { return __builtin_expect(expr, false); }
(gdb) p this->m_share->table_name
+p this->m_share->table_name
$5 = 0x7efa9c05d720 "./d2/t3"
(gdb) c
+c
Continuing.

この手順でやると、 t4, t1, t5, t2, t3 ………えっ、あれ、 t3 最後に読むの？

+----+-------------+------------+------------+-------+---------------+------+---------+-------+------+----------+-------------------------------+
| id | select_type | table      | partitions | type  | possible_keys | key  | key_len | ref   | rows | filtered | Extra                         |
+----+-------------+------------+------------+-------+---------------+------+---------+-------+------+----------+-------------------------------+
|  1 | PRIMARY     | t1         | NULL       | const | num           | num  | 8       | const |    1 |   100.00 | NULL                          |
|  1 | PRIMARY     | t5         | NULL       | const | num           | num  | 8       | const |    1 |   100.00 | NULL                          |
|  1 | PRIMARY     | t2         | NULL       | ALL   | NULL          | NULL | NULL    | NULL  |    1 |   100.00 | NULL                          |
|  1 | PRIMARY     | <derived2> | NULL       | ALL   | NULL          | NULL | NULL    | NULL  |    2 |   100.00 | Using join buffer (hash join) |
|  4 | SUBQUERY    | NULL       | NULL       | NULL  | NULL          | NULL | NULL    | NULL  | NULL |     NULL | Select tables optimized away  |
|  2 | DERIVED     | t3         | NULL       | ALL   | NULL          | NULL | NULL    | NULL  |    1 |   100.00 | Using temporary               |
+----+-------------+------------+------------+-------+---------------+------+---------+-------+------+----------+-------------------------------+

バージョンを5.5まで遡ったら、ステップ実行しても t3, t4, t1, t5, t2 の順番で読むようになったので、5.6でそういえばそんな最適化が…と思ったらこれだった。

Materialization of subqueries in the FROM clause is postponed until their contents are needed during query execution, which improves performance.

MySQL :: MySQL 5.6 Release Notes :: Changes in MySQL 5.6.3 (2011-10-03, Milestone 6)

というわけで、前回言っていた「t3が一番最初」は誤りでしたorz

日々の覚書

GA

2022/04/07

MySQL標準のEXPLAINと、実際にテーブルにアクセスする順番と

TL;DR