GA

2021/07/20

準同期レプリケーションで、でかいテーブルをDROP TABLEした時の死にポイント on 5.7.34

TL;DR

  • dict_sys のmutexを取るのでDDL系は死ぬし新しくテーブルキャッシュを作れないのでテーブルキャッシュが枯渇すると死ぬ
  • ROLLBACKdict_sys のmutexを取るので死ぬ。 COMMIT はできる。
  • 実はGroup Replicationまたは準同期レプリケーションを使っていると、更新系DMLの中に dict_sys を使う処理が追加されるのでこっちはいきなりDMLが刺さる。
  • 試したのは5.7.34だけ。他のバージョンの動作は知らない。
  • この動作は単純にunlink中のmutexの話なので、バッファプールの大小にはよらない。
    • 【2022/08/01 11:21】この実験は単純にunlinkを遅延させて測っているだけなので、バッファプールの大小はまた別の問題(今回の実験対象ではない)

まず、「でかいテーブルをDROP」のためにでっかいテーブルを作るのも大変なので、単純に unlink に時間がかかっているように見せかけるためにパッチを当てる。

$ diff -U 1 storage/innobase/os/os0file.cc.orig storage/innobase/os/os0file.cc
--- storage/innobase/os/os0file.cc.orig 2021-03-26 15:58:52.000000000 +0900
+++ storage/innobase/os/os0file.cc      2021-07-19 23:12:21.372096902 +0900
@@ -3781,2 +3781,3 @@

+       os_thread_sleep(30 * 1000000); //debug
        int     ret = unlink(name);
@@ -3803,2 +3804,3 @@
 {
+       os_thread_sleep(30 * 1000000); //debug
        int     ret = unlink(name);

DROP TABLEの実行から、最後に行きつく unlink のところに30秒のスリープを入れた。

https://github.com/mysql/mysql-server/blob/mysql-5.7.34/storage/innobase/os/os0file.cc#L3769-L3813

こいつをコンパイルしてスタート。

mysql57 16> CREATE DATABASE drop_test;
Query OK, 1 row affected (0.00 sec)

mysql57 16> CREATE TABLE drop_test.t1 (num int) Engine = InnoDB;
Query OK, 0 rows affected (0.02 sec)

mysql57 16> FLUSH TABLES;  -- いったんテーブルキャッシュを飛ばす
Query OK, 0 rows affected (0.00 sec)

mysql57 16> DROP TABLE drop_test.t1; -- やたら時間がかかる

mysql57 17> SELECT * FROM d1.t1 LIMIT 1; -- 刺さる

mysql57 18> SHOW PROCESSLIST;  -- Opening tablesで止まっている
+----+-----------------+-----------+------+---------+------+------------------------+-----------------------------+
| Id | User            | Host      | db   | Command | Time | State                  | Info                        |
+----+-----------------+-----------+------+---------+------+------------------------+-----------------------------+
|  1 | event_scheduler | localhost | NULL | Daemon  | 2039 | Waiting on empty queue | NULL                        |
| 16 | root            | localhost | NULL | Query   |   25 | checking permissions   | DROP TABLE drop_test.t1     |
| 17 | root            | localhost | d1   | Query   |   15 | Opening tables         | SELECT * FROM d1.t1 LIMIT 1 |
| 18 | root            | localhost | NULL | Query   |    0 | starting               | SHOW PROCESSLIST            |
+----+-----------------+-----------+------+---------+------+------------------------+-----------------------------+
4 rows in set (0.00 sec)

mysql57 18> SHOW ENGINE INNODB STATUS\G
..
----------                                                                                                                                                                        [101/140]
SEMAPHORES
----------
OS WAIT ARRAY INFO: reservation count 74
--Thread 140472257337088 has waited at row0purge.cc line 882 for 28  seconds the semaphore:
S-lock on RW-latch at 0x3d1f528 created in file dict0dict.cc line 1228
a writer (thread id 140472341939968) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0purge.cc line 882
Last time write locked in file /home/yoku0825/mysql-5.7.34/storage/innobase/row/row0mysql.cc line 4319
--Thread 140472274122496 has waited at row0purge.cc line 882 for 28  seconds the semaphore:
S-lock on RW-latch at 0x3d1f528 created in file dict0dict.cc line 1228
a writer (thread id 140472341939968) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0purge.cc line 882
Last time write locked in file /home/yoku0825/mysql-5.7.34/storage/innobase/row/row0mysql.cc line 4319
--Thread 140472342480640 has waited at dict0dict.cc line 1283 for 19  seconds the semaphore:
Mutex at 0x3d1f5c8, Mutex DICT_SYS created dict0dict.cc:1217, lock var 1

--Thread 140472265729792 has waited at row0purge.cc line 882 for 28  seconds the semaphore:
S-lock on RW-latch at 0x3d1f528 created in file dict0dict.cc line 1228
a writer (thread id 140472341939968) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0purge.cc line 882
Last time write locked in file /home/yoku0825/mysql-5.7.34/storage/innobase/row/row0mysql.cc line 4319
--Thread 140472351954688 has waited at srv0srv.cc line 1989 for 27  seconds the semaphore:
X-lock on RW-latch at 0x3d1f528 created in file dict0dict.cc line 1228
a writer (thread id 140472341939968) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0purge.cc line 882
Last time write locked in file /home/yoku0825/mysql-5.7.34/storage/innobase/row/row0mysql.cc line 4319
--Thread 140472248944384 has waited at row0purge.cc line 882 for 28  seconds the semaphore:
S-lock on RW-latch at 0x3d1f528 created in file dict0dict.cc line 1228
a writer (thread id 140472341939968) has reserved it in mode  exclusive
number of readers 0, waiters flag 1, lock_word: 0
Last time read locked in file row0purge.cc line 882
Last time write locked in file /home/yoku0825/mysql-5.7.34/storage/innobase/row/row0mysql.cc line 4319
OS WAIT ARRAY INFO: signal count 40
RW-shared spins 0, rounds 79, OS waits 44
RW-excl spins 0, rounds 173, OS waits 5
RW-sx spins 0, rounds 0, OS waits 0
Spin rounds per wait: 79.00 RW-shared, 173.00 RW-excl, 0.00 RW-sx
..

$ gstack $(pidof mysqld)
..
Thread 4 (Thread 0x7fc244130700 (LWP 11888)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1  0x0000000001026981 in wait (this=<optimized out>) at /home/yoku0825/mysql-5.7.34/storage/innobase/os/os0event.cc:179
#2  os_event::wait_low (this=0x3d1f6b8, reset_sig_count=<optimized out>) at /home/yoku0825/mysql-5.7.34/storage/innobase/os/os0event.cc:366
#3  0x000000000102727a in os_event_wait_low (event=<optimized out>, reset_sig_count=<optimized out>) at /home/yoku0825/mysql-5.7.34/storage/innobase/os/os0event.cc:611
#4  0x00000000010e2f38 in sync_array_wait_event (arr=arr@entry=0x342b408, cell=@0x7fc24412d790: 0x7fc256c420a8) at /home/yoku0825/mysql-5.7.34/storage/innobase/sync/sync0arr.cc:483
#5  0x00000000011aeb06 in wait (spin=4, line=1283, filename=0x15099c0 "/home/yoku0825/mysql-5.7.34/storage/innobase/dict/dict0dict.cc", this=0x3d1f5c8) at /home/yoku0825/mysql-5.7.34/stor
age/innobase/include/ut0mutex.ic:97
#6  spin_and_try_lock (line=1283, filename=0x15099c0 "/home/yoku0825/mysql-5.7.34/storage/innobase/dict/dict0dict.cc", max_delay=<optimized out>, max_spins=<optimized out>, this=0x3d1f5c8
) at /home/yoku0825/mysql-5.7.34/storage/innobase/include/ib0mutex.h:858
#7  enter (line=1283, filename=0x15099c0 "/home/yoku0825/mysql-5.7.34/storage/innobase/dict/dict0dict.cc", max_delay=<optimized out>, max_spins=<optimized out>, this=0x3d1f5c8) at /home/y
oku0825/mysql-5.7.34/storage/innobase/include/ib0mutex.h:715
#8  PolicyMutex<TTASEventMutex<GenericPolicy> >::enter (this=0x3d1f5c8, n_spins=<optimized out>, n_delay=<optimized out>, line=line@entry=1283, name=0x15099c0 "/home/yoku0825/mysql-5.7.34
/storage/innobase/dict/dict0dict.cc") at /home/yoku0825/mysql-5.7.34/storage/innobase/include/ib0mutex.h:995
#9  0x00000000011b4768 in dict_table_open_on_name (table_name=table_name@entry=0x7fc24412dda0 "d1/t1", dict_locked=dict_locked@entry=0, try_drop=try_drop@entry=1, ignore_err=ignore_err@en
try=DICT_ERR_IGNORE_NONE) at /home/yoku0825/mysql-5.7.34/storage/innobase/dict/dict0dict.cc:1283
#10 0x0000000000f9718a in ha_innobase::open_dict_table (table_name=table_name@entry=0x7fc20c016aa8 "./d1/t1", norm_name=norm_name@entry=0x7fc24412dda0 "d1/t1", is_partition=<optimized out
>, ignore_err=ignore_err@entry=DICT_ERR_IGNORE_NONE) at /home/yoku0825/mysql-5.7.34/storage/innobase/handler/ha_innodb.cc:6300
#11 0x0000000000fada3a in ha_innobase::open (this=0x7fc20c00f110, name=0x7fc20c016aa8 "./d1/t1", mode=<optimized out>, test_if_locked=<optimized out>) at /home/yoku0825/mysql-5.7.34/stora
ge/innobase/handler/ha_innodb.cc:5926
#12 0x00000000007eced3 in handler::ha_open (this=0x7fc20c00f110, table_arg=table_arg@entry=0x7fc20c00e760, name=0x7fc20c016aa8 "./d1/t1", mode=mode@entry=2, test_if_locked=2) at /home/yok
u0825/mysql-5.7.34/sql/handler.cc:2775
#13 0x0000000000d1c217 in open_table_from_share (thd=thd@entry=0x7fc20c012280, share=share@entry=0x7fc20c016720, alias=<optimized out>, db_stat=db_stat@entry=39, prgflag=prgflag@entry=8,
ha_open_flags=<optimized out>, outparam=outparam@entry=0x7fc20c00e760, is_create_table=is_create_table@entry=false) at /home/yoku0825/mysql-5.7.34/sql/table.cc:3398
#14 0x0000000000c30ca4 in open_table (thd=thd@entry=0x7fc20c012280, table_list=table_list@entry=0x7fc20c018200, ot_ctx=ot_ctx@entry=0x7fc24412e620) at /home/yoku0825/mysql-5.7.34/sql/sql_
base.cc:3638
#15 0x0000000000c323d2 in open_and_process_table (flags=0, ot_ctx=0x7fc24412e620, has_prelocking_list=false, prelocking_strategy=0x7fc24412e6b0, counter=0x7fc20c0144b8, tables=0x7fc20c018
200, lex=<optimized out>, thd=0x7fc20c012280) at /home/yoku0825/mysql-5.7.34/sql/sql_base.cc:5260
#16 open_tables (thd=thd@entry=0x7fc20c012280, start=start@entry=0x7fc24412e6a8, counter=<optimized out>, flags=flags@entry=0, prelocking_strategy=prelocking_strategy@entry=0x7fc24412e6b0
) at /home/yoku0825/mysql-5.7.34/sql/sql_base.cc:5885
#17 0x0000000000c32d3b in open_tables_for_query (thd=thd@entry=0x7fc20c012280, tables=tables@entry=0x7fc20c018200, flags=flags@entry=0) at /home/yoku0825/mysql-5.7.34/sql/sql_base.cc:6660#18 0x000000000075c2bd in execute_sqlcom_select (thd=thd@entry=0x7fc20c012280, all_tables=0x7fc20c018200) at /home/yoku0825/mysql-5.7.34/sql/sql_parse.cc:5127
#19 0x0000000000c83c19 in mysql_execute_command (thd=thd@entry=0x7fc20c012280, first_level=first_level@entry=true) at /home/yoku0825/mysql-5.7.34/sql/sql_parse.cc:2827
#20 0x0000000000c862bd in mysql_parse (thd=thd@entry=0x7fc20c012280, parser_state=parser_state@entry=0x7fc24412f660) at /home/yoku0825/mysql-5.7.34/sql/sql_parse.cc:5589
#21 0x0000000000c86eca in dispatch_command (thd=thd@entry=0x7fc20c012280, com_data=com_data@entry=0x7fc24412fcc0, command=COM_QUERY) at /home/yoku0825/mysql-5.7.34/sql/sql_parse.cc:1491
#22 0x0000000000c888e7 in do_command (thd=thd@entry=0x7fc20c012280) at /home/yoku0825/mysql-5.7.34/sql/sql_parse.cc:1032
#23 0x0000000000d46c58 in handle_connection (arg=arg@entry=0x3b0e040) at /home/yoku0825/mysql-5.7.34/sql/conn_handler/connection_handler_per_thread.cc:313
#24 0x0000000000edd684 in pfs_spawn_thread (arg=0x3c90a20) at /home/yoku0825/mysql-5.7.34/storage/perfschema/pfs.cc:2197
#25 0x00007fc262127ea5 in start_thread (arg=0x7fc244130700) at pthread_create.c:307
#26 0x00007fc26050a9fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111
..

unlink が終わるまで dict_sys のmutexを離してくれないので、テーブルオープンの処理ができない。テーブルキャッシュがあってテーブルオープンせずに使いまわせる時はちゃんと処理できる。

mysql57 16> CREATE TABLE drop_test.t1 (num int) Engine = InnoDB;
Query OK, 0 rows affected (0.02 sec)

mysql57 16> DROP TABLE drop_test.t1;  -- FLUSH TABLESせずにもういっかい

mysql57 17> SELECT * FROM d1.t1 LIMIT 1; -- 動ける
+-----+----------------------------------+
| num | val                              |
+-----+----------------------------------+
|   1 | c4ca4238a0b923820dcc509a6f75849b |
+-----+----------------------------------+
1 row in set (0.00 sec)

mysql57 17> BEGIN;
Query OK, 0 rows affected (0.00 sec)

mysql57 17> UPDATE d1.t1 SET val = 'hoge' WHERE num = 1;
Query OK, 1 row affected (0.07 sec)
Rows matched: 1  Changed: 1  Warnings: 0

mysql57 17> SELECT * FROM d1.t1 LIMIT 1;
+-----+------+
| num | val  |
+-----+------+
|   1 | hoge |
+-----+------+
1 row in set (0.00 sec)

mysql57 17> COMMIT;
Query OK, 0 rows affected (0.00 sec)

書き込みもできた。
しかしロールバックは刺さった。

mysql57 17> BEGIN;
Query OK, 0 rows affected (0.00 sec)

mysql57 17> UPDATE d1.t1 SET val = 'c4ca4238a0b923820dcc509a6f75849b' WHERE num = 1;
Query OK, 1 row affected (0.00 sec)
Rows matched: 1  Changed: 1  Warnings: 0

mysql57 17> ROLLBACK; -- 刺さった

Thread 4 (Thread 0x7fc244130700 (LWP 11888)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1  0x0000000001026981 in wait (this=<optimized out>) at /home/yoku0825/mysql-5.7.34/storage/innobase/os/os0event.cc:179
#2  os_event::wait_low (this=0x3add508, reset_sig_count=<optimized out>) at /home/yoku0825/mysql-5.7.34/storage/innobase/os/os0event.cc:366
#3  0x000000000102727a in os_event_wait_low (event=<optimized out>, reset_sig_count=<optimized out>) at /home/yoku0825/mysql-5.7.34/storage/innobase/os/os0event.cc:611
#4  0x00000000010e2f38 in sync_array_wait_event (arr=arr@entry=0x342b408, cell=@0x7fc24412cbe0: 0x7fc256c42128) at /home/yoku0825/mysql-5.7.34/storage/innobase/sync/sync0arr.cc:483
#5  0x00000000010e53b4 in rw_lock_s_lock_spin (lock=lock@entry=0x3d1f528, pass=pass@entry=0, file_name=file_name@entry=0x14f7e70 "/home/yoku0825/mysql-5.7.34/storage/innobase/row/row0undo.cc", line=line@entry=330) at /home/yoku0825/mysq$
-5.7.34/storage/innobase/sync/sync0rw.cc:440
#6  0x000000000108582c in rw_lock_s_lock_func (pass=0, line=330, file_name=0x14f7e70 "/home/yoku0825/mysql-5.7.34/storage/innobase/row/row0undo.cc", lock=0x3d1f528) at /home/yoku0825/mysql-5.7.34/storage/innobase/include/sync0rw.ic:440
#7  pfs_rw_lock_s_lock_func (pass=0, line=330, file_name=0x14f7e70 "/home/yoku0825/mysql-5.7.34/storage/innobase/row/row0undo.cc", lock=0x3d1f528) at /home/yoku0825/mysql-5.7.34/storage/innobase/include/sync0rw.ic:805
#8  row_mysql_freeze_data_dictionary_func (trx=trx@entry=0x7fc256841ae0, file=file@entry=0x14f7e70 "/home/yoku0825/mysql-5.7.34/storage/innobase/row/row0undo.cc", line=line@entry=330) at /home/yoku0825/mysql-5.7.34/storage/innobase/row/$
ow0mysql.cc:2963
#9  0x00000000010ba43c in row_undo (thr=0x7fc20c01bd48, node=0x7fc20c01bf08) at /home/yoku0825/mysql-5.7.34/storage/innobase/row/row0undo.cc:330
#10 row_undo_step (thr=thr@entry=0x7fc20c01bd48) at /home/yoku0825/mysql-5.7.34/storage/innobase/row/row0undo.cc:420
#11 0x000000000104a2a1 in que_thr_step (thr=<optimized out>) at /home/yoku0825/mysql-5.7.34/storage/innobase/que/que0que.cc:1055
#12 que_run_threads_low (thr=<optimized out>) at /home/yoku0825/mysql-5.7.34/storage/innobase/que/que0que.cc:1119
#13 que_run_threads (thr=<optimized out>) at /home/yoku0825/mysql-5.7.34/storage/innobase/que/que0que.cc:1159
#14 0x000000000110a838 in trx_rollback_to_savepoint_low (trx=trx@entry=0x7fc256841ae0, savept=savept@entry=0x0) at /home/yoku0825/mysql-5.7.34/storage/innobase/trx/trx0roll.cc:126
#15 0x000000000110b1c0 in trx_rollback_for_mysql_low (trx=0x7fc256841ae0) at /home/yoku0825/mysql-5.7.34/storage/innobase/trx/trx0roll.cc:188
#16 trx_rollback_low (trx=trx@entry=0x7fc256841ae0) at /home/yoku0825/mysql-5.7.34/storage/innobase/trx/trx0roll.cc:220
#17 0x000000000110b528 in trx_rollback_for_mysql (trx=trx@entry=0x7fc256841ae0) at /home/yoku0825/mysql-5.7.34/storage/innobase/trx/trx0roll.cc:297
#18 0x0000000000fa388b in innobase_rollback (hton=<optimized out>, thd=0x7fc20c012280, rollback_trx=<optimized out>) at /home/yoku0825/mysql-5.7.34/storage/innobase/handler/ha_innodb.cc:4540
#19 0x00000000007ebbd7 in ha_rollback_low (thd=thd@entry=0x7fc20c012280, all=all@entry=true) at /home/yoku0825/mysql-5.7.34/sql/handler.cc:1984
#20 0x0000000000e4e09f in MYSQL_BIN_LOG::rollback (this=0x1d3bb20 <mysql_bin_log>, thd=0x7fc20c012280, all=<optimized out>) at /home/yoku0825/mysql-5.7.34/sql/binlog.cc:2349
#21 0x00000000007ebde6 in ha_rollback_trans (thd=thd@entry=0x7fc20c012280, all=all@entry=true) at /home/yoku0825/mysql-5.7.34/sql/handler.cc:2071
#22 0x0000000000d296fa in trans_rollback (thd=thd@entry=0x7fc20c012280) at /home/yoku0825/mysql-5.7.34/sql/transaction.cc:363
#23 0x0000000000c82fe5 in mysql_execute_command (thd=thd@entry=0x7fc20c012280, first_level=first_level@entry=true) at /home/yoku0825/mysql-5.7.34/sql/sql_parse.cc:4285
#24 0x0000000000c862bd in mysql_parse (thd=thd@entry=0x7fc20c012280, parser_state=parser_state@entry=0x7fc24412f660) at /home/yoku0825/mysql-5.7.34/sql/sql_parse.cc:5589
#25 0x0000000000c86eca in dispatch_command (thd=thd@entry=0x7fc20c012280, com_data=com_data@entry=0x7fc24412fcc0, command=COM_QUERY) at /home/yoku0825/mysql-5.7.34/sql/sql_parse.cc:1491
#26 0x0000000000c888e7 in do_command (thd=thd@entry=0x7fc20c012280) at /home/yoku0825/mysql-5.7.34/sql/sql_parse.cc:1032
#27 0x0000000000d46c58 in handle_connection (arg=arg@entry=0x3b0e040) at /home/yoku0825/mysql-5.7.34/sql/conn_handler/connection_handler_per_thread.cc:313
#28 0x0000000000edd684 in pfs_spawn_thread (arg=0x3c90a20) at /home/yoku0825/mysql-5.7.34/storage/perfschema/pfs.cc:2197
#29 0x00007fc262127ea5 in start_thread (arg=0x7fc244130700) at pthread_create.c:307
#30 0x00007fc26050a9fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

row_undo の先で row_mysql_freeze_data_dictionary_func なるものを呼んでいる。まあ確かにロールバック中にデータディクショナリ書き替えられたら大変だからそうなのかもしれない。

mysql57 16> INSTALL PLUGIN rpl_semi_sync_master SONAME 'semisync_master.so';
Query OK, 0 rows affected (0.02 sec)

mysql57 16> SET GLOBAL rpl_semi_sync_master_enabled= ON;
Query OK, 0 rows affected (0.00 sec)

mysql57 16> CREATE TABLE drop_test.t1 (num int) Engine = InnoDB;
Query OK, 0 rows affected (10.01 sec)

mysql57 16> DROP TABLE drop_test.t1;

mysql57 17> BEGIN;
Query OK, 0 rows affected (0.00 sec)

mysql57 17> SELECT * FROM d1.t1 LIMIT 1;
+-----+------+
| num | val  |
+-----+------+
|   1 | hoge |
+-----+------+
1 row in set (0.00 sec)

mysql57 17> UPDATE d1.t1 SET val = 'hoge' WHERE num = 1;  -- テーブルキャッシュはあるのに刺さる

Thread 5 (Thread 0x7fc244130700 (LWP 11888)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1  0x0000000001026981 in wait (this=<optimized out>) at /home/yoku0825/mysql-5.7.34/storage/innobase/os/os0event.cc:179
#2  os_event::wait_low (this=0x3d1f6b8, reset_sig_count=<optimized out>) at /home/yoku0825/mysql-5.7.34/storage/innobase/os/os0event.cc:366
#3  0x000000000102727a in os_event_wait_low (event=<optimized out>, reset_sig_count=<optimized out>) at /home/yoku0825/mysql-5.7.34/storage/innobase/os/os0event.cc:611
#4  0x00000000010e2f38 in sync_array_wait_event (arr=arr@entry=0x342b408, cell=@0x7fc24412e2c0: 0x7fc256c42128) at /home/yoku0825/mysql-5.7.34/storage/innobase/sync/sync0arr.cc:483
#5  0x0000000000f9e1fe in wait (spin=4, line=15047, filename=<optimized out>, this=0x3d1f5c8) at /home/yoku0825/mysql-5.7.34/storage/innobase/include/ut0mutex.ic:97
#6  spin_and_try_lock (line=15047, filename=<optimized out>, max_delay=<optimized out>, max_spins=<optimized out>, this=0x3d1f5c8) at /home/yoku0825/mysql-5.7.34/storage/innobase/include/ib0mutex.h:858
#7  enter (line=15047, filename=<optimized out>, max_delay=<optimized out>, max_spins=<optimized out>, this=0x3d1f5c8) at /home/yoku0825/mysql-5.7.34/storage/innobase/include/ib0mutex.h:715
#8  PolicyMutex<TTASEventMutex<GenericPolicy> >::enter (this=0x3d1f5c8, n_spins=<optimized out>, n_delay=<optimized out>, name=name@entry=0x14e0228 "/home/yoku0825/mysql-5.7.34/storage/innobase/handler/ha_innodb.cc", line=line@entry=1504
7) at /home/yoku0825/mysql-5.7.34/storage/innobase/include/ib0mutex.h:995
#9  0x0000000000fa219a in ha_innobase::get_foreign_key_list (this=0x7fc20c00f110, thd=0x7fc20c012280, f_key_list=0x7fc24412e390) at /home/yoku0825/mysql-5.7.34/storage/innobase/handler/ha_innodb.cc:15047
#10 0x0000000000bedb53 in has_cascade_foreign_key (table=table@entry=0x7fc20c00e760, thd=thd@entry=0x7fc20c012280) at /home/yoku0825/mysql-5.7.34/sql/rpl_handler.cc:663
#11 0x0000000000bf2262 in Trans_delegate::prepare_table_info (this=this@entry=0x1d17340 <delegates_init()::trans_mem>, thd=thd@entry=0x7fc20c012280, table_info_list=@0x7fc24412e578: 0x0, number_of_tables=@0x7fc24412e580: 0) at /home/yoku
0825/mysql-5.7.34/sql/rpl_handler.cc:743
#12 0x0000000000bf2467 in Trans_delegate::before_dml (this=0x1d17340 <delegates_init()::trans_mem>, thd=thd@entry=0x7fc20c012280, result=@0x7fc24412e630: 0) at /home/yoku0825/mysql-5.7.34/sql/rpl_handler.cc:814
#13 0x0000000000c29cbf in run_before_dml_hook (thd=thd@entry=0x7fc20c012280) at /home/yoku0825/mysql-5.7.34/sql/sql_base.cc:5420
#14 0x0000000000d08c71 in Sql_cmd_update::try_single_table_update (this=this@entry=0x7fc20c0183a0, thd=thd@entry=0x7fc20c012280, switch_to_multitable=switch_to_multitable@entry=0x7fc24412e710) at /home/yoku0825/mysql-5.7.34/sql/sql_updat
e.cc:2913
#15 0x0000000000d09087 in Sql_cmd_update::execute (this=0x7fc20c0183a0, thd=0x7fc20c012280) at /home/yoku0825/mysql-5.7.34/sql/sql_update.cc:3058
#16 0x0000000000c7fe70 in mysql_execute_command (thd=thd@entry=0x7fc20c012280, first_level=first_level@entry=true) at /home/yoku0825/mysql-5.7.34/sql/sql_parse.cc:4846
#17 0x0000000000c862bd in mysql_parse (thd=thd@entry=0x7fc20c012280, parser_state=parser_state@entry=0x7fc24412f660) at /home/yoku0825/mysql-5.7.34/sql/sql_parse.cc:5589
#18 0x0000000000c86eca in dispatch_command (thd=thd@entry=0x7fc20c012280, com_data=com_data@entry=0x7fc24412fcc0, command=COM_QUERY) at /home/yoku0825/mysql-5.7.34/sql/sql_parse.cc:1491
#19 0x0000000000c888e7 in do_command (thd=thd@entry=0x7fc20c012280) at /home/yoku0825/mysql-5.7.34/sql/sql_parse.cc:1032
#20 0x0000000000d46c58 in handle_connection (arg=arg@entry=0x3b0e040) at /home/yoku0825/mysql-5.7.34/sql/conn_handler/connection_handler_per_thread.cc:313
#21 0x0000000000edd684 in pfs_spawn_thread (arg=0x3c90a20) at /home/yoku0825/mysql-5.7.34/storage/perfschema/pfs.cc:2197
#22 0x00007fc262127ea5 in start_thread (arg=0x7fc244130700) at pthread_create.c:307
#23 0x00007fc26050a9fd in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

どうやら、 run_before_dml_hook なるフックの中であらかじめCascade指定のFKがないかを確認する関数 ( has_cascade_foreign_key )を通るようになっていて、これが dict_sys を必要とするので刺さる。

「ないかどうかを確認する関数」なので、実際にあろうがなかろうがここを通る。 foreign_key_checks のON/OFFにも一切依存しない。

今まで非同期レプリケーション万歳だったからあまり気が付かなかった。記念パピコ。