TL;DR
再現方法。
8.0.19でレプリケーション設定をしたMySQLを用意する(8.0.28では再現しなかった。5.7.39でも今のところ再現していない)
$ make_replication_sandbox --how_many_slaves=1 8.0.19
$ cd sandboxes/rsandbox_8_0_19/
$ vim master/my.sandbox.cnf
..
binlog_group_commit_sync_delay = 1000000 ### binlogのgroup_commitを起こしやすくするため
$ vim node1/my.sandbox.cnf
..
slave_parallel_workers = 2
slave_preserve_commit_order = ON
slave_parallel_type = LOGICAL_CLOCK
$ ./restart_all
俺は未だにMySQL::Sandboxを使っているのだ、すまんな…。
2つのターミナルを用意して、↓の2ステートメントを1秒以内( binlog_group_commit_sync_delay を100万マイクロ秒に設定しているので、1秒なら同じグループコミットに入れる)に実行する
### Terminal1
$ ./m -e "FLUSH PRIVILEGES"
### Terminal2
$ ./m -e "CREATE USER yoku0825"
体感、50%くらいで再現する。
再現すると、ソースは無事だけどレプリカに一切合切ログインできなくなる。
$ ./s1 ### 刺さって返ってこなくなる
新規接続は全部デッドロックに巻き込まれて動けなくなるけれど、既にログインしているアカウントなら動ける（ただし USE mysql とかすると噛まれて動けなくなる）
SHOW PROCESSLISTで見ると、 FLUSH PRIVILEGES は Waiting for table metadata lock で止まり、そのMDLをもってそうなDROP USERは Waiting for preceding transaction to commit で待っている。
あとから追いかけてきたコネクションは Waiting for acl cache lock で待たされている。
slave1 [localhost] {msandbox} ((none)) > SHOW PROCESSLIST;
+----+----------------------+-----------------+------+---------+------+--------------------------------------------------------+--------------------+
| Id | User | Host | db | Command | Time | State | Info |
+----+----------------------+-----------------+------+---------+------+--------------------------------------------------------+--------------------+
| 4 | system user | | NULL | Query | 95 | Slave has read all relay log; waiting for more updates | NULL |
| 5 | event_scheduler | localhost | NULL | Daemon | 186 | Waiting on empty queue | NULL |
| 8 | system user | | | Connect | 96 | Waiting for table metadata lock | FLUSH PRIVILEGES |
| 9 | system user | | | Connect | 95 | Waiting for preceding transaction to commit | DROP USER yoku0825 |
| 10 | system user | connecting host | NULL | Connect | 186 | Waiting for master to send event | NULL |
| 15 | msandbox | localhost | NULL | Query | 0 | starting | SHOW PROCESSLIST |
| 16 | unauthenticated user | localhost | NULL | Connect | 92 | Waiting for acl cache lock | NULL |
+----+----------------------+-----------------+------+---------+------+--------------------------------------------------------+--------------------+
7 rows in set (0.03 sec)
FLUSH PRIVILEGES,DROP USERの順番でソースのbinlogに入るFLUSH PRIVILEGES,DROP USERの順番でレプリカのrelaylogに入るlast_committed=6(同じLOGICAL_CLOCK)の枠の中にあるので、コイツらはパラレルで動かされるDROP USERが先に終わってしまうと、slave_preserve_commit_orderのためにFLUSH PRIVILEGESが終わるのを(mysql.userとかの排他メタデータロックを持ったまま) 待つFLUSH PRIVILEGESはACL_Cache(=mysql.userとかの情報をメモリ上にロードしているアレ) の排他ロックをかけたまま、mysql.userとかの共有メタデータロックが欲しいので待つ (デッドロック！）- それ以降の接続や権限の読みなおし要求は全て
ACL_Cacheの排他ロックに阻まれてブロックされる - 死！
slave1 [localhost] {msandbox} (mysql) > SELECT * FROM performance_schema.metadata_locks;
+-------------------+--------------------+------------------+-----------------------+-----------------------+----------------------+---------------+-------------+------------------------+-----------------+----------------+
| OBJECT_TYPE | OBJECT_SCHEMA | OBJECT_NAME | COLUMN_NAME | OBJECT_INSTANCE_BEGIN | LOCK_TYPE | LOCK_DURATION | LOCK_STATUS | SOURCE | OWNER_THREAD_ID | OWNER_EVENT_ID |
+-------------------+--------------------+------------------+-----------------------+-----------------------+----------------------+---------------+-------------+------------------------+-----------------+----------------+
| GLOBAL | NULL | NULL | NULL | 140468113535472 | INTENTION_EXCLUSIVE | STATEMENT | GRANTED | sql_base.cc:5398 | 48 | 15 |
| BACKUP LOCK | NULL | NULL | NULL | 140468113913600 | INTENTION_EXCLUSIVE | TRANSACTION | GRANTED | sql_base.cc:5405 | 48 | 15 |
| SCHEMA | mysql | NULL | NULL | 140468113563696 | INTENTION_EXCLUSIVE | TRANSACTION | GRANTED | sql_base.cc:5385 | 48 | 15 |
| TABLE | mysql | columns_priv | NULL | 140468113536896 | SHARED_NO_READ_WRITE | TRANSACTION | GRANTED | table.h:2553 | 48 | 15 |
| TABLE | mysql | db | NULL | 140468113982576 | SHARED_NO_READ_WRITE | TRANSACTION | GRANTED | table.h:2553 | 48 | 15 |
| TABLE | mysql | columns_priv | NULL | 140468181071040 | SHARED_READ_ONLY | TRANSACTION | PENDING | table.h:2553 | 47 | 39 |
| TABLE | mysql | default_roles | NULL | 140468113772864 | SHARED_NO_READ_WRITE | TRANSACTION | GRANTED | table.h:2553 | 48 | 15 |
| TABLE | mysql | global_grants | NULL | 140468113772960 | SHARED_NO_READ_WRITE | TRANSACTION | GRANTED | table.h:2553 | 48 | 15 |
| TABLE | mysql | password_history | NULL | 140468113540192 | SHARED_NO_READ_WRITE | TRANSACTION | GRANTED | table.h:2553 | 48 | 15 |
| TABLE | mysql | procs_priv | NULL | 140468113540288 | SHARED_NO_READ_WRITE | TRANSACTION | GRANTED | table.h:2553 | 48 | 15 |
| TABLE | mysql | proxies_priv | NULL | 140468113540384 | SHARED_NO_READ_WRITE | TRANSACTION | GRANTED | table.h:2553 | 48 | 15 |
| TABLE | mysql | role_edges | NULL | 140468113534816 | SHARED_NO_READ_WRITE | TRANSACTION | GRANTED | table.h:2553 | 48 | 15 |
| TABLE | mysql | tables_priv | NULL | 140468113534912 | SHARED_NO_READ_WRITE | TRANSACTION | GRANTED | table.h:2553 | 48 | 15 |
| TABLE | mysql | user | NULL | 140468113535008 | SHARED_NO_READ_WRITE | TRANSACTION | GRANTED | table.h:2553 | 48 | 15 |
| TABLESPACE | NULL | mysql | NULL | 140468113897264 | INTENTION_EXCLUSIVE | TRANSACTION | GRANTED | lock.cc:795 | 48 | 15 |
| ACL CACHE | NULL | NULL | NULL | 140468113911328 | EXCLUSIVE | EXPLICIT | GRANTED | sql_auth_cache.cc:3393 | 48 | 16 |
| COMMIT | NULL | NULL | NULL | 140468113899824 | INTENTION_EXCLUSIVE | EXPLICIT | GRANTED | handler.cc:1719 | 48 | 16 |
| ACL CACHE | NULL | NULL | NULL | 140468448997264 | SHARED | EXPLICIT | PENDING | sql_auth_cache.cc:3393 | 57 | 1 |
バイナリログを開くと、 last_committed が同じになっている。
ただ、これでも先に DROP USER が処理されないと再現はしないので、100%再現とまではいかなかった。
#220822 14:39:48 server id 1 end_log_pos 1411 CRC32 0x3c26f86e Anonymous_GTID last_committed=6 sequence_number=7 rbr_only=no original_committed_timestamp=1661146788679412 immediate_commit_timestamp=1661146788679412 transaction_length=167
# original_commit_timestamp=1661146788679412 (2022-08-22 14:39:48.679412 JST)
# immediate_commit_timestamp=1661146788679412 (2022-08-22 14:39:48.679412 JST)
/*!80001 SET @@session.original_commit_timestamp=1661146788679412*//*!*/;
/*!80014 SET @@session.original_server_version=80019*//*!*/;
/*!80014 SET @@session.immediate_server_version=80019*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 1411
#220822 14:39:48 server id 1 end_log_pos 1501 CRC32 0xd17997a8 Query thread_id=15 exec_time=0 error_code=0
SET TIMESTAMP=1661146788/*!*/;
FLUSH PRIVILEGES
/*!*/;
# at 1501
#220822 14:39:49 server id 1 end_log_pos 1578 CRC32 0x91c06a81 Anonymous_GTID last_committed=6 sequence_number=8 rbr_only=no original_committed_timestamp=1661146789250989 immediate_commit_timestamp=1661146789250989 transaction_length=178
# original_commit_timestamp=1661146789250989 (2022-08-22 14:39:49.250989 JST)
# immediate_commit_timestamp=1661146789250989 (2022-08-22 14:39:49.250989 JST)
/*!80001 SET @@session.original_commit_timestamp=1661146789250989*//*!*/;
/*!80014 SET @@session.original_server_version=80019*//*!*/;
/*!80014 SET @@session.immediate_server_version=80019*//*!*/;
SET @@SESSION.GTID_NEXT= 'ANONYMOUS'/*!*/;
# at 1578
#220822 14:39:49 server id 1 end_log_pos 1679 CRC32 0xf4243118 Query thread_id=16 exec_time=0 error_code=0 Xid = 34
SET TIMESTAMP=1661146789/*!*/;
DROP USER yoku0825
/*!*/;
InnoDBとかで刺さる時と違って、CPU使用率も大して上がらずに緩やかに刺さった。
対処方法は kill -9 での再起動（もう kill -15 や mysqladmin shutdown では落ちてくれない）
gtid_mode=ONになってないとMTS中の異常終了で起動した後もSQL_Threadが止まったり(これはもうgtid_mode=ONの時以外MTSは危険…)、そもそも起動の時にまた同じ組み合わせをパラレル適用しようとしてまた刺さったり(replica_parallel_workers = 1にして起動して回避する)とか、なかなかエグい。
いつかぶち当たる人がいたら、参考にしてください…。
（バージョンアップすれば当たらなくなりそうだからバージョン上げましょう…）
0 件のコメント :
コメントを投稿