2021/09/11

pt-online-schema-changeがColumn 'xx' cannot be nullで止まる

TL;DR

NULLが入っているカラムを後から NOT NULL にしようとすると出る
何故出るかというと、 INSERT IGNORE INTOがNOT NULL DEFAULTを裏切るから敢えて SHOW WARNINGS を拾ってエラーにしている
- 裏切られるのを承知の上で強行するなら pt-online-schema-change --null-to-not-null でいける
UPDATE t1 SET val = ? WHERE val IS NULL でNULLを排除してからpt-online-schema-changeすればいいんじゃないかな

日々の覚書: INSERT IGNORE INTOがNOT NULL DEFAULTを裏切るの続き。

pt-oscは INSERT IGNORE INTO を使ってるはずなのになんでこのメッセージでエラるんだろ？と思ったら、 ↑の裏切りを防ぐために明示的にワーニングを拾ってエラーにエスカレーションしているのであった。

https://github.com/percona/percona-toolkit/blob/v3.3.1/bin/pt-online-schema-change#L11791-L11828

mysql80 121> CREATE TABLE t1 (num int PRIMARY KEY, val varchar(32));
Query OK, 0 rows affected (0.02 sec)

mysql80 121> INSERT INTO t1 VALUES (1, 'one'), (2, NULL);
Query OK, 2 rows affected (0.01 sec)
Records: 2  Duplicates: 0  Warnings: 0

mysql80 121> SELECT * FROM t1;
+-----+------+
| num | val  |
+-----+------+
|   1 | one  |
|   2 | NULL |
+-----+------+
2 rows in set (0.00 sec)

mysql80 123> SELECT @@global.sql_mode;
+-------------------+
| @@global.sql_mode |
+-------------------+
|                   |
+-------------------+
1 row in set (0.00 sec)

sql_modeに関係ないことを確認するために、グローバルSQL_MODEを空っぽにしておく。

$ pt-online-schema-change -S /usr/mysql/8.0.26/data/mysql.sock -uroot --alter "MODIFY val varchar(32) NOT NULL DEFAULT 'z'" D=d2,t=t1 --execute
No slaves found.  See --recursion-method if host 150-95-141-50 has slaves.
Not checking slave lag because no slaves were found and --check-slave-lag was not specified.
Operation, tries, wait:
  analyze_table, 10, 1
  copy_rows, 10, 0.25
  create_triggers, 10, 1
  drop_triggers, 10, 1
  swap_tables, 10, 1
  update_foreign_keys, 10, 1
Altering `d2`.`t1`...
Creating new table...
Created new table d2._t1_new OK.
Altering new table...
Altered `d2`.`_t1_new` OK.
2021-09-11T00:11:48 Creating triggers...
2021-09-11T00:11:48 Created triggers OK.
2021-09-11T00:11:48 Copying approximately 2 rows...
2021-09-11T00:11:48 Dropping triggers...
2021-09-11T00:11:48 Dropped triggers OK.
2021-09-11T00:11:48 Dropping new table...
2021-09-11T00:11:48 Dropped new table OK.
`d2`.`t1` was not altered.
        (in cleanup) 2021-09-11T00:11:48 Error copying rows from `d2`.`t1` to `d2`.`_t1_new`: 2021-09-11T00:11:48 Copying rows caused a MySQL error 1048:
    Level: Warning
     Code: 1048
  Message: Column 'val' cannot be null
    Query: INSERT LOW_PRIORITY IGNORE INTO `d2`.`_t1_new` (`num`, `val`) SELECT `num`, `val` FROM `d2`.`t1` LOCK IN SHARE MODE /*pt-online-schema-change 5706 copy table*/
2021-09-11T00:11:48 Dropping triggers...
2021-09-11T00:11:48 Dropped triggers OK.
`d2`.`t1` was not altered.

とまあ転けて終わる。
…と、ジェネラルログをよく見てたら、元のsql_modeに関わらずいったんsql_modeを全OFFしていた。

2021-09-11T00:11:48.055972+09:00          132 Query     /*!40101 SET @@SQL_MODE := @OLD_SQL_MODE, @@SQL_QUOTE_SHOW_CREATE := @OLD_QUOTE */

まあいっか。

—null-to-not-null オプションをつけると、通る。ただし、DEFAULTに裏切られるので暗黙のフォールバックを受ける。

mysql80 136> SHOW CREATE TABLE t1\G
*************************** 1. row ***************************
       Table: t1
Create Table: CREATE TABLE `t1` (
  `num` int NOT NULL,
  `val` varchar(32) NOT NULL DEFAULT 'z',
  PRIMARY KEY (`num`)
) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_0900_ai_ci
1 row in set (0.00 sec)

mysql80 136> SELECT * FROM t1;
+-----+-----+
| num | val |
+-----+-----+
|   1 | one |
|   2 |     |
+-----+-----+
2 rows in set (0.00 sec)

これが嫌な場合、先んじて UPDATE t1 SET val = 'z' WHERE val IS NULL とでもしてNULLをつぶしておくのが正しいと思う。実際にNULLに当たらなければ、 --null-to-not-null をつけなくてもpt-oscは完走する。

ちなみにMySQLのNative ALTER TABLEはsql_modeに影響を受ける。STRICTな時はエラーになるし

mysql80 136> SELECT @@session.sql_mode;
+-----------------------------------------------------------------------------------------------------------------------+
| @@session.sql_mode                                                                                                    |
+-----------------------------------------------------------------------------------------------------------------------+
| ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_ENGINE_SUBSTITUTION |
+-----------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

mysql80 136> SELECT * FROM t1;
+-----+------+
| num | val  |
+-----+------+
|   1 | one  |
|   2 | NULL |
+-----+------+
2 rows in set (0.00 sec)

mysql80 136> ALTER TABLE t1 MODIFY val varchar(32) NOT NULL DEFAULT 'z';
ERROR 1138 (22004): Invalid use of NULL value

Non-Strictな場合はDEFAULTを裏切ってALTERが走る。

mysql80 136> SET SESSION sql_mode = '';
Query OK, 0 rows affected (0.00 sec)

mysql80 136> ALTER TABLE t1 MODIFY val varchar(32) NOT NULL DEFAULT 'z';
Query OK, 2 rows affected, 1 warning (0.04 sec)
Records: 2  Duplicates: 0  Warnings: 1

mysql80 136> SHOW WARNINGS;
+---------+------+------------------------------------------+
| Level   | Code | Message                                  |
+---------+------+------------------------------------------+
| Warning | 1265 | Data truncated for column 'val' at row 2 |
+---------+------+------------------------------------------+
1 row in set (0.00 sec)

mysql80 136> SELECT * FROM t1;
+-----+-----+
| num | val |
+-----+-----+
|   1 | one |
|   2 |     |
+-----+-----+
2 rows in set (0.00 sec)

こっちももちろんNULLに当たらなければSTRICT + ALTER TABLEでもエラーにはならないので、「NULLABLEからNOT NULLにする時はUPDATEでまずNULLを排除しましょう」という極めてフツーの感じになるのであった。

mysql80 136> SELECT @@session.sql_mode;
+-----------------------------------------------------------------------------------------------------------------------+
| @@session.sql_mode                                                                                                    |
+-----------------------------------------------------------------------------------------------------------------------+
| ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_ENGINE_SUBSTITUTION |
+-----------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

mysql80 136> CREATE TABLE t1 (num int PRIMARY KEY, val varchar(32));
Query OK, 0 rows affected (0.01 sec)

mysql80 136> INSERT INTO t1 VALUES (1, 'one'), (2, NULL);
Query OK, 2 rows affected (0.01 sec)
Records: 2  Duplicates: 0  Warnings: 0

mysql80 136> UPDATE t1 SET val = 'z' WHERE val IS NULL;
Query OK, 1 row affected (0.01 sec)
Rows matched: 1  Changed: 1  Warnings: 0

mysql80 136> SELECT * FROM t1;
+-----+------+
| num | val  |
+-----+------+
|   1 | one  |
|   2 | z    |
+-----+------+
2 rows in set (0.00 sec)

mysql80 136> ALTER TABLE t1 MODIFY val varchar(32) NOT NULL DEFAULT 'z';
Query OK, 0 rows affected (0.04 sec)
Records: 0  Duplicates: 0  Warnings: 0

mysql80 136> SELECT * FROM t1;
+-----+-----+
| num | val |
+-----+-----+
|   1 | one |
|   2 | z   |
+-----+-----+
2 rows in set (0.00 sec)

2021/09/06

INSERT IGNORE INTOがNOT NULL DEFAULTを裏切る

とりあえず8.0.26で実験する。

INSERT IGNORE INTO といえば、キー重複エラーを握りつぶして複数のINSERTを「先勝ち」であるかのように振る舞わせるのに使われることが多いやつ。

mysql80 10> CREATE TABLE t2 (pk int PRIMARY KEY);
Query OK, 0 rows affected (0.02 sec)

mysql80 10> INSERT INTO t2 VALUES (1);
Query OK, 1 row affected (0.01 sec)

mysql80 10> INSERT INTO t2 VALUES (1);
ERROR 1062 (23000): Duplicate entry '1' for key 't2.PRIMARY'

mysql80 10> INSERT IGNORE INTO t2 VALUES (1);
Query OK, 0 rows affected, 1 warning (0.00 sec)

mysql80 10> SELECT * FROM t2;
+----+
| pk |
+----+
|  1 |
+----+
1 row in set (0.00 sec)

あるいは、あたかも sql_mode= STRICT_TRANS_TABLES であっても、non-strictな設定の時の振る舞いをさせるかのようなやつ。

mysql80 10> CREATE TABLE t1 (val varchar(1));
Query OK, 0 rows affected (0.03 sec)

mysql80 10> SELECT @@sql_mode;
+-----------------------------------------------------------------------------------------------------------------------+
| @@sql_mode                                                                                                            |
+-----------------------------------------------------------------------------------------------------------------------+
| ONLY_FULL_GROUP_BY,STRICT_TRANS_TABLES,NO_ZERO_IN_DATE,NO_ZERO_DATE,ERROR_FOR_DIVISION_BY_ZERO,NO_ENGINE_SUBSTITUTION |
+-----------------------------------------------------------------------------------------------------------------------+
1 row in set (0.00 sec)

mysql80 10> INSERT INTO t1 VALUES ('aa');
ERROR 1406 (22001): Data too long for column 'val' at row 1

mysql80 10> INSERT IGNORE INTO t1 VALUES ('aa');
Query OK, 1 row affected, 1 warning (0.00 sec)

mysql80 10> SHOW WARNINGS;
+---------+------+------------------------------------------+
| Level   | Code | Message                                  |
+---------+------+------------------------------------------+
| Warning | 1265 | Data truncated for column 'val' at row 1 |
+---------+------+------------------------------------------+
1 row in set (0.00 sec)

mysql80 10> SELECT * FROM t1;
+------+
| val  |
+------+
| a    |
+------+
1 row in set (0.00 sec)

なんか前者の動作(先勝ち)だけを期待していたのに、後者の動作(non-strict)も一緒についてきちゃってしょんぼりなんてネタがどこかにあったようななかったような気がする。

pt-oscやgh-ostで使う、 INSERT IGNORE INTO .. SELECT .. LOCK IN SHARE MODE でたまにロックタイムアウトしてエラるのは、 IGNORE は飽くまで INSERT にかかっているのであって、 SELECT のエラーを握りつぶす訳ではないから。

mysql80 11> SELECT * FROM t2 FOR UPDATE;  -- 別トランザクションでロックして
+----+
| pk |
+----+
|  1 |
+----+
1 row in set (0.00 sec)

mysql80 10> INSERT IGNORE INTO t1 SELECT pk FROM t2;  -- ロックをタイムアウトさせる
ERROR 1205 (HY000): Lock wait timeout exceeded; try restarting transaction

さてここまでは良くて。

NOT NULL なカラムに明示的に NULL を入れようと(DEFAULT句があろうとも)すると当然怒られる。これを避けるには「明示的な NULL 」ではなくて「単にリストに指定しない」ようにしてやれば良くて。

mysql80 12> CREATE TABLE t3 (num int, val varchar(1) NOT NULL DEFAULT 'z');
Query OK, 0 rows affected (0.02 sec)

mysql80 12> INSERT INTO t3 VALUES (1, NULL);
ERROR 1048 (23000): Column 'val' cannot be null

mysql80 12> INSERT INTO t3 (num) VALUES (1);
Query OK, 1 row affected (0.00 sec)

mysql80 12> SELECT * FROM t3;
+------+-----+
| num  | val |
+------+-----+
|    1 | z   |
+------+-----+
1 row in set (0.00 sec)

これを間違って INSERT IGNORE INTO に食わせるとこうなる。

mysql80 12> INSERT IGNORE INTO t3 VALUES (2, NULL);
Query OK, 1 row affected, 1 warning (0.00 sec)

mysql80 12> SHOW WARNINGS;
+---------+------+-----------------------------+
| Level   | Code | Message                     |
+---------+------+-----------------------------+
| Warning | 1048 | Column 'val' cannot be null |
+---------+------+-----------------------------+
1 row in set (0.00 sec)

mysql80 12> SELECT * FROM t3;
+------+-----+
| num  | val |
+------+-----+
|    1 | z   |
|    2 |     |                 <-- NOT 'z'
+------+-----+
2 rows in set (0.00 sec)

NOT NULL vs NULLをIGNOREが検知して、NULLを「varcharの暗黙のデフォルト値である空文字列」に変換してから実際にテーブルに渡すので、テーブルから見ると「未指定だったらDEFAULT値を割り当てるけど空文字列が指定されてるから受け取ったそのままを入れる」という感じになるんだと思う。

緩く業務連絡なんですが、 pt-online-schema-change が1048で落ちるのは、これを避けるためにIGNOREではちゃんと無視されるけど敢えて SHOW WARNINGS を拾ってエラーにしている、そういう仕様でした。

https://github.com/percona/percona-toolkit/blob/v3.3.1/bin/pt-online-schema-change#L11791-L11828

2021/07/20

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

TL;DR

dict_sys のmutexを取るのでDDL系は死ぬし新しくテーブルキャッシュを作れないのでテーブルキャッシュが枯渇すると死ぬ
ROLLBACK も dict_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にも一切依存しない。

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

登録: コメント ( Atom )

GA

2021/09/11

pt-online-schema-changeがColumn 'xx' cannot be nullで止まる

TL;DR

2021/09/06

INSERT IGNORE INTOがNOT NULL DEFAULTを裏切る

2021/07/20

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

TL;DR